Hibernate
/
hibernate-orm
mirror of https://github.com/hibernate/hibernate-orm
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

HHH-7359 Added a new method to MessageHelper to intelligently handle 

property-ref issues in logging.  Rolled it out to as many MessageHelper
users as possible.
This commit is contained in:
brmeyer 2012-10-24 22:51:05 -04:00
parent 9968ce3adb
commit 30ea167c41
13 changed files with 110 additions and 51 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
hibernate-core/src/main/java/org/hibernate/action/internal/CollectionUpdateAction.java
View File

@ -73,7 +73,8 @@ public final class CollectionUpdateAction extends CollectionAction {
if (affectedByFilters) {
throw new HibernateException(
"cannot recreate collection while filter is enabled: " +
MessageHelper.collectionInfoString( persister, id, persister.getFactory() )
MessageHelper.collectionInfoString(persister, collection,
id, session )
);
}
if ( !emptySnapshot ) persister.remove( id, session );

5
hibernate-core/src/main/java/org/hibernate/collection/internal/AbstractPersistentCollection.java
View File

@ -643,9 +643,8 @@ public abstract class AbstractPersistentCollection implements Serializable, Pers
throw new HibernateException(
"Illegal attempt to associate a collection with two open sessions: " +
MessageHelper.collectionInfoString(
ce.getLoadedPersister(),
ce.getLoadedKey(),
session.getFactory()
ce.getLoadedPersister(), this,
ce.getLoadedKey(), session
)
);
}

23
hibernate-core/src/main/java/org/hibernate/engine/internal/Collections.java
View File

