From 54a088186ca7cb243853df8c365a66f59ac8c72f Mon Sep 17 00:00:00 2001 From: brmeyer Date: Wed, 24 Oct 2012 22:51:05 -0400 Subject: [PATCH] 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. --- .../internal/CollectionUpdateAction.java | 3 +- .../AbstractPersistentCollection.java | 5 +- .../engine/internal/Collections.java | 23 ++++---- .../internal/CollectionLoadContext.java | 9 ++- .../engine/loading/internal/LoadContexts.java | 5 -- ...aultInitializeCollectionEventListener.java | 6 +- .../event/internal/EvictVisitor.java | 3 +- .../AbstractCollectionPersister.java | 12 ++-- .../collection/BasicCollectionPersister.java | 2 +- .../collection/OneToManyPersister.java | 2 +- .../org/hibernate/pretty/MessageHelper.java | 58 +++++++++++++++++-- .../org/hibernate/type/CollectionType.java | 13 ++++- .../src/test/resources/log4j.properties | 20 ++++--- 13 files changed, 110 insertions(+), 51 deletions(-) diff --git a/hibernate-core/src/main/java/org/hibernate/action/internal/CollectionUpdateAction.java b/hibernate-core/src/main/java/org/hibernate/action/internal/CollectionUpdateAction.java index 52c4795d92..31c565ce15 100644 --- a/hibernate-core/src/main/java/org/hibernate/action/internal/CollectionUpdateAction.java +++ b/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 ); diff --git a/hibernate-core/src/main/java/org/hibernate/collection/internal/AbstractPersistentCollection.java b/hibernate-core/src/main/java/org/hibernate/collection/internal/AbstractPersistentCollection.java index 9558b14159..75323d23d6 100644 --- a/hibernate-core/src/main/java/org/hibernate/collection/internal/AbstractPersistentCollection.java +++ b/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.getLoadedKey(), - session.getFactory() + ce.getLoadedPersister(), this, + ce.getLoadedKey(), session ) ); } diff --git a/hibernate-core/src/main/java/org/hibernate/engine/internal/Collections.java b/hibernate-core/src/main/java/org/hibernate/engine/internal/Collections.java index 16311723da..2c6a840ba3 100755 --- a/hibernate-core/src/main/java/org/hibernate/engine/internal/Collections.java +++ b/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( - 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 ); diff --git a/hibernate-core/src/main/java/org/hibernate/engine/loading/internal/CollectionLoadContext.java b/hibernate-core/src/main/java/org/hibernate/engine/loading/internal/CollectionLoadContext.java index 72a5e68898..23f9755feb 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/loading/internal/CollectionLoadContext.java +++ b/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" ); } diff --git a/hibernate-core/src/main/java/org/hibernate/engine/loading/internal/LoadContexts.java b/hibernate-core/src/main/java/org/hibernate/engine/loading/internal/LoadContexts.java index ba56e22870..5a6e4a6cf2 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/loading/internal/LoadContexts.java +++ b/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; } diff --git a/hibernate-core/src/main/java/org/hibernate/event/internal/DefaultInitializeCollectionEventListener.java b/hibernate-core/src/main/java/org/hibernate/event/internal/DefaultInitializeCollectionEventListener.java index 69ce7ce476..033682d5df 100755 --- a/hibernate-core/src/main/java/org/hibernate/event/internal/DefaultInitializeCollectionEventListener.java +++ b/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(), - source.getFactory() ) ); + MessageHelper.collectionInfoString( ce.getLoadedPersister(), collection, ce.getLoadedKey(), source ) ); } LOG.trace( "Checking second-level cache" ); diff --git a/hibernate-core/src/main/java/org/hibernate/event/internal/EvictVisitor.java b/hibernate-core/src/main/java/org/hibernate/event/internal/EvictVisitor.java index dcc18fa019..14a0f6ffae 100644 --- a/hibernate-core/src/main/java/org/hibernate/event/internal/EvictVisitor.java +++ b/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? diff --git a/hibernate-core/src/main/java/org/hibernate/persister/collection/AbstractCollectionPersister.java b/hibernate-core/src/main/java/org/hibernate/persister/collection/AbstractCollectionPersister.java index 4bddd04438..fc77d3ff05 100644 --- a/hibernate-core/src/main/java/org/hibernate/persister/collection/AbstractCollectionPersister.java +++ b/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() ); } diff --git a/hibernate-core/src/main/java/org/hibernate/persister/collection/BasicCollectionPersister.java b/hibernate-core/src/main/java/org/hibernate/persister/collection/BasicCollectionPersister.java index 4170a8b3cd..58647cdc9b 100644 --- a/hibernate-core/src/main/java/org/hibernate/persister/collection/BasicCollectionPersister.java +++ b/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() ); } diff --git a/hibernate-core/src/main/java/org/hibernate/persister/collection/OneToManyPersister.java b/hibernate-core/src/main/java/org/hibernate/persister/collection/OneToManyPersister.java index 01f58b9653..488e631e5d 100644 --- a/hibernate-core/src/main/java/org/hibernate/persister/collection/OneToManyPersister.java +++ b/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() ); } diff --git a/hibernate-core/src/main/java/org/hibernate/pretty/MessageHelper.java b/hibernate-core/src/main/java/org/hibernate/pretty/MessageHelper.java index 401317a9d5..f519ecdc41 100644 --- a/hibernate-core/src/main/java/org/hibernate/pretty/MessageHelper.java +++ b/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; @@ -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( "" ); + } + 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, } /** diff --git a/hibernate-core/src/main/java/org/hibernate/type/CollectionType.java b/hibernate-core/src/main/java/org/hibernate/type/CollectionType.java index c410181186..f7683161de 100644 --- a/hibernate-core/src/main/java/org/hibernate/type/CollectionType.java +++ b/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 PersistentCollections (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); diff --git a/hibernate-core/src/test/resources/log4j.properties b/hibernate-core/src/test/resources/log4j.properties index 686aae8fc2..f933444118 100644 --- a/hibernate-core/src/test/resources/log4j.properties +++ b/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.hql.internal.ast=debug - -log4j.logger.org.hibernate.sql.ordering.antlr=debug \ No newline at end of file +log4j.logger.org.hibernate.SQL=debug, stdout \ No newline at end of file