From 87012e81012ff10fc0ced74f6b86cccd7970cb9f Mon Sep 17 00:00:00 2001 From: Steve Ebersole Date: Mon, 18 Mar 2013 09:30:13 -0500 Subject: [PATCH] HHH-8077 - Add MDC usage into attribute walking to help decode logs from recursive calls --- .../hibernate/engine/internal/Cascade.java | 2 +- .../hql/internal/ast/tree/DotNode.java | 4 +-- .../internal/ast/tree/FromElementType.java | 4 +-- .../plan/spi/AbstractCollectionReference.java | 11 +++--- .../spi/AbstractLoadPlanBuilderStrategy.java | 29 +++++++++++++++ .../loader/plan/spi/CollectionFetch.java | 5 --- .../loader/plan/spi/CollectionReference.java | 3 ++ .../src/test/resources/log4j.properties | 35 +++++++++++++++++-- .../PersisterClassProviderTest.java | 17 +++++++++ 9 files changed, 93 insertions(+), 17 deletions(-) diff --git a/hibernate-core/src/main/java/org/hibernate/engine/internal/Cascade.java b/hibernate-core/src/main/java/org/hibernate/engine/internal/Cascade.java index cc446c5414..1b9b2e29bf 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/internal/Cascade.java +++ b/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 ) { diff --git a/hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/DotNode.java b/hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/DotNode.java index 024d4c56a2..c83370e8cd 100644 --- a/hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/DotNode.java +++ b/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 ); } } diff --git a/hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/FromElementType.java b/hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/FromElementType.java index fea26dbc6f..dea3517a6e 100644 --- a/hibernate-core/src/main/java/org/hibernate/hql/internal/ast/tree/FromElementType.java +++ b/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. diff --git a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractCollectionReference.java b/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractCollectionReference.java index e623f0a898..996f7106c2 100644 --- a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractCollectionReference.java +++ b/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; } diff --git a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractLoadPlanBuilderStrategy.java b/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractLoadPlanBuilderStrategy.java index 2ec4457bfe..2ab7a1ab29 100644 --- a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/AbstractLoadPlanBuilderStrategy.java +++ b/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 pathStack = new ArrayDeque(); + + public void push(PropertyPath path) { + pathStack.addFirst( path ); + } + + public void pop() { + pathStack.removeFirst(); + } + + public String toString() { + final PropertyPath path = pathStack.peekFirst(); + return path == null ? "" : path.getFullPath(); + } + } } diff --git a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionFetch.java b/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionFetch.java index b5ad2e9e04..ae79e5db80 100644 --- a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionFetch.java +++ b/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. diff --git a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionReference.java b/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionReference.java index da4acdcbb3..c67f803793 100644 --- a/hibernate-core/src/main/java/org/hibernate/loader/plan/spi/CollectionReference.java +++ b/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(); /** diff --git a/hibernate-core/src/test/resources/log4j.properties b/hibernate-core/src/test/resources/log4j.properties index 73d5935aea..51025a3b1e 100644 --- a/hibernate-core/src/test/resources/log4j.properties +++ b/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 diff --git a/hibernate-entitymanager/src/test/java/org/hibernate/jpa/test/ejb3configuration/PersisterClassProviderTest.java b/hibernate-entitymanager/src/test/java/org/hibernate/jpa/test/ejb3configuration/PersisterClassProviderTest.java index e217265aa0..c506af986c 100644 --- a/hibernate-entitymanager/src/test/java/org/hibernate/jpa/test/ejb3configuration/PersisterClassProviderTest.java +++ b/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 getAttributes() { + return null; //To change body of implemented methods use File | Settings | File Templates. + } } public static class GoofyException extends RuntimeException {