@ -25,8 +25,6 @@ package org.hibernate.engine.internal;
import java.io.Serializable;
import org.jboss.logging.Logger;
import org.hibernate.AssertionFailure;
import org.hibernate.HibernateException;
import org.hibernate.collection.spi.PersistentCollection;
@ -41,6 +39,7 @@ import org.hibernate.internal.CoreMessageLogger;
import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.pretty.MessageHelper;
import org.hibernate.type.CollectionType;
import org.jboss.logging.Logger;
/**
* Implements book-keeping for the collection persistence by reachability algorithm
@ -76,10 +75,8 @@ public final class Collections {
if ( LOG.isDebugEnabled() && loadedPersister != null ) {
LOG.debugf(
"Collection dereferenced: %s",
MessageHelper.collectionInfoString(
loadedPersister,
entry.getLoadedKey(),
session.getFactory()
MessageHelper.collectionInfoString( loadedPersister,
coll, entry.getLoadedKey(), session
)
);
}
@ -135,7 +132,9 @@ public final class Collections {
if ( LOG.isDebugEnabled() ) {
LOG.debugf( "Found collection with unloaded owner: %s",
MessageHelper.collectionInfoString( entry.getLoadedPersister(), entry.getLoadedKey(), session.getFactory() ) );
MessageHelper.collectionInfoString(
entry.getLoadedPersister(), coll,
entry.getLoadedKey(), session ) );
}
entry.setCurrentPersister( entry.getLoadedPersister() );
@ -189,13 +188,13 @@ public final class Collections {
if (LOG.isDebugEnabled()) {
if (collection.wasInitialized()) LOG.debugf("Collection found: %s, was: %s (initialized)",
MessageHelper.collectionInfoString(persister, ce.getCurrentKey(), factory),
MessageHelper.collectionInfoString(ce.getLoadedPersister(),
MessageHelper.collectionInfoString(persister, collection, ce.getCurrentKey(), session),
MessageHelper.collectionInfoString(ce.getLoadedPersister(), collection,
ce.getLoadedKey(),
factory));
session));
else LOG.debugf("Collection found: %s, was: %s (uninitialized)",
MessageHelper.collectionInfoString(persister, ce.getCurrentKey(), factory),
MessageHelper.collectionInfoString(ce.getLoadedPersister(), ce.getLoadedKey(), factory));
MessageHelper.collectionInfoString(persister, collection, ce.getCurrentKey(), session),
MessageHelper.collectionInfoString(ce.getLoadedPersister(), collection, ce.getLoadedKey(), session));
}
prepareCollectionForUpdate( collection, ce, factory );

9
hibernate-core/src/main/java/org/hibernate/engine/loading/internal/CollectionLoadContext.java
View File

@ -31,8 +31,6 @@ import java.util.Iterator;
import java.util.List;
import java.util.Set;
import org.jboss.logging.Logger;
import org.hibernate.CacheMode;
import org.hibernate.EntityMode;
import org.hibernate.HibernateException;
@ -47,6 +45,7 @@ import org.hibernate.engine.spi.Status;
import org.hibernate.internal.CoreMessageLogger;
import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.pretty.MessageHelper;
import org.jboss.logging.Logger;
/**
* Represents state associated with the processing of a given {@link ResultSet}
@ -265,7 +264,7 @@ public class CollectionLoadContext {
if ( LOG.isDebugEnabled() ) {
LOG.debugf(
"Collection fully initialized: %s",
MessageHelper.collectionInfoString(persister, lce.getKey(), session.getFactory())
MessageHelper.collectionInfoString(persister, lce.getCollection(), lce.getKey(), session)
);
}
if ( session.getFactory().getStatistics().isStatisticsEnabled() ) {
@ -284,7 +283,7 @@ public class CollectionLoadContext {
final SessionFactoryImplementor factory = session.getFactory();
if ( LOG.isDebugEnabled() ) {
LOG.debugf( "Caching collection: %s", MessageHelper.collectionInfoString( persister, lce.getKey(), factory ) );
LOG.debugf( "Caching collection: %s", MessageHelper.collectionInfoString( persister, lce.getCollection(), lce.getKey(), session ) );
}
if ( !session.getEnabledFilters().isEmpty() && persister.isAffectedByEnabledFilters( session ) ) {
@ -317,7 +316,7 @@ public class CollectionLoadContext {
if ( collectionOwner == null ) {
throw new HibernateException(
"Unable to resolve owner of loading collection [" +
MessageHelper.collectionInfoString( persister, lce.getKey(), factory ) +
MessageHelper.collectionInfoString( persister, lce.getCollection(), lce.getKey(), session ) +
"] for second level caching"
);
}

5
hibernate-core/src/main/java/org/hibernate/engine/loading/internal/LoadContexts.java
View File

@ -201,11 +201,6 @@ public class LoadContexts {
}
return lce.getCollection();
}
// TODO : should really move this log statement to CollectionType, where this is used from...
if ( LOG.isTraceEnabled() ) {
LOG.tracef( "Creating collection wrapper: %s",
MessageHelper.collectionInfoString( persister, ownerKey, getSession().getFactory() ) );
}
return null;
}

6
hibernate-core/src/main/java/org/hibernate/event/internal/DefaultInitializeCollectionEventListener.java
View File

@ -25,8 +25,6 @@ package org.hibernate.event.internal;
import java.io.Serializable;
import org.jboss.logging.Logger;
import org.hibernate.HibernateException;
import org.hibernate.cache.spi.CacheKey;
import org.hibernate.cache.spi.entry.CollectionCacheEntry;
@ -40,6 +38,7 @@ import org.hibernate.event.spi.InitializeCollectionEventListener;
import org.hibernate.internal.CoreMessageLogger;
import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.pretty.MessageHelper;
import org.jboss.logging.Logger;
/**
* @author Gavin King
@ -62,8 +61,7 @@ public class DefaultInitializeCollectionEventListener implements InitializeColle
if ( !collection.wasInitialized() ) {
if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Initializing collection {0}",
MessageHelper.collectionInfoString( ce.getLoadedPersister(), ce.getLoadedKey(),
source.getFactory() ) );
MessageHelper.collectionInfoString( ce.getLoadedPersister(), collection, ce.getLoadedKey(), source ) );
}
LOG.trace( "Checking second-level cache" );

3
hibernate-core/src/main/java/org/hibernate/event/internal/EvictVisitor.java
View File

@ -79,8 +79,9 @@ public class EvictVisitor extends AbstractVisitor {
if ( LOG.isDebugEnabled() ) {
LOG.debugf( "Evicting collection: %s",
MessageHelper.collectionInfoString( ce.getLoadedPersister(),
collection,
ce.getLoadedKey(),
getSession().getFactory() ) );
getSession() ) );
}
if ( ce.getLoadedPersister() != null && ce.getLoadedKey() != null ) {
//TODO: is this 100% correct?

12
hibernate-core/src/main/java/org/hibernate/persister/collection/AbstractCollectionPersister.java
View File

@ -1203,7 +1203,7 @@ public abstract class AbstractCollectionPersister
if ( LOG.isDebugEnabled() ) {
LOG.debugf( "Inserting collection: %s",
MessageHelper.collectionInfoString( this, id, getFactory() ) );
MessageHelper.collectionInfoString( this, collection, id, session ) );
}
try {
@ -1296,7 +1296,7 @@ public abstract class AbstractCollectionPersister
throw sqlExceptionHelper.convert(
sqle,
"could not insert collection: " +
MessageHelper.collectionInfoString( this, id, getFactory() ),
MessageHelper.collectionInfoString( this, collection, id, session ),
getSQLInsertRowString()
);
}
@ -1316,7 +1316,7 @@ public abstract class AbstractCollectionPersister
if ( LOG.isDebugEnabled() ) {
LOG.debugf( "Deleting rows of collection: %s",
MessageHelper.collectionInfoString( this, id, getFactory() ) );
MessageHelper.collectionInfoString( this, collection, id, session ) );
}
boolean deleteByIndex = !isOneToMany() && hasIndex && !indexContainsFormula;
@ -1404,7 +1404,7 @@ public abstract class AbstractCollectionPersister
throw sqlExceptionHelper.convert(
sqle,
"could not delete collection rows: " +
MessageHelper.collectionInfoString( this, id, getFactory() ),
MessageHelper.collectionInfoString( this, collection, id, session ),
getSQLDeleteRowString()
);
}
@ -1423,7 +1423,7 @@ public abstract class AbstractCollectionPersister
if ( !isInverse && isRowInsertEnabled() ) {
if ( LOG.isDebugEnabled() ) LOG.debugf( "Inserting rows of collection: %s",
MessageHelper.collectionInfoString( this, id, getFactory() ) );
MessageHelper.collectionInfoString( this, collection, id, session ) );
try {
// insert all the new entries
@ -1503,7 +1503,7 @@ public abstract class AbstractCollectionPersister
throw sqlExceptionHelper.convert(
sqle,
"could not insert collection rows: " +
MessageHelper.collectionInfoString( this, id, getFactory() ),
MessageHelper.collectionInfoString( this, collection, id, session ),
getSQLInsertRowString()
);
}

2
hibernate-core/src/main/java/org/hibernate/persister/collection/BasicCollectionPersister.java
View File

@ -284,7 +284,7 @@ public class BasicCollectionPersister extends AbstractCollectionPersister {
catch ( SQLException sqle ) {
throw getSQLExceptionHelper().convert(
sqle,
"could not update collection rows: " + MessageHelper.collectionInfoString( this, id, getFactory() ),
"could not update collection rows: " + MessageHelper.collectionInfoString( this, collection, id, session ),
getSQLUpdateRowString()
);
}

2
hibernate-core/src/main/java/org/hibernate/persister/collection/OneToManyPersister.java
View File

@ -327,7 +327,7 @@ public class OneToManyPersister extends AbstractCollectionPersister {
throw getFactory().getSQLExceptionHelper().convert(
sqle,
"could not update collection rows: " +
MessageHelper.collectionInfoString( this, id, getFactory() ),
MessageHelper.collectionInfoString( this, collection, id, session ),
getSQLInsertRowString()
);
}

58
hibernate-core/src/main/java/org/hibernate/pretty/MessageHelper.java
View File

@ -25,7 +25,9 @@
package org.hibernate.pretty;
import java.io.Serializable;
import org.hibernate.collection.spi.PersistentCollection;
import org.hibernate.engine.spi.SessionFactoryImplementor;
import org.hibernate.engine.spi.SessionImplementor;
import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.persister.entity.EntityPersister;
import org.hibernate.type.Type;
@ -234,7 +236,52 @@ public final class MessageHelper {
// collections ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/**
* Generate an info message string relating to a particular managed
* collection. Attempts to intelligently handle property-refs issues
* where the collection key is not the same as the owner key.
*
* @param persister The persister for the collection
* @param collection The collection itself
* @param collectionKey The collection key
* @param session The session
* @return An info string, in the form [Foo.bars#1]
*/
public static String collectionInfoString(
CollectionPersister persister,
PersistentCollection collection,
Serializable collectionKey,
SessionImplementor session ) {
StringBuilder s = new StringBuilder();
s.append( '[' );
if ( persister == null ) {
s.append( "<unreferenced>" );
}
else {
s.append( persister.getRole() );
s.append( '#' );
Type ownerIdentifierType = persister.getOwnerEntityPersister()
.getIdentifierType();
Serializable ownerKey;
// TODO: Is it redundant to attempt to use the collectionKey,
// or is always using the owner id sufficient?
if ( collectionKey.getClass().isAssignableFrom(
ownerIdentifierType.getReturnedClass() ) ) {
ownerKey = collectionKey;
} else {
ownerKey = session.getPersistenceContext()
.getEntry( collection.getOwner() ).getId();
}
s.append( ownerIdentifierType.toLoggableString(
ownerKey, session.getFactory() ) );
}
s.append( ']' );
return s.toString();
}
/**
* Generate an info message string relating to a series of managed
@ -315,13 +362,16 @@ public final class MessageHelper {
// Also need to check that the expected identifier type matches
// the given ID. Due to property-ref keys, the collection key
// may not be the owner key.
Type identifierType = persister.getOwnerEntityPersister()
Type ownerIdentifierType = persister.getOwnerEntityPersister()
.getIdentifierType();
if ( id.getClass().isAssignableFrom(
identifierType.getReturnedClass() ) ) {
s.append( identifierType.toLoggableString( id, factory ) );
ownerIdentifierType.getReturnedClass() ) ) {
s.append( ownerIdentifierType.toLoggableString( id, factory ) );
} else {
// TODO: This is a crappy backup if a property-ref is used.
// If the reference is an object w/o toString(), this isn't going to work.
s.append( id.toString() );
}
// TODO: If the collection key was not the owner key,
}
/**

13
hibernate-core/src/main/java/org/hibernate/type/CollectionType.java
View File

@ -35,7 +35,6 @@ import java.util.Map;
import org.dom4j.Element;
import org.dom4j.Node;
import org.hibernate.EntityMode;
import org.hibernate.Hibernate;
import org.hibernate.HibernateException;
@ -47,6 +46,7 @@ import org.hibernate.engine.spi.Mapping;
import org.hibernate.engine.spi.PersistenceContext;
import org.hibernate.engine.spi.SessionFactoryImplementor;
import org.hibernate.engine.spi.SessionImplementor;
import org.hibernate.internal.CoreMessageLogger;
import org.hibernate.internal.util.MarkerObject;
import org.hibernate.internal.util.collections.ArrayHelper;
import org.hibernate.metamodel.relational.Size;
@ -54,8 +54,10 @@ import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.persister.collection.QueryableCollection;
import org.hibernate.persister.entity.EntityPersister;
import org.hibernate.persister.entity.Joinable;
import org.hibernate.pretty.MessageHelper;
import org.hibernate.proxy.HibernateProxy;
import org.hibernate.proxy.LazyInitializer;
import org.jboss.logging.Logger;
/**
* A type that handles Hibernate <tt>PersistentCollection</tt>s (including arrays).
@ -64,6 +66,8 @@ import org.hibernate.proxy.LazyInitializer;
*/
public abstract class CollectionType extends AbstractType implements AssociationType {
private static final CoreMessageLogger LOG = Logger.getMessageLogger(CoreMessageLogger.class, CollectionType.class.getName());
private static final Object NOT_NULL_COLLECTION = new MarkerObject( "NOT NULL COLLECTION" );
public static final Object UNFETCHED_COLLECTION = new MarkerObject( "UNFETCHED COLLECTION" );
@ -622,6 +626,7 @@ public abstract class CollectionType extends AbstractType implements Association
if ( collection == null ) {
// create a new collection wrapper, to be initialized later
collection = instantiate( session, persister, key );
collection.setOwner(owner);
persistenceContext.addUninitializedCollection( persister, collection, key );
@ -640,6 +645,12 @@ public abstract class CollectionType extends AbstractType implements Association
}
if ( LOG.isTraceEnabled() ) {
LOG.tracef( "Created collection wrapper: %s",
MessageHelper.collectionInfoString( persister, collection,
key, session ) );
}
}
collection.setOwner(owner);

20
hibernate-core/src/test/resources/log4j.properties
View File

@ -1,17 +1,23 @@
log4j.appender.null=org.apache.log4j.varia.NullAppender
# Only records messages at INFO below, used to mimim root level info logging
log4j.appender.stdout_info=org.apache.log4j.ConsoleAppender
log4j.appender.stdout_info.Target=System.out
log4j.appender.stdout_info.Threshold=INFO
log4j.appender.stdout_info.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout_info.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
# Used by loggers other than root to log at any level
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n
log4j.rootLogger=info, stdout
log4j.rootLogger=trace, null, stdout_info
log4j.logger.org.hibernate.tool.hbm2ddl=trace
log4j.logger.org.hibernate.testing.cache=debug
log4j.logger.org.hibernate.testing.cache=debug, stdout
# SQL Logging - HHH-6833
log4j.logger.org.hibernate.SQL=debug
log4j.logger.org.hibernate.hql.internal.ast=debug
log4j.logger.org.hibernate.sql.ordering.antlr=debug
log4j.logger.org.hibernate.SQL=debug, stdout