HHH-8077 - Add MDC usage into attribute walking to help decode logs from recursive calls

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

@@ -249,7 +249,7 @@ public final class Cascade {
 							//				orphaned value, something a delete with a subquery to
 							// 				match the owner.
 //							final EntityType entityType = (EntityType) type;
-//							final String propertyPath = composePropertyPath( entityType.getPropertyName() );
+//							final String getPropertyPath = composePropertyPath( entityType.getPropertyName() );
 							loadedValue = null;
 						}
 						if ( loadedValue != null ) {

hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/DotNode.java

@@ -141,7 +141,7 @@ public class DotNode extends FromReferenceNode implements DisplayableNode, Selec
 		FromElement fromElement = getFromElement();
 		buf.append( "{propertyName=" ).append( propertyName );
 		buf.append( ",dereferenceType=" ).append( getWalker().getASTPrinter().getTokenTypeName( dereferenceType ) );
-		buf.append( ",propertyPath=" ).append( propertyPath );
+		buf.append( ",getPropertyPath=" ).append( propertyPath );
 		buf.append( ",path=" ).append( getPath() );
 		if ( fromElement != null ) {
 			buf.append( ",tableAlias=" ).append( fromElement.getTableAlias() );
@@ -585,7 +585,7 @@ public class DotNode extends FromReferenceNode implements DisplayableNode, Selec
 			LOG.debugf( "Unresolved property path is now '%s'", dotNode.propertyPath );
 		}
 		else {
-			LOG.debugf( "Terminal propertyPath = [%s]", propertyPath );
+			LOG.debugf( "Terminal getPropertyPath = [%s]", propertyPath );
 		}
 	}
 

hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/FromElementType.java

@@ -295,13 +295,13 @@ class FromElementType {
 	 *
 	 * @param propertyName The last part of the full path to the property.
 	 * @return The type.
-	 * @0param propertyPath The full property path.
+	 * @0param getPropertyPath The full property path.
 	 */
 	public Type getPropertyType(String propertyName, String propertyPath) {
 		checkInitialized();
 		Type type = null;
 		// If this is an entity and the property is the identifier property, then use getIdentifierType().
-		//      Note that the propertyName.equals( propertyPath ) checks whether we have a component
+		//      Note that the propertyName.equals( getPropertyPath ) checks whether we have a component
 		//      key reference, where the component class property name is the same as the
 		//      entity id property name; if the two are not equal, this is the case and
 		//      we'd need to "fall through" to using the property mapping.

hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractCollectionReference.java

@@ -72,11 +72,11 @@ public abstract class AbstractCollectionReference extends AbstractPlanNode imple
 			final Type type = persister.getIndexType();
 			if ( type.isAssociationType() ) {
 				if ( type.isEntityType() ) {
-					return new EntityIndexGraph( sessionFactory(), this, propertyPath() );
+					return new EntityIndexGraph( sessionFactory(), this, getPropertyPath() );
 				}
 			}
 			else if ( type.isComponentType() ) {
-				return new CompositeIndexGraph( sessionFactory(), this, propertyPath() );
+				return new CompositeIndexGraph( sessionFactory(), this, getPropertyPath() );
 			}
 		}
 
@@ -87,17 +87,18 @@ public abstract class AbstractCollectionReference extends AbstractPlanNode imple
 		final Type type = persister.getElementType();
 		if ( type.isAssociationType() ) {
 			if ( type.isEntityType() ) {
-				return new EntityElementGraph( sessionFactory(), this, propertyPath() );
+				return new EntityElementGraph( sessionFactory(), this, getPropertyPath() );
 			}
 		}
 		else if ( type.isComponentType() ) {
-			return new CompositeElementGraph( sessionFactory(), this, propertyPath() );
+			return new CompositeElementGraph( sessionFactory(), this, getPropertyPath() );
 		}
 
 		return null;
 	}
 
-	public PropertyPath propertyPath() {
+	@Override
+	public PropertyPath getPropertyPath() {
 		return propertyPath;
 	}
 

hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractLoadPlanBuilderStrategy.java

@@ -33,6 +33,7 @@ import java.util.List;
 import java.util.Map;
 
 import org.jboss.logging.Logger;
+import org.jboss.logging.MDC;
 
 import org.hibernate.HibernateException;
 import org.hibernate.LockMode;
@@ -70,6 +71,7 @@ import static org.hibernate.loader.spi.ResultSetProcessingContext.IdentifierReso
  */
 public abstract class AbstractLoadPlanBuilderStrategy implements LoadPlanBuilderStrategy, LoadPlanBuildingContext {
 	private static final Logger log = Logger.getLogger( AbstractLoadPlanBuilderStrategy.class );
+	private static final String MDC_KEY = "hibernateLoadPlanWalkPath";
 
 	private final SessionFactoryImplementor sessionFactory;
 
@@ -103,10 +105,12 @@ public abstract class AbstractLoadPlanBuilderStrategy implements LoadPlanBuilder
 							"be sure to not use LoadPlanBuilderStrategy instances concurrently"
 			);
 		}
+		MDC.put( MDC_KEY, new MDCStack() );
 	}
 
 	@Override
 	public void finish() {
+		MDC.remove( MDC_KEY );
 		fetchOwnerStack.clear();
 		collectionReferenceStack.clear();
 	}
@@ -419,12 +423,18 @@ public abstract class AbstractLoadPlanBuilderStrategy implements LoadPlanBuilder
 
 	private void pushToStack(FetchOwner fetchOwner) {
 		log.trace( "Pushing fetch owner to stack : " + fetchOwner );
+		mdcStack().push( fetchOwner.getPropertyPath() );
 		fetchOwnerStack.addFirst( fetchOwner );
 	}
 
+	private MDCStack mdcStack() {
+		return (MDCStack) MDC.get( MDC_KEY );
+	}
+
 	private FetchOwner popFromStack() {
 		final FetchOwner last = fetchOwnerStack.removeFirst();
 		log.trace( "Popped fetch owner from stack : " + last );
+		mdcStack().pop();
 		if ( FetchStackAware.class.isInstance( last ) ) {
 			( (FetchStackAware) last ).poppedFromStack();
 		}
@@ -433,12 +443,14 @@ public abstract class AbstractLoadPlanBuilderStrategy implements LoadPlanBuilder
 
 	private void pushToCollectionStack(CollectionReference collectionReference) {
 		log.trace( "Pushing collection reference to stack : " + collectionReference );
+		mdcStack().push( collectionReference.getPropertyPath() );
 		collectionReferenceStack.addFirst( collectionReference );
 	}
 
 	private CollectionReference popFromCollectionStack() {
 		final CollectionReference last = collectionReferenceStack.removeFirst();
 		log.trace( "Popped collection reference from stack : " + last );
+		mdcStack().pop();
 		if ( FetchStackAware.class.isInstance( last ) ) {
 			( (FetchStackAware) last ).poppedFromStack();
 		}
@@ -722,4 +734,21 @@ public abstract class AbstractLoadPlanBuilderStrategy implements LoadPlanBuilder
 			return context.getSession().generateEntityKey( resolvedId, entityReference.getEntityPersister() );
 		}
 	}
+
+	public static class MDCStack {
+		private ArrayDeque<PropertyPath> pathStack = new ArrayDeque<PropertyPath>();
+
+		public void push(PropertyPath path) {
+			pathStack.addFirst( path );
+		}
+
+		public void pop() {
+			pathStack.removeFirst();
+		}
+
+		public String toString() {
+			final PropertyPath path = pathStack.peekFirst();
+			return path == null ? "<no-path>" : path.getFullPath();
+		}
+	}
 }

hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionFetch.java

@@ -80,11 +80,6 @@ public class CollectionFetch extends AbstractCollectionReference implements Coll
 		return fetchStrategy;
 	}
 
-	@Override
-	public PropertyPath getPropertyPath() {
-		return propertyPath();
-	}
-
 	@Override
 	public void hydrate(ResultSet resultSet, ResultSetProcessingContext context) throws SQLException {
 		//To change body of implemented methods use File | Settings | File Templates.

hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionReference.java

@@ -26,6 +26,7 @@ package org.hibernate.loader.plan.spi;
 import org.hibernate.LockMode;
 import org.hibernate.loader.CollectionAliases;
 import org.hibernate.loader.EntityAliases;
+import org.hibernate.loader.PropertyPath;
 import org.hibernate.persister.collection.CollectionPersister;
 
 /**
@@ -59,6 +60,8 @@ public interface CollectionReference {
 
 	public FetchOwner getElementGraph();
 
+	public PropertyPath getPropertyPath();
+
 	public boolean hasEntityElements();
 
 	/**

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

@@ -1,16 +1,47 @@
+#
+# Hibernate, Relational Persistence for Idiomatic Java
+#
+# Copyright (c) 2013, Red Hat Inc. or third-party contributors as
+# indicated by the @author tags or express copyright attribution
+# statements applied by the authors.  All third-party contributions are
+# distributed under license by Red Hat Inc.
+#
+# This copyrighted material is made available to anyone wishing to use, modify,
+# copy, or redistribute it subject to the terms and conditions of the GNU
+# Lesser General Public License, as published by the Free Software Foundation.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
+# or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU Lesser General Public License
+# for more details.
+#
+# You should have received a copy of the GNU Lesser General Public License
+# along with this distribution; if not, write to:
+# Free Software Foundation, Inc.
+# 51 Franklin Street, Fifth Floor
+# Boston, MA  02110-1301  USA
+#
 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.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L (hibernateLoadPlanWalkPath->%X{hibernateLoadPlanWalkPath}) - %m%n
 
+log4j.appender.stdout-mdc=org.apache.log4j.ConsoleAppender
+log4j.appender.stdout-mdc.Target=System.out
+log4j.appender.stdout-mdc.layout=org.apache.log4j.PatternLayout
+log4j.appender.stdout-mdc.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L (walk path -> %X{hibernateLoadPlanWalkPath}) - %m%n
 
 log4j.rootLogger=info, stdout
 
+log4j.logger.org.hibernate.loader.plan=trace, stdout-mdc
+log4j.additivity.org.hibernate.loader.plan=false
+log4j.logger.org.hibernate.persister.walking=trace, stdout-mdc
+log4j.additivity.org.hibernate.persister.walking=false
+
 log4j.logger.org.hibernate.tool.hbm2ddl=trace
 log4j.logger.org.hibernate.testing.cache=debug
 
-log4j.logger.org.hibernate.loader.plan=trace
-
 # SQL Logging - HHH-6833
 log4j.logger.org.hibernate.SQL=debug
 

hibernate-entitymanager/src/test/java/org/hibernate/jpa/test/ejb3configuration/PersisterClassProviderTest.java

@@ -60,6 +60,8 @@ import org.hibernate.persister.collection.CollectionPersister;
 import org.hibernate.persister.entity.EntityPersister;
 import org.hibernate.persister.internal.PersisterClassResolverInitiator;
 import org.hibernate.persister.spi.PersisterClassResolver;
+import org.hibernate.persister.walking.spi.AttributeDefinition;
+import org.hibernate.persister.walking.spi.EntityIdentifierDefinition;
 import org.hibernate.tuple.entity.EntityMetamodel;
 import org.hibernate.tuple.entity.EntityTuplizer;
 import org.hibernate.tuple.entity.NonPojoInstrumentationMetadata;
@@ -609,6 +611,21 @@ public class PersisterClassProviderTest {
 			// TODO Auto-generated method stub
 			return null;
 		}
+
+		@Override
+		public EntityPersister getEntityPersister() {
+			return this;
+		}
+
+		@Override
+		public EntityIdentifierDefinition getEntityKeyDefinition() {
+			return null;  //To change body of implemented methods use File | Settings | File Templates.
+		}
+
+		@Override
+		public Iterable<AttributeDefinition> getAttributes() {
+			return null;  //To change body of implemented methods use File | Settings | File Templates.
+		}
 	}
 
 	public static class GoofyException extends RuntimeException {