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.

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

@@ -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 );

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

@@ -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.getLoadedPersister(), this,
-											ce.getLoadedKey(),
+											ce.getLoadedKey(), session
-											session.getFactory()
 									)
 					);
 				}

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

@@ -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(
+					MessageHelper.collectionInfoString( loadedPersister, 
-							loadedPersister,
+							coll, entry.getLoadedKey(), session
-							entry.getLoadedKey(),
-							session.getFactory()
 					)
 			);
 		}
@@ -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(persister, collection, ce.getCurrentKey(), session),
-                                                        MessageHelper.collectionInfoString(ce.getLoadedPersister(),
+                                                        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(persister, collection, ce.getCurrentKey(), session),
-                            MessageHelper.collectionInfoString(ce.getLoadedPersister(), ce.getLoadedKey(), factory));
+                            MessageHelper.collectionInfoString(ce.getLoadedPersister(), collection, ce.getLoadedKey(), session));
         }
 
 		prepareCollectionForUpdate( collection, ce, factory );

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

@@ -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"
 					);
 				}

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

@@ -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;
 	}
 

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

@@ -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(),
+						MessageHelper.collectionInfoString( ce.getLoadedPersister(), collection, ce.getLoadedKey(), source ) );
-						source.getFactory() ) );
 			}
 
 			LOG.trace( "Checking second-level cache" );

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

@@ -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?

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

@@ -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()
 						);
 			}

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

@@ -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()
 				);
 		}

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

@@ -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()
 			);
 		}

hibernate-core/src/main/java/org/hibernate/pretty/MessageHelper.java

@@ -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;
@@ -235,6 +237,51 @@ 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() ) ) {
+				ownerIdentifierType.getReturnedClass() ) ) {
-			s.append( identifierType.toLoggableString( id, factory ) );
+			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, 
 	}
 
 	/**

hibernate-core/src/main/java/org/hibernate/type/CollectionType.java

@@ -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);

hibernate-core/src/test/resources/log4j.properties

@@ -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.SQL=debug, stdout
-
-log4j.logger.org.hibernate.hql.internal.ast=debug
-
-log4j.logger.org.hibernate.sql.ordering.antlr=debug