diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/BytecodeLogging.java b/hibernate-core/src/main/java/org/hibernate/bytecode/BytecodeLogging.java deleted file mode 100644 index 35b9968a6cda..000000000000 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/BytecodeLogging.java +++ /dev/null @@ -1,23 +0,0 @@ -/* - * SPDX-License-Identifier: Apache-2.0 - * Copyright Red Hat Inc. and Hibernate Authors - */ -package org.hibernate.bytecode; - -import org.hibernate.Internal; -import org.hibernate.internal.log.SubSystemLogging; - -import org.jboss.logging.Logger; - -/** - * @author Steve Ebersole - */ -@SubSystemLogging( - name = BytecodeLogging.LOGGER_NAME, - description = "Logging related to bytecode handling" -) -@Internal -public interface BytecodeLogging { - String LOGGER_NAME = SubSystemLogging.BASE + "bytecode"; - Logger LOGGER = Logger.getLogger( LOGGER_NAME ); -} diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/BytecodeEnhancementLogging.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/BytecodeEnhancementLogging.java new file mode 100644 index 000000000000..991d8ef41bf9 --- /dev/null +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/BytecodeEnhancementLogging.java @@ -0,0 +1,112 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * Copyright Red Hat Inc. and Hibernate Authors + */ +package org.hibernate.bytecode.enhance.internal; + +import org.hibernate.Internal; +import org.hibernate.internal.log.SubSystemLogging; +import org.jboss.logging.BasicLogger; +import org.jboss.logging.Logger; +import org.jboss.logging.annotations.LogMessage; +import org.jboss.logging.annotations.Message; +import org.jboss.logging.annotations.MessageLogger; +import org.jboss.logging.annotations.ValidIdRange; + +import java.lang.invoke.MethodHandles; + +import static org.jboss.logging.Logger.Level.DEBUG; +import static org.jboss.logging.Logger.Level.INFO; +import static org.jboss.logging.Logger.Level.TRACE; + + +/** + * @author Steve Ebersole + */ +@MessageLogger(projectCode = "HHH") +@ValidIdRange(min = 90009001, max = 90009900) +@SubSystemLogging( + name = BytecodeEnhancementLogging.LOGGER_NAME, + description = "Logging related to bytecode handling" +) +@Internal +public interface BytecodeEnhancementLogging extends BasicLogger { + String LOGGER_NAME = SubSystemLogging.BASE + ".bytecode.enhancement"; + BytecodeEnhancementLogging LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), BytecodeEnhancementLogging.class, LOGGER_NAME ); + + // ---- trace messages ---- + @LogMessage(level = TRACE) + @Message(id = 90009001, value = "Skipping enhancement of [%s]: it's already annotated with @EnhancementInfo") + void skippingAlreadyAnnotated(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009002, value = "Skipping enhancement of [%s]: it's an interface") + void skippingInterface(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009003, value = "Skipping enhancement of [%s]: it's a record") + void skippingRecord(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009004, value = "Enhancing [%s] as Entity") + void enhancingAsEntity(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009005, value = "Enhancing [%s] as Composite") + void enhancingAsComposite(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009006, value = "Enhancing [%s] as MappedSuperclass") + void enhancingAsMappedSuperclass(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009007, value = "Extended enhancement of [%s]") + void extendedEnhancement(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009008, value = "Skipping enhancement of [%s]: not entity or composite") + void skippingNotEntityOrComposite(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009009, value = "Weaving in PersistentAttributeInterceptable implementation on [%s]") + void weavingPersistentAttributeInterceptable(String className); + + @LogMessage(level = TRACE) + @Message(id = 90009010, value = "mappedBy association for field [%s.%s] is [%s.%s]") + void mappedByAssociation(String ownerName, String fieldName, String targetEntityName, String targetFieldName); + + @LogMessage(level = TRACE) + @Message(id = 90009011, value = "Persistent fields for entity %s: %s") + void persistentFieldsForEntity(String entityName, String orderedFields); + + @LogMessage(level = TRACE) + @Message(id = 90009012, value = "Found @MappedSuperclass '%s' to collectPersistenceFields") + void foundMappedSuperclass(String superClassName); + + @LogMessage(level = TRACE) + @Message(id = 90009013, value = "Extended enhancement: Transforming access to field [%s.%s] from method [%s.%s()]") + void extendedTransformingFieldAccess(String ownerType, String fieldName, String methodOwner, String methodName); + + // ---- debug messages ---- + @LogMessage(level = DEBUG) + @Message(id = 90009020, value = "Skipping re-enhancement version check for '%s' due to 'ignore'") + void skippingReEnhancementVersionCheck(String className); + + @LogMessage(level = DEBUG) + @Message(id = 90009021, value = "Skipping enhancement of [%s] because no field named [%s] could be found for property accessor method [%s]." + + " To fix this, make sure all property accessor methods have a matching field.") + void propertyAccessorNoFieldSkip(String className, String fieldName, String methodName); + + // ---- info messages ---- + @LogMessage(level = INFO) + @Message(id = 90009030, value = "Bidirectional association not managed for field [%s.%s]: Could not find target field in [%s]") + void bidirectionalNotManagedCouldNotFindTargetField(String ownerName, String fieldName, String targetEntityCanonicalName); + + @LogMessage(level = INFO) + @Message(id = 90009031, value = "Bidirectional association not managed for field [%s.%s]: @ManyToMany in java.util.Map attribute not supported ") + void manyToManyInMapNotSupported(String ownerName, String fieldName); + + @LogMessage(level = INFO) + @Message(id = 90009032, value = "Bidirectional association not managed for field [%s.%s]: Could not find target type") + void bidirectionalNotManagedCouldNotFindTargetType(String ownerName, String fieldName); +} diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/BiDirectionalAssociationHandler.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/BiDirectionalAssociationHandler.java index 03592a44ff4e..5c3bb89d6bf9 100644 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/BiDirectionalAssociationHandler.java +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/BiDirectionalAssociationHandler.java @@ -20,8 +20,7 @@ import org.hibernate.bytecode.enhance.internal.bytebuddy.EnhancerImpl.AnnotatedFieldDescription; import org.hibernate.bytecode.enhance.spi.EnhancementException; import org.hibernate.bytecode.enhance.spi.EnhancerConstants; -import org.hibernate.internal.CoreLogging; -import org.hibernate.internal.CoreMessageLogger; +import org.hibernate.bytecode.enhance.internal.BytecodeEnhancementLogging; import net.bytebuddy.asm.Advice; import net.bytebuddy.description.annotation.AnnotationDescription; @@ -40,8 +39,6 @@ final class BiDirectionalAssociationHandler implements Implementation { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( BiDirectionalAssociationHandler.class ); - static Implementation wrap( TypeDescription managedCtClass, ByteBuddyEnhancementContext enhancementContext, @@ -64,9 +61,8 @@ static Implementation wrap( bidirectionalAttributeName = mappedBy; } if ( bidirectionalAttributeName == null || bidirectionalAttributeName.isEmpty() ) { - if ( LOG.isInfoEnabled() ) { - LOG.infof( - "Bidirectional association not managed for field [%s#%s]: Could not find target field in [%s]", + if ( BytecodeEnhancementLogging.LOGGER.isInfoEnabled() ) { + BytecodeEnhancementLogging.LOGGER.bidirectionalNotManagedCouldNotFindTargetField( managedCtClass.getName(), persistentField.getName(), targetEntity.getCanonicalName() @@ -120,9 +116,8 @@ static Implementation wrap( if ( persistentField.hasAnnotation( ManyToMany.class ) ) { if ( persistentField.getType().asErasure().isAssignableTo( Map.class ) || targetType.isAssignableTo( Map.class ) ) { - if ( LOG.isInfoEnabled() ) { - LOG.infof( - "Bidirectional association not managed for field [%s#%s]: @ManyToMany in java.util.Map attribute not supported ", + if ( BytecodeEnhancementLogging.LOGGER.isInfoEnabled() ) { + BytecodeEnhancementLogging.LOGGER.manyToManyInMapNotSupported( managedCtClass.getName(), persistentField.getName() ); @@ -148,35 +143,29 @@ public static TypeDescription getTargetEntityClass(TypeDescription managedCtClas AnnotationDescription.Loadable mto = persistentField.getAnnotation( ManyToOne.class ); AnnotationDescription.Loadable mtm = persistentField.getAnnotation( ManyToMany.class ); - if ( oto == null && otm == null && mto == null && mtm == null ) { - return null; - } - - AnnotationValue targetClass = null; + final AnnotationValue targetClass; if ( oto != null ) { targetClass = oto.getValue( new MethodDescription.ForLoadedMethod( OneToOne.class.getDeclaredMethod( "targetEntity" ) ) ); } - if ( otm != null ) { + else if ( otm != null ) { targetClass = otm.getValue( new MethodDescription.ForLoadedMethod( OneToMany.class.getDeclaredMethod( "targetEntity" ) ) ); } - if ( mto != null ) { + else if ( mto != null ) { targetClass = mto.getValue( new MethodDescription.ForLoadedMethod( ManyToOne.class.getDeclaredMethod( "targetEntity" ) ) ); } - if ( mtm != null ) { + else if ( mtm != null ) { targetClass = mtm.getValue( new MethodDescription.ForLoadedMethod( ManyToMany.class.getDeclaredMethod( "targetEntity" ) ) ); } - - if ( targetClass == null ) { - if ( LOG.isInfoEnabled() ) { - LOG.infof( - "Bidirectional association not managed for field [%s#%s]: Could not find target type", + else { + if ( BytecodeEnhancementLogging.LOGGER.isInfoEnabled() ) { + BytecodeEnhancementLogging.LOGGER.bidirectionalNotManagedCouldNotFindTargetType( managedCtClass.getName(), persistentField.getName() ); } return null; } - else if ( !targetClass.resolve( TypeDescription.class ).represents( void.class ) ) { + if ( !targetClass.resolve( TypeDescription.class ).represents( void.class ) ) { return targetClass.resolve( TypeDescription.class ); } } @@ -253,8 +242,8 @@ private static String getMappedByManyToMany(AnnotatedFieldDescription target, Ty if ( context.isPersistentField( annotatedF ) && target.getName().equals( getMappedBy( annotatedF, entityType( annotatedF.getType() ), context ) ) && target.getDeclaringType().asErasure().isAssignableTo( entityType( annotatedF.getType() ) ) ) { - if ( LOG.isTraceEnabled() ) { - LOG.tracef( + if ( BytecodeEnhancementLogging.LOGGER.isTraceEnabled() ) { + BytecodeEnhancementLogging.LOGGER.tracef( "mappedBy association for field [%s#%s] is [%s#%s]", target.getDeclaringType().asErasure().getName(), target.getName(), diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/EnhancerImpl.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/EnhancerImpl.java index 7c7fe759419d..680c93943e84 100644 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/EnhancerImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/EnhancerImpl.java @@ -45,8 +45,7 @@ import org.hibernate.engine.spi.CompositeOwner; import org.hibernate.engine.spi.ExtendedSelfDirtinessTracker; import org.hibernate.engine.spi.Managed; -import org.hibernate.internal.CoreLogging; -import org.hibernate.internal.CoreMessageLogger; +import org.hibernate.bytecode.enhance.internal.BytecodeEnhancementLogging; import java.lang.annotation.Annotation; import java.lang.reflect.Modifier; @@ -69,7 +68,6 @@ import static org.hibernate.bytecode.enhance.internal.bytebuddy.FeatureMismatchException.Feature.DIRTY_CHECK; public class EnhancerImpl implements Enhancer { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( Enhancer.class ); protected final ByteBuddyEnhancementContext enhancementContext; private final ByteBuddyState byteBuddyState; @@ -172,19 +170,19 @@ private DynamicType.Builder doEnhance(Supplier> builde verifyReEnhancement( managedCtClass, infoAnnotation.load(), enhancementContext ); } // verification succeeded (or not done) - we can simply skip the enhancement - LOG.tracef( "Skipping enhancement of [%s]: it's already annotated with @EnhancementInfo", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.skippingAlreadyAnnotated( managedCtClass.getName() ); return null; } // can't effectively enhance interfaces if ( managedCtClass.isInterface() ) { - LOG.tracef( "Skipping enhancement of [%s]: it's an interface", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.skippingInterface( managedCtClass.getName() ); return null; } // can't effectively enhance records if ( managedCtClass.isRecord() ) { - LOG.tracef( "Skipping enhancement of [%s]: it's a record", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.skippingRecord( managedCtClass.getName() ); return null; } @@ -194,7 +192,7 @@ private DynamicType.Builder doEnhance(Supplier> builde return null; } - LOG.tracef( "Enhancing [%s] as Entity", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.enhancingAsEntity( managedCtClass.getName() ); DynamicType.Builder builder = builderSupplier.get(); builder = builder .implement( constants.INTERFACES_for_ManagedEntity ) @@ -374,7 +372,7 @@ else if ( enhancementContext.isCompositeClass( managedCtClass ) ) { return null; } - LOG.tracef( "Enhancing [%s] as Composite", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.enhancingAsComposite( managedCtClass.getName() ); DynamicType.Builder builder = builderSupplier.get(); builder = builder.implement( constants.INTERFACES_for_ManagedComposite ); @@ -412,18 +410,18 @@ else if ( enhancementContext.isMappedSuperclassClass( managedCtClass ) ) { return null; } - LOG.tracef( "Enhancing [%s] as MappedSuperclass", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.enhancingAsMappedSuperclass( managedCtClass.getName() ); DynamicType.Builder builder = builderSupplier.get(); builder = builder.implement( constants.INTERFACES_for_ManagedMappedSuperclass ); return createTransformer( managedCtClass ).applyTo( builder ); } else if ( enhancementContext.doExtendedEnhancement() ) { - LOG.tracef( "Extended enhancement of [%s]", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.extendedEnhancement( managedCtClass.getName() ); return createTransformer( managedCtClass ).applyExtended( builderSupplier.get() ); } else { - LOG.tracef( "Skipping enhancement of [%s]: not entity or composite", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.skippingNotEntityOrComposite( managedCtClass.getName() ); return null; } } @@ -436,7 +434,7 @@ private void verifyReEnhancement( final String enhancementVersion = existingInfo.version(); if ( "ignore".equals( enhancementVersion ) ) { // for testing - LOG.debugf( "Skipping re-enhancement version check for %s due to `ignore`", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.skippingReEnhancementVersionCheck( managedCtClass.getName() ); } else if ( !Version.getVersionString().equals( enhancementVersion ) ) { throw new VersionMismatchException( managedCtClass, enhancementVersion, Version.getVersionString() ); @@ -607,9 +605,7 @@ private static boolean checkUnsupportedAttributeNaming(TypeDescription managedCt // We shouldn't even be in this method if using LEGACY, see top of this method. return switch ( strategy ) { case SKIP -> { - LOG.debugf( - "Skipping enhancement of [%s] because no field named [%s] could be found for property accessor method [%s]." - + " To fix this, make sure all property accessor methods have a matching field.", + BytecodeEnhancementLogging.LOGGER.propertyAccessorNoFieldSkip( managedCtClass.getName(), fieldName, methodDescription.getName() @@ -666,7 +662,7 @@ private boolean alreadyEnhanced(TypeDescription managedCtClass) { private DynamicType.Builder addInterceptorHandling(DynamicType.Builder builder, TypeDescription managedCtClass) { // interceptor handling is only needed if class has lazy-loadable attributes if ( enhancementContext.hasLazyLoadableAttributes( managedCtClass ) ) { - LOG.tracef( "Weaving in PersistentAttributeInterceptable implementation on [%s]", managedCtClass.getName() ); + BytecodeEnhancementLogging.LOGGER.weavingPersistentAttributeInterceptable( managedCtClass.getName() ); builder = builder.implement( constants.INTERFACES_for_PersistentAttributeInterceptable ); diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/FieldAccessEnhancer.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/FieldAccessEnhancer.java index 6ff6f0848322..fb9d6a79cccc 100644 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/FieldAccessEnhancer.java +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/FieldAccessEnhancer.java @@ -16,8 +16,7 @@ import org.hibernate.bytecode.enhance.internal.bytebuddy.EnhancerImpl.AnnotatedFieldDescription; import org.hibernate.bytecode.enhance.spi.EnhancementException; import org.hibernate.bytecode.enhance.spi.EnhancerConstants; -import org.hibernate.internal.CoreLogging; -import org.hibernate.internal.CoreMessageLogger; +import org.hibernate.bytecode.enhance.internal.BytecodeEnhancementLogging; import net.bytebuddy.asm.AsmVisitorWrapper; import net.bytebuddy.description.field.FieldList; @@ -33,8 +32,6 @@ final class FieldAccessEnhancer implements AsmVisitorWrapper.ForDeclaredMethods.MethodVisitorWrapper { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( FieldAccessEnhancer.class ); - private final TypeDescription managedCtClass; private final ByteBuddyEnhancementContext enhancementContext; @@ -76,8 +73,7 @@ public void visitFieldInsn(int opcode, String owner, String name, String desc) { && !field.hasAnnotation( Id.class ) && !field.getName().equals( "this$0" ) ) { - LOG.tracef( - "Extended enhancement: Transforming access to field [%s#%s] from method [%s#%s()]", + BytecodeEnhancementLogging.LOGGER.extendedTransformingFieldAccess( declaredOwnerType.getName(), field.getName(), instrumentedType.getName(), diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/PersistentAttributeTransformer.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/PersistentAttributeTransformer.java index 10d572a09fe2..fc69a1c3e250 100644 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/PersistentAttributeTransformer.java +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/internal/bytebuddy/PersistentAttributeTransformer.java @@ -17,8 +17,7 @@ import org.hibernate.bytecode.enhance.internal.bytebuddy.EnhancerImpl.AnnotatedFieldDescription; import org.hibernate.bytecode.enhance.spi.EnhancerConstants; -import org.hibernate.internal.CoreLogging; -import org.hibernate.internal.CoreMessageLogger; +import org.hibernate.bytecode.enhance.internal.BytecodeEnhancementLogging; import net.bytebuddy.asm.Advice; import net.bytebuddy.asm.AsmVisitorWrapper; @@ -43,8 +42,6 @@ final class PersistentAttributeTransformer implements AsmVisitorWrapper.ForDeclaredMethods.MethodVisitorWrapper { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( PersistentAttributeTransformer.class ); - private static final Junction NOT_HIBERNATE_GENERATED = not( nameStartsWith( "$$_hibernate_" ) ); private static final ModifierContributor.ForField REMOVE_PRIVATE_FINAL_MODIFIER = new ModifierContributor.ForField() { @Override @@ -130,9 +127,8 @@ public static PersistentAttributeTransformer collectPersistentFields( } AnnotatedFieldDescription[] orderedFields = enhancementContext.order( persistentFieldList.toArray( new AnnotatedFieldDescription[0] ) ); - if ( LOG.isTraceEnabled() ) { - LOG.tracef( - "Persistent fields for entity %s: %s", + if ( BytecodeEnhancementLogging.LOGGER.isTraceEnabled() ) { + BytecodeEnhancementLogging.LOGGER.persistentFieldsForEntity( managedCtClass.getName(), Arrays.toString( orderedFields ) ); @@ -158,7 +154,7 @@ else if ( !enhancementContext.isMappedSuperclassClass( managedCtSuperclass.asEra return collectInheritPersistentFields( managedCtSuperclass, enhancementContext ); } - LOG.tracef( "Found @MappedSuperclass %s to collectPersistenceFields", managedCtSuperclass ); + BytecodeEnhancementLogging.LOGGER.foundMappedSuperclass( String.valueOf( managedCtSuperclass ) ); List persistentFieldList = new ArrayList<>(); diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/BytecodeInterceptorLogging.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/BytecodeInterceptorLogging.java index 757bd943739f..44f8d72799eb 100644 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/BytecodeInterceptorLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/BytecodeInterceptorLogging.java @@ -5,7 +5,6 @@ package org.hibernate.bytecode.enhance.spi.interceptor; import org.hibernate.Internal; -import org.hibernate.bytecode.BytecodeLogging; import org.hibernate.internal.log.SubSystemLogging; import org.jboss.logging.BasicLogger; @@ -17,6 +16,7 @@ import java.lang.invoke.MethodHandles; +import static org.jboss.logging.Logger.Level.TRACE; import static org.jboss.logging.Logger.Level.WARN; /** @@ -30,8 +30,7 @@ ) @Internal public interface BytecodeInterceptorLogging extends BasicLogger { - String SUB_NAME = "interceptor"; - String LOGGER_NAME = BytecodeLogging.LOGGER_NAME + "." + SUB_NAME; + String LOGGER_NAME = SubSystemLogging.BASE + ".bytecode.interceptor"; Logger LOGGER = Logger.getLogger( LOGGER_NAME ); BytecodeInterceptorLogging MESSAGE_LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), BytecodeInterceptorLogging.class, LOGGER_NAME ); @@ -39,9 +38,13 @@ public interface BytecodeInterceptorLogging extends BasicLogger { @LogMessage(level = WARN) @Message( id = 90005901, - value = "`%s#%s` was mapped with explicit lazy-group (`%s`). Hibernate will ignore the lazy-group - this is generally " + - "not a good idea for to-one associations as it would lead to 2 separate SQL selects to initialize the association. " + + value = "'%s.%s' was mapped with explicit lazy group '%s'. Hibernate will ignore the lazy group - this is generally " + + "not a good idea for to-one associations as it leads to two separate SQL selects to initialize the association. " + "This is expected to be improved in future versions of Hibernate" ) void lazyGroupIgnoredForToOne(String ownerName, String attributeName, String requestedLazyGroup); + + @LogMessage(level = TRACE) + @Message(id = 90005902, value = "Forcing initialization: %s.%s -> %s") + void enhancementAsProxyLazinessForceInitialize(String entityName, Object identifier, String attributeName); } diff --git a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/EnhancementAsProxyLazinessInterceptor.java b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/EnhancementAsProxyLazinessInterceptor.java index dddf6ec4d65d..ef2821ae7d08 100644 --- a/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/EnhancementAsProxyLazinessInterceptor.java +++ b/hibernate-core/src/main/java/org/hibernate/bytecode/enhance/spi/interceptor/EnhancementAsProxyLazinessInterceptor.java @@ -9,7 +9,6 @@ import java.util.Set; import org.hibernate.HibernateException; -import org.hibernate.bytecode.BytecodeLogging; import org.hibernate.engine.spi.EntityKey; import org.hibernate.engine.spi.SharedSessionContractImplementor; import org.hibernate.metamodel.mapping.AttributeMapping; @@ -144,9 +143,8 @@ private Object extractIdValue(Object target, String attributeName) { } public Object forceInitialize(Object target, String attributeName) { - if ( BytecodeLogging.LOGGER.isTraceEnabled() ) { - BytecodeLogging.LOGGER.tracef( - "EnhancementAsProxyLazinessInterceptor#forceInitialize : %s#%s -> %s )", + if ( BytecodeInterceptorLogging.MESSAGE_LOGGER.isTraceEnabled() ) { + BytecodeInterceptorLogging.MESSAGE_LOGGER.enhancementAsProxyLazinessForceInitialize( entityKey.getEntityName(), entityKey.getIdentifier(), attributeName @@ -166,9 +164,8 @@ public Object forceInitialize( String attributeName, SharedSessionContractImplementor session, boolean isTemporarySession) { - if ( BytecodeLogging.LOGGER.isTraceEnabled() ) { - BytecodeLogging.LOGGER.tracef( - "EnhancementAsProxyLazinessInterceptor#forceInitialize : %s#%s -> %s )", + if ( BytecodeInterceptorLogging.MESSAGE_LOGGER.isTraceEnabled() ) { + BytecodeInterceptorLogging.MESSAGE_LOGGER.enhancementAsProxyLazinessForceInitialize( entityKey.getEntityName(), entityKey.getIdentifier(), attributeName diff --git a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java index 85efb677dd6c..d71784daa7bd 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java @@ -8,8 +8,6 @@ import org.hibernate.Internal; import org.hibernate.internal.log.SubSystemLogging; -import static org.hibernate.cfg.JdbcSettings.CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT; - import org.jboss.logging.BasicLogger; import org.jboss.logging.Logger; import org.jboss.logging.annotations.Cause; @@ -78,47 +76,6 @@ public interface JdbcLogging extends BasicLogger { @Message(value = "Closing unreleased batch in JdbcCoordinator @%s", id = 100008) void closingUnreleasedBatch(int hashCode); - @LogMessage(level = TRACE) - @Message(value = "Closing logical connection @%s", id = 100009) - void closingLogicalConnection(int hashCode); - - @LogMessage(level = TRACE) - @Message(value = "Closed logical connection @%s", id = 100010) - void logicalConnectionClosed(int hashCode); - - @LogMessage(level = TRACE) - @Message(value = "Skipping aggressive release of JDBC connection @%s from 'afterStatement' due to held resources", id = 100011) - void skipConnectionReleaseAfterStatementDueToResources(int hashCode); - - @LogMessage(level = TRACE) - @Message(value = "Initiating release of JDBC connection @%s from 'afterStatement'", id = 100012) - void initiatingConnectionReleaseAfterStatement(int hashCode); - - @LogMessage(level = TRACE) - @Message(value = "Initiating release of JDBC connection @%s from 'beforeTransactionCompletion'", id = 100013) - void initiatingConnectionReleaseBeforeTransactionCompletion(int hashCode); - - @LogMessage(level = TRACE) - @Message(value = "Initiating release of JDBC connection @%s from 'afterTransaction'", id = 100014) - void initiatingConnectionReleaseAfterTransaction(int hashCode); - - @LogMessage(level = WARN) - @Message(value = "Error before releasing JDBC connection @%s", id = 100015) - void errorBeforeReleasingJdbcConnection(int hashCode, @Cause Throwable e); - - @LogMessage(level = DEBUG) - @Message( - id = 100016, - value = - "'" + CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT + "' " + - """ - was enabled. This setting should only be enabled when JDBC Connections obtained by Hibernate \ - from the ConnectionProvider have auto-commit disabled. Enabling this setting when connections \ - have auto-commit enabled leads to execution of SQL operations outside of any JDBC transaction.\ - """ - ) - void connectionProviderDisablesAutoCommitEnabled(); - @LogMessage(level = DEBUG) @Message(value = """ Database: @@ -195,4 +152,28 @@ public interface JdbcLogging extends BasicLogger { @LogMessage(level = TRACE) @Message(value = "Sequence value retrieved from database: %s", id = 100032) void sequenceValueRetrievedFromDatabase(Number sequenceValue); + + @LogMessage(level = TRACE) + @Message(value = "Notifying resource-local transaction observers after begin", id = 100033) + void notifyingResourceLocalObserversAfterBegin(); + + @LogMessage(level = TRACE) + @Message(value = "Notifying resource-local transaction observers before completion", id = 100034) + void notifyingResourceLocalObserversBeforeCompletion(); + + @LogMessage(level = TRACE) + @Message(value = "Notifying resource-local transaction observers after completion", id = 100035) + void notifyingResourceLocalObserversAfterCompletion(); + + @LogMessage(level = TRACE) + @Message(value = "On commit, transaction was marked for rollback only, rolling back", id = 100036) + void onCommitMarkedRollbackOnlyRollingBack(); + + @LogMessage(level = TRACE) + @Message(value = "JDBC transaction marked for rollback only (exception provided for stack trace)", id = 100037) + void jdbcTransactionMarkedForRollbackOnly(@Cause Throwable stackTraceHolder); + + @LogMessage(level = DEBUG) + @Message(value = "Encountered failure rolling back failed commit", id = 100038) + void encounteredFailureRollingBackFailedCommit(@Cause Throwable cause); } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java index 510ddad591a5..41f4a64ea0e7 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java @@ -17,7 +17,6 @@ import org.hibernate.HibernateException; import org.hibernate.Internal; import org.hibernate.JDBCException; -import org.hibernate.LockMode; import org.hibernate.cache.CacheException; import org.hibernate.id.IntegralDataTypeHolder; import org.hibernate.type.SerializationException; @@ -29,7 +28,6 @@ import org.jboss.logging.annotations.MessageLogger; import org.jboss.logging.annotations.ValidIdRange; -import jakarta.transaction.Synchronization; import org.checkerframework.checker.nullness.qual.Nullable; import static org.jboss.logging.Logger.Level.DEBUG; @@ -110,14 +108,6 @@ public interface CoreMessageLogger extends BasicLogger { @Message(value = "Duplicate generator name %s", id = 69) void duplicateGeneratorName(String name); - @LogMessage(level = INFO) - @Message(value = "entity listener duplication, first event definition will be used: %s", id = 73) - void duplicateListener(String className); - - @LogMessage(level = WARN) - @Message(value = "Found more than one , subsequent ignored", id = 74) - void duplicateMetadata(); - @LogMessage(level = WARN) @Message(value = "Entity [%s] is abstract-class/interface explicitly mapped as non-abstract; be sure to supply entity-names", id = 84) @@ -273,14 +263,6 @@ void missingArguments( @Message(value = "Start time: %s", id = 251) void startTime(long startTime); - @LogMessage(level = INFO) - @Message(value = "Synchronization [%s] was already registered", id = 259) - void synchronizationAlreadyRegistered(Synchronization synchronization); - - @LogMessage(level = ERROR) - @Message(value = "Exception calling user Synchronization [%s]: %s", id = 260) - void synchronizationFailed(Synchronization synchronization, Throwable t); - @LogMessage(level = INFO) @Message(value = "Table not found: %s", id = 262) void tableNotFound(String name); @@ -301,10 +283,6 @@ void missingArguments( @Message(value = "Error accessing type info result set: %s", id = 273) void unableToAccessTypeInfoResultSet(String string); - @LogMessage(level = WARN) - @Message(value = "Unable to apply constraints on DDL for %s", id = 274) - void unableToApplyConstraints(String className, @Cause Exception e); - @LogMessage(level = WARN) @Message(value = "Unable to cleanup temporary id table after use [%s]", id = 283) void unableToCleanupTemporaryIdTable(Throwable t); @@ -483,14 +461,6 @@ void cannotResolveNonNullableTransientDependencies( ) void usingFollowOnLocking(); - @LogMessage(level = WARN) - @Message( - value = "Alias-specific lock modes requested, which is not currently supported with follow-on locking; " + - "all acquired locks will be [%s]", - id = 445 - ) - void aliasSpecificLockingWithFollowOnLocking(LockMode lockMode); - @LogMessage(level = WARN) @Message( value = "Explicit use of UPGRADE_SKIPLOCKED in lock() calls is not recommended; use normal UPGRADE locking instead", @@ -670,14 +640,6 @@ void unableToLocateStaticMetamodelField( ) void invalidJSONColumnType(String actual, String expected); - @LogMessage(level = TRACE) - @Message(value = "Closing logical connection", id = 456) - void closingLogicalConnection(); - - @LogMessage(level = TRACE) - @Message(value = "Logical connection closed", id = 457) - void logicalConnectionClosed(); - @LogMessage(level = TRACE) @Message(value = "Initializing service: %s", id = 500) void initializingService(String serviceRole); diff --git a/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/ContainerManagedLifecycleStrategy.java b/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/ContainerManagedLifecycleStrategy.java index 0f4511191652..36151c77bba6 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/ContainerManagedLifecycleStrategy.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/ContainerManagedLifecycleStrategy.java @@ -13,7 +13,7 @@ import org.hibernate.resource.beans.container.spi.ContainedBeanImplementor; import org.hibernate.resource.beans.spi.BeanInstanceProducer; -import org.jboss.logging.Logger; +import static org.hibernate.resource.beans.internal.BeansMessageLogger.BEANS_MSG_LOGGER; /** * A {@link BeanLifecycleStrategy} to use when CDI compliance is required @@ -26,8 +26,6 @@ * and are not duplicated, in contrast to {@link JpaCompliantLifecycleStrategy}. */ public class ContainerManagedLifecycleStrategy implements BeanLifecycleStrategy { - private static final Logger LOG = Logger.getLogger( ContainerManagedLifecycleStrategy.class ); - public static final ContainerManagedLifecycleStrategy INSTANCE = new ContainerManagedLifecycleStrategy(); private ContainerManagedLifecycleStrategy() { @@ -99,7 +97,7 @@ public void initialize() { throw e; } catch (Exception e) { - LOG.debug( "Error resolving CDI bean - using fallback" ); + BEANS_MSG_LOGGER.errorResolvingCdiBeanUsingFallback(); beanInstance = produceFallbackInstance(); instance = null; } @@ -124,12 +122,7 @@ public void release() { instance.destroy( beanInstance ); } catch (ContextNotActiveException e) { - LOG.debugf( - "Error destroying managed bean instance [%s] - the context is not active anymore." - + " The instance must have been destroyed already - ignoring.", - instance, - e - ); + BEANS_MSG_LOGGER.errorDestroyingManagedBeanInstanceContextNotActive( instance, e ); } finally { beanInstance = null; diff --git a/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/JpaCompliantLifecycleStrategy.java b/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/JpaCompliantLifecycleStrategy.java index ba8b76a72677..f033ce0c9d1d 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/JpaCompliantLifecycleStrategy.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/beans/container/internal/JpaCompliantLifecycleStrategy.java @@ -15,7 +15,7 @@ import org.hibernate.resource.beans.container.spi.ContainedBeanImplementor; import org.hibernate.resource.beans.spi.BeanInstanceProducer; -import org.jboss.logging.Logger; +import static org.hibernate.resource.beans.internal.BeansMessageLogger.BEANS_MSG_LOGGER; import java.util.Set; @@ -32,8 +32,6 @@ * the JPA 2.2 spec. */ public class JpaCompliantLifecycleStrategy implements BeanLifecycleStrategy { - private static final Logger LOG = Logger.getLogger( JpaCompliantLifecycleStrategy.class ); - public static final JpaCompliantLifecycleStrategy INSTANCE = new JpaCompliantLifecycleStrategy(); private JpaCompliantLifecycleStrategy() { @@ -141,7 +139,7 @@ public void initialize() { throw e; } catch (Exception e) { - LOG.debugf( "Error resolving CDI bean [%s] - using fallback", beanType.getName() ); + BEANS_MSG_LOGGER.errorResolvingCdiBeanUsingFallback( beanType.getName() ); beanInstance = fallbackProducer.produceBeanInstance( beanType ); try { @@ -255,7 +253,7 @@ public void initialize() { beanInstance = bean.create( creationalContext ); } catch (Exception e) { - LOG.debugf( "Error resolving CDI bean [%s] - using fallback", beanName ); + BEANS_MSG_LOGGER.errorResolvingCdiBeanUsingFallback( beanName ); beanInstance = fallbackProducer.produceBeanInstance( beanName, beanType ); try { diff --git a/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/BeansMessageLogger.java b/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/BeansMessageLogger.java index 9c73558b2d34..c2133bf06433 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/BeansMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/BeansMessageLogger.java @@ -9,6 +9,7 @@ import org.hibernate.resource.beans.container.spi.BeanContainer; import org.jboss.logging.Logger; +import org.jboss.logging.annotations.Cause; import org.jboss.logging.annotations.LogMessage; import org.jboss.logging.annotations.Message; import org.jboss.logging.annotations.MessageLogger; @@ -18,6 +19,7 @@ import static org.jboss.logging.Logger.Level.DEBUG; import static org.jboss.logging.Logger.Level.INFO; +import static org.jboss.logging.Logger.Level.TRACE; /** * @author Steve Ebersole @@ -34,6 +36,13 @@ public interface BeansMessageLogger { BeansMessageLogger BEANS_MSG_LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), BeansMessageLogger.class, LOGGER_NAME ); + @LogMessage( level = TRACE ) + @Message( + id = 10005001, + value = "Creating ManagedBean [%s] using direct instantiation" + ) + void creatingManagedBeanUsingDirectInstantiation(String beanName); + @LogMessage( level = INFO ) @Message( id = 10005002, @@ -42,6 +51,13 @@ public interface BeansMessageLogger { ) void noBeanManagerButCdiAvailable(); + @LogMessage( level = DEBUG ) + @Message( + id = 10005003, + value = "Error resolving CDI bean - using fallback" + ) + void errorResolvingCdiBeanUsingFallback(); + @LogMessage( level = DEBUG ) @Message( id = 10005004, @@ -49,6 +65,13 @@ public interface BeansMessageLogger { ) void stoppingBeanContainer(BeanContainer beanContainer); + @LogMessage( level = DEBUG ) + @Message( + id = 10005005, + value = "Error resolving CDI bean [%s] - using fallback" + ) + void errorResolvingCdiBeanUsingFallback(String identifier); + @LogMessage( level = DEBUG ) @Message( id = 10005006, @@ -62,4 +85,12 @@ public interface BeansMessageLogger { value = "Extended access to BeanManager" ) void extendedAccessToBeanManager(); + + @LogMessage( level = DEBUG ) + @Message( + id = 10005008, + value = "Error destroying managed bean instance [%s] - the context is not active anymore." + + " The instance must have been destroyed already - ignoring." + ) + void errorDestroyingManagedBeanInstanceContextNotActive(Object instance, @Cause Throwable e); } diff --git a/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/FallbackBeanInstanceProducer.java b/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/FallbackBeanInstanceProducer.java index eb38270ac75f..8a64ee2ce3ee 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/FallbackBeanInstanceProducer.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/beans/internal/FallbackBeanInstanceProducer.java @@ -8,7 +8,7 @@ import org.hibernate.InstantiationException; import org.hibernate.resource.beans.spi.BeanInstanceProducer; -import org.jboss.logging.Logger; +import static org.hibernate.resource.beans.internal.BeansMessageLogger.BEANS_MSG_LOGGER; /** * {@link BeanInstanceProducer} implementation based on direct instantiation. @@ -21,8 +21,6 @@ * @author Steve Ebersole */ public class FallbackBeanInstanceProducer implements BeanInstanceProducer { - private static final Logger LOG = Logger.getLogger( FallbackBeanInstanceProducer.class ); - /** * Singleton access */ @@ -33,7 +31,7 @@ private FallbackBeanInstanceProducer() { @Override public B produceBeanInstance(Class beanType) { - LOG.tracef( "Creating ManagedBean [%s] using direct instantiation", beanType.getName() ); + BEANS_MSG_LOGGER.creatingManagedBeanUsingDirectInstantiation( beanType.getName() ); try { final var constructor = beanType.getDeclaredConstructor(); constructor.setAccessible( true ); diff --git a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/AbstractLogicalConnectionImplementor.java b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/AbstractLogicalConnectionImplementor.java index b63566441b49..8e743bef09d0 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/AbstractLogicalConnectionImplementor.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/AbstractLogicalConnectionImplementor.java @@ -14,7 +14,7 @@ import org.hibernate.resource.jdbc.spi.PhysicalJdbcTransaction; import org.hibernate.resource.transaction.spi.TransactionStatus; -import org.jboss.logging.Logger; +import static org.hibernate.resource.jdbc.internal.LogicalConnectionLogging.LOGGER; /** * Base support for {@link LogicalConnection} implementations @@ -22,7 +22,6 @@ * @author Steve Ebersole */ public abstract class AbstractLogicalConnectionImplementor implements LogicalConnectionImplementor, PhysicalJdbcTransaction { - private static final Logger LOG = Logger.getLogger( AbstractLogicalConnectionImplementor.class ); private TransactionStatus status = TransactionStatus.NOT_ACTIVE; protected ResourceRegistry resourceRegistry; @@ -46,17 +45,14 @@ public ResourceRegistry getResourceRegistry() { @Override public void afterStatement() { -// LOG.trace( "LogicalConnection#afterStatement" ); } @Override public void beforeTransactionCompletion() { -// LOG.trace( "LogicalConnection#beforeTransactionCompletion" ); } @Override public void afterTransaction() { -// LOG.trace( "LogicalConnection#afterTransaction" ); resourceRegistry.releaseResources(); } @@ -68,9 +64,9 @@ public void afterTransaction() { public void begin() { try { if ( !doConnectionsFromProviderHaveAutoCommitDisabled() ) { - LOG.trace( "Preparing to begin transaction via JDBC Connection.setAutoCommit(false)" ); + LOGGER.preparingToBeginViaSetAutoCommitFalse(); getConnectionForTransactionManagement().setAutoCommit( false ); - LOG.trace( "Transaction begun via JDBC Connection.setAutoCommit(false)" ); + LOGGER.transactionBegunViaSetAutoCommitFalse(); } status = TransactionStatus.ACTIVE; } @@ -82,7 +78,7 @@ public void begin() { @Override public void commit() { try { - LOG.trace( "Preparing to commit transaction via JDBC Connection.commit()" ); + LOGGER.preparingToCommitViaConnectionCommit(); status = TransactionStatus.COMMITTING; if ( isPhysicallyConnected() ) { getConnectionForTransactionManagement().commit(); @@ -91,7 +87,7 @@ public void commit() { errorIfClosed(); } status = TransactionStatus.COMMITTED; - LOG.trace( "Transaction committed via JDBC Connection.commit()" ); + LOGGER.transactionCommittedViaConnectionCommit(); } catch( SQLException e ) { status = TransactionStatus.FAILED_COMMIT; @@ -108,20 +104,20 @@ protected void afterCompletion() { protected void resetConnection(boolean initiallyAutoCommit) { try { if ( initiallyAutoCommit ) { - LOG.trace( "Re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction" ); + LOGGER.reenablingAutoCommitAfterJdbcTransaction(); getConnectionForTransactionManagement().setAutoCommit( true ); status = TransactionStatus.NOT_ACTIVE; } } catch ( Exception e ) { - LOG.debug( "Could not re-enable auto-commit on JDBC Connection after completion of JDBC-based transaction", e ); + LOGGER.couldNotReEnableAutoCommit( e ); } } @Override public void rollback() { try { - LOG.trace( "Preparing to roll back transaction via JDBC Connection.rollback()" ); + LOGGER.preparingToRollbackViaConnectionRollback(); status = TransactionStatus.ROLLING_BACK; if ( isPhysicallyConnected() ) { getConnectionForTransactionManagement().rollback(); @@ -130,7 +126,7 @@ public void rollback() { errorIfClosed(); } status = TransactionStatus.ROLLED_BACK; - LOG.trace( "Transaction rolled back via JDBC Connection.rollback()" ); + LOGGER.transactionRolledBackViaConnectionRollback(); } catch( SQLException e ) { status = TransactionStatus.FAILED_ROLLBACK; @@ -145,7 +141,7 @@ protected static boolean determineInitialAutoCommitMode(Connection providedConne return providedConnection.getAutoCommit(); } catch (SQLException e) { - LOG.debug( "Unable to ascertain initial auto-commit state of provided connection; assuming auto-commit" ); + LOGGER.unableToAscertainInitialAutoCommit(); return true; } } diff --git a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionLogging.java b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionLogging.java new file mode 100644 index 000000000000..1fe245ccc9ba --- /dev/null +++ b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionLogging.java @@ -0,0 +1,137 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * Copyright Red Hat Inc. and Hibernate Authors + */ +package org.hibernate.resource.jdbc.internal; + +import org.hibernate.Internal; +import org.hibernate.internal.log.SubSystemLogging; +import org.jboss.logging.BasicLogger; +import org.jboss.logging.Logger; +import org.jboss.logging.annotations.Cause; +import org.jboss.logging.annotations.LogMessage; +import org.jboss.logging.annotations.Message; +import org.jboss.logging.annotations.MessageLogger; +import org.jboss.logging.annotations.ValidIdRange; + +import java.lang.invoke.MethodHandles; + +import static org.hibernate.cfg.JdbcSettings.CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT; +import static org.jboss.logging.Logger.Level.DEBUG; +import static org.jboss.logging.Logger.Level.TRACE; +import static org.jboss.logging.Logger.Level.WARN; + +/** + * Logging related to logical JDBC connection handling in the resource.jdbc.internal package + */ +@MessageLogger(projectCode = "HHH") +@ValidIdRange(min = 10003001, max = 10003100) +@SubSystemLogging( + name = LogicalConnectionLogging.LOGGER_NAME, + description = "Logging related to logical JDBC connection handling" +) +@Internal +public interface LogicalConnectionLogging extends BasicLogger { + String LOGGER_NAME = SubSystemLogging.BASE + ".resource.jdbc"; + LogicalConnectionLogging LOGGER = Logger.getMessageLogger( + MethodHandles.lookup(), LogicalConnectionLogging.class, LOGGER_NAME + ); + + // ---- TRACE: lifecycle around JDBC transactions on logical connection ---- + @LogMessage(level = TRACE) + @Message(id = 10003001, value = "Preparing to begin transaction via JDBC Connection.setAutoCommit(false)") + void preparingToBeginViaSetAutoCommitFalse(); + + @LogMessage(level = TRACE) + @Message(id = 10003002, value = "Transaction begun via JDBC Connection.setAutoCommit(false)") + void transactionBegunViaSetAutoCommitFalse(); + + @LogMessage(level = TRACE) + @Message(id = 10003003, value = "Preparing to commit transaction via JDBC Connection.commit()") + void preparingToCommitViaConnectionCommit(); + + @LogMessage(level = TRACE) + @Message(id = 10003004, value = "Transaction committed via JDBC Connection.commit()") + void transactionCommittedViaConnectionCommit(); + + @LogMessage(level = TRACE) + @Message(id = 10003005, value = "Preparing to roll back transaction via JDBC Connection.rollback()") + void preparingToRollbackViaConnectionRollback(); + + @LogMessage(level = TRACE) + @Message(id = 10003006, value = "Transaction rolled back via JDBC Connection.rollback()") + void transactionRolledBackViaConnectionRollback(); + + @LogMessage(level = TRACE) + @Message(id = 10003007, value = "Re-enabling auto-commit on JDBC Connection after completion of JDBC-based transaction") + void reenablingAutoCommitAfterJdbcTransaction(); + + // ---- DEBUG/TRACE for auto-commit reset issues ---- + @LogMessage(level = DEBUG) + @Message(id = 10003008, value = "Could not re-enable auto-commit on JDBC Connection after completion of JDBC-based transaction") + void couldNotReEnableAutoCommit(@Cause Exception e); + + @LogMessage(level = DEBUG) + @Message(id = 10003009, value = "Unable to ascertain initial auto-commit state of provided connection; assuming auto-commit") + void unableToAscertainInitialAutoCommit(); + + // ---- TRACE around manual reconnect in provided logical connection ---- + @LogMessage(level = TRACE) + @Message(id = 10003010, value = "Reconnecting the same connection that is already connected; should this connection have been disconnected?") + void reconnectingSameConnectionAlreadyConnected(); + + @LogMessage(level = TRACE) + @Message(id = 10003011, value = "Manually reconnected logical connection") + void manuallyReconnectedLogicalConnection(); + + // ---- TRACE around connection release timing in managed logical connection ---- + @LogMessage(level = TRACE) + @Message(id = 10003012, value = "Skipping aggressive release of JDBC connection @%s from 'afterStatement' due to held resources") + void skipConnectionReleaseAfterStatementDueToResources(int hashCode); + + @LogMessage(level = TRACE) + @Message(id = 10003013, value = "Initiating release of JDBC connection @%s from 'afterStatement'") + void initiatingConnectionReleaseAfterStatement(int hashCode); + + @LogMessage(level = TRACE) + @Message(id = 10003014, value = "Initiating release of JDBC connection @%s from 'beforeTransactionCompletion'") + void initiatingConnectionReleaseBeforeTransactionCompletion(int hashCode); + + @LogMessage(level = TRACE) + @Message(id = 10003015, value = "Initiating release of JDBC connection @%s from 'afterTransaction'") + void initiatingConnectionReleaseAfterTransaction(int hashCode); + + @LogMessage(level = WARN) + @Message(id = 10003016, value = "Error before releasing JDBC connection @%s") + void errorBeforeReleasingJdbcConnection(int hashCode, @Cause Throwable e); + + @LogMessage(level = TRACE) + @Message(id = 10003017, value = "Closing logical connection @%s") + void closingLogicalConnection(int hashCode); + + @LogMessage(level = TRACE) + @Message(id = 10003018, value = "Closed logical connection @%s") + void logicalConnectionClosed(int hashCode); + + // Variants without hashCode used by provided logical connection + @LogMessage(level = TRACE) + @Message(id = 10003019, value = "Closing logical connection") + void closingLogicalConnection(); + + @LogMessage(level = TRACE) + @Message(id = 10003020, value = "Closed logical connection") + void logicalConnectionClosed(); + + @LogMessage(level = DEBUG) + @Message( + id = 10003030, + value = + "'" + CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT + "' " + + """ + was enabled. This setting should only be enabled when JDBC Connections obtained by Hibernate \ + from the ConnectionProvider have auto-commit disabled. Enabling this setting when connections \ + have auto-commit enabled leads to execution of SQL operations outside of any JDBC transaction.\ + """ + ) + void connectionProviderDisablesAutoCommitEnabled(); +} diff --git a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionManagedImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionManagedImpl.java index 56705539606a..644099581cde 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionManagedImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionManagedImpl.java @@ -23,7 +23,7 @@ import static org.hibernate.ConnectionReleaseMode.AFTER_STATEMENT; import static org.hibernate.ConnectionReleaseMode.BEFORE_TRANSACTION_COMPLETION; import static org.hibernate.ConnectionReleaseMode.ON_CLOSE; -import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER; +import static org.hibernate.resource.jdbc.internal.LogicalConnectionLogging.LOGGER; import static org.hibernate.resource.jdbc.spi.PhysicalConnectionHandlingMode.DELAYED_ACQUISITION_AND_RELEASE_AFTER_TRANSACTION; /** @@ -53,7 +53,7 @@ public LogicalConnectionManagedImpl(JdbcSessionOwner sessionOwner, ResourceRegis } if ( sessionOwner.getJdbcSessionContext().doesConnectionProviderDisableAutoCommit() ) { - JDBC_MESSAGE_LOGGER.connectionProviderDisablesAutoCommitEnabled(); + LOGGER.connectionProviderDisablesAutoCommitEnabled(); } } @@ -131,10 +131,10 @@ public void afterStatement() { super.afterStatement(); if ( connectionHandlingMode.getReleaseMode() == AFTER_STATEMENT ) { if ( getResourceRegistry().hasRegisteredResources() ) { - JDBC_MESSAGE_LOGGER.skipConnectionReleaseAfterStatementDueToResources( hashCode() ); + LOGGER.skipConnectionReleaseAfterStatementDueToResources( hashCode() ); } else { - JDBC_MESSAGE_LOGGER.initiatingConnectionReleaseAfterStatement( hashCode() ); + LOGGER.initiatingConnectionReleaseAfterStatement( hashCode() ); releaseConnectionIfNeeded(); } } @@ -144,7 +144,7 @@ public void afterStatement() { public void beforeTransactionCompletion() { super.beforeTransactionCompletion(); if ( connectionHandlingMode.getReleaseMode() == BEFORE_TRANSACTION_COMPLETION ) { - JDBC_MESSAGE_LOGGER.initiatingConnectionReleaseBeforeTransactionCompletion( hashCode() ); +LOGGER.initiatingConnectionReleaseBeforeTransactionCompletion( hashCode() ); releaseConnectionIfNeeded(); } } @@ -157,7 +157,7 @@ public void afterTransaction() { // - AFTER_STATEMENT cases that were circumvented due to held resources // - BEFORE_TRANSACTION_COMPLETION cases that were circumvented because a rollback occurred // (we don't get a beforeTransactionCompletion event on rollback). - JDBC_MESSAGE_LOGGER.initiatingConnectionReleaseAfterTransaction( hashCode() ); +LOGGER.initiatingConnectionReleaseAfterTransaction( hashCode() ); releaseConnectionIfNeeded(); } } @@ -238,7 +238,7 @@ private void beforeRelease() { jdbcSessionOwner.beforeReleaseConnection( physicalConnection ); } catch (SQLException e) { - JDBC_MESSAGE_LOGGER.errorBeforeReleasingJdbcConnection( hashCode(), e ); +LOGGER.errorBeforeReleasingJdbcConnection( hashCode(), e ); } } @@ -256,14 +256,14 @@ public static LogicalConnectionManagedImpl deserialize(ObjectInputStream ois, Jd public Connection close() { if ( !closed ) { getResourceRegistry().releaseResources(); - JDBC_MESSAGE_LOGGER.closingLogicalConnection( hashCode() ); +LOGGER.closingLogicalConnection( hashCode() ); try { releaseConnectionIfNeeded(); } finally { // no matter what closed = true; - JDBC_MESSAGE_LOGGER.logicalConnectionClosed( hashCode() ); + LOGGER.logicalConnectionClosed( hashCode() ); } } return null; diff --git a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionProvidedImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionProvidedImpl.java index b944002f719a..1787037db60c 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionProvidedImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/jdbc/internal/LogicalConnectionProvidedImpl.java @@ -9,9 +9,7 @@ import java.io.ObjectOutputStream; import java.sql.Connection; -import org.hibernate.internal.CoreLogging; -import org.hibernate.internal.CoreMessageLogger; -import org.hibernate.resource.jdbc.LogicalConnection; +import static org.hibernate.resource.jdbc.internal.LogicalConnectionLogging.LOGGER; import org.hibernate.resource.jdbc.ResourceRegistry; import org.hibernate.resource.jdbc.spi.PhysicalConnectionHandlingMode; @@ -21,7 +19,6 @@ * @author Steve Ebersole */ public class LogicalConnectionProvidedImpl extends AbstractLogicalConnectionImplementor { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( LogicalConnection.class ); private transient Connection providedConnection; private final boolean initiallyAutoCommit; @@ -54,7 +51,7 @@ public boolean isOpen() { @Override public Connection close() { - LOG.closingLogicalConnection(); + LOGGER.closingLogicalConnection(); getResourceRegistry().releaseResources(); try { return providedConnection; @@ -62,7 +59,7 @@ public Connection close() { finally { providedConnection = null; closed = true; - LOG.logicalConnectionClosed(); + LOGGER.logicalConnectionClosed(); } } @@ -110,7 +107,7 @@ public void manualReconnect(Connection connection) { } else if ( connection == providedConnection ) { // likely an unmatched reconnect call (no matching disconnect call) - LOG.trace( "Reconnecting the same connection that is already connected; should this connection have been disconnected?" ); + LOGGER.reconnectingSameConnectionAlreadyConnected(); } else if ( providedConnection != null ) { throw new IllegalArgumentException( @@ -118,7 +115,7 @@ else if ( providedConnection != null ) { ); } providedConnection = connection; - LOG.trace( "Manually reconnected logical connection" ); + LOGGER.manuallyReconnectedLogicalConnection(); } @Override diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jdbc/internal/JdbcResourceLocalTransactionCoordinatorImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jdbc/internal/JdbcResourceLocalTransactionCoordinatorImpl.java index 30d52f731c52..2035e59be132 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jdbc/internal/JdbcResourceLocalTransactionCoordinatorImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jdbc/internal/JdbcResourceLocalTransactionCoordinatorImpl.java @@ -150,7 +150,7 @@ private void afterBeginCallback() { // report entering into a "transactional context" transactionCoordinatorOwner.startTransactionBoundary(); - JDBC_LOGGER.trace( "Notifying resource-local transaction observers after begin" ); + JDBC_MESSAGE_LOGGER.notifyingResourceLocalObserversAfterBegin(); // trigger the Transaction-API-only after-begin callback transactionCoordinatorOwner.afterTransactionBegin(); @@ -162,7 +162,7 @@ private void afterBeginCallback() { } private void beforeCompletionCallback() { - JDBC_LOGGER.trace( "Notifying resource-local transaction observers before completion" ); + JDBC_MESSAGE_LOGGER.notifyingResourceLocalObserversBeforeCompletion(); try { transactionCoordinatorOwner.beforeTransactionCompletion(); synchronizationRegistry.notifySynchronizationsBeforeTransactionCompletion(); @@ -180,7 +180,7 @@ private void beforeCompletionCallback() { } private void afterCompletionCallback(boolean successful) { - JDBC_LOGGER.trace( "Notifying resource-local transaction observers after completion" ); + JDBC_MESSAGE_LOGGER.notifyingResourceLocalObserversAfterCompletion(); final int statusToSend = successful ? Status.STATUS_COMMITTED : Status.STATUS_ROLLEDBACK; synchronizationRegistry.notifySynchronizationsAfterTransactionCompletion( statusToSend ); transactionCoordinatorOwner.afterTransactionCompletion( successful, false ); @@ -262,14 +262,14 @@ private void commitNoRollbackOnly() { } catch (RuntimeException e2) { e.addSuppressed( e2 ); - JDBC_LOGGER.debug( "Encountered failure rolling back failed commit", e2 ); + JDBC_MESSAGE_LOGGER.encounteredFailureRollingBackFailedCommit( e2 ); } throw e; } } private void commitRollbackOnly() { - JDBC_LOGGER.trace( "On commit, transaction was marked for rollback only, rolling back" ); + JDBC_MESSAGE_LOGGER.onCommitMarkedRollbackOnlyRollingBack(); rollback(); if ( jpaCompliance.isJpaTransactionComplianceEnabled() ) { throw new RollbackException( "Transaction was marked for rollback only" ); @@ -291,7 +291,7 @@ public void rollback() { @Override public TransactionStatus getStatus() { - final TransactionStatus status = jdbcResourceTransaction.getStatus(); + final var status = jdbcResourceTransaction.getStatus(); return rollbackOnly && status == TransactionStatus.ACTIVE ? TransactionStatus.MARKED_ROLLBACK : status; @@ -301,7 +301,7 @@ public TransactionStatus getStatus() { public void markRollbackOnly() { if ( getStatus() != TransactionStatus.ROLLED_BACK ) { if ( JDBC_LOGGER.isTraceEnabled() ) { - JDBC_LOGGER.trace( "JDBC transaction marked for rollback only (exception provided for stack trace)", + JDBC_MESSAGE_LOGGER.jdbcTransactionMarkedForRollbackOnly( new Exception( "exception just for purpose of providing stack trace" ) ); } rollbackOnly = true; diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/DdlTransactionIsolatorJtaImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/DdlTransactionIsolatorJtaImpl.java index af10bc684772..3057adf361e6 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/DdlTransactionIsolatorJtaImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/DdlTransactionIsolatorJtaImpl.java @@ -8,14 +8,14 @@ import java.sql.SQLException; import jakarta.transaction.SystemException; import jakarta.transaction.Transaction; -import jakarta.transaction.TransactionManager; import org.hibernate.HibernateException; import org.hibernate.engine.transaction.jta.platform.spi.JtaPlatform; import org.hibernate.resource.transaction.spi.DdlTransactionIsolator; import org.hibernate.tool.schema.internal.exec.JdbcContext; -import org.jboss.logging.Logger; + +import static org.hibernate.resource.transaction.backend.jta.internal.JtaLogging.JTA_LOGGER; /** * DdlExecutor for use in JTA environments @@ -23,31 +23,29 @@ * @author Steve Ebersole */ public class DdlTransactionIsolatorJtaImpl implements DdlTransactionIsolator { - private static final Logger LOG = Logger.getLogger( DdlTransactionIsolatorJtaImpl.class ); - private final JdbcContext jdbcContext; private final Transaction suspendedTransaction; private Connection jdbcConnection; + private static JtaPlatform getJtaPlatform(JdbcContext jdbcContext) { + return jdbcContext.getServiceRegistry().requireService( JtaPlatform.class ); + } + public DdlTransactionIsolatorJtaImpl(JdbcContext jdbcContext) { this.jdbcContext = jdbcContext; try { - final var jtaPlatform = jdbcContext.getServiceRegistry().requireService( JtaPlatform.class ); - LOG.tracef( "DdlTransactionIsolatorJtaImpl#prepare: JtaPlatform -> %s", jtaPlatform ); - - final TransactionManager tm = jtaPlatform.retrieveTransactionManager(); - if ( tm == null ) { + final var jtaPlatform = getJtaPlatform( jdbcContext ); + final var transactionManager = jtaPlatform.retrieveTransactionManager(); + if ( transactionManager == null ) { throw new HibernateException( "DdlTransactionIsolatorJtaImpl could not locate TransactionManager to suspend any current transaction; " + "base JtaPlatform impl (" + jtaPlatform + ")?" ); } - LOG.tracef( "DdlTransactionIsolatorJtaImpl#prepare: TransactionManager -> %s", tm ); - - this.suspendedTransaction = tm.suspend(); - LOG.tracef( "DdlTransactionIsolatorJtaImpl#prepare: suspended Transaction -> %s", this.suspendedTransaction ); + suspendedTransaction = transactionManager.suspend(); + JTA_LOGGER.suspendedTransactionForDdlIsolation( suspendedTransaction ); } catch (SystemException e) { throw new HibernateException( "Unable to suspend current JTA transaction in preparation for DDL execution" ); @@ -103,9 +101,10 @@ public void release() { if ( suspendedTransaction != null ) { try { - jdbcContext.getServiceRegistry().requireService( JtaPlatform.class ) + getJtaPlatform( jdbcContext ) .retrieveTransactionManager() .resume( suspendedTransaction ); + JTA_LOGGER.resumedTransactionForDdlIsolation(); } catch (Exception e) { throw new HibernateException( "Unable to resume JTA transaction after DDL execution" ); diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaLogging.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaLogging.java index 2ca751e2c497..554dd0d3efa9 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaLogging.java @@ -4,6 +4,7 @@ */ package org.hibernate.resource.transaction.backend.jta.internal; +import jakarta.transaction.Transaction; import org.hibernate.Internal; import org.hibernate.internal.log.SubSystemLogging; @@ -19,6 +20,7 @@ import static org.jboss.logging.Logger.Level.TRACE; import static org.jboss.logging.Logger.Level.WARN; +import static org.jboss.logging.Logger.Level.DEBUG; /** * Logging interface for JTA transaction operations. @@ -176,4 +178,129 @@ public interface JtaLogging extends BasicLogger { "delaying afterCompletion processing until the original thread can handle it. [status=%s]" ) void rollbackFromBackgroundThread(int status); + + @LogMessage(level = TRACE) + @Message( + value = "Suspended transaction to isolate DDL execution [%s]", + id = NAMESPACE + 30 + ) + void suspendedTransactionForDdlIsolation(Transaction suspendedTransaction); + + @LogMessage(level = TRACE) + @Message( + value = "Resumed transaction after isolated DDL execution", + id = NAMESPACE + 31 + ) + void resumedTransactionForDdlIsolation(); + + @LogMessage(level = TRACE) + @Message( + value = "JTA platform says we cannot currently register synchronization; skipping", + id = NAMESPACE + 32 + ) + void cannotRegisterSynchronization(); + + @LogMessage(level = TRACE) + @Message( + value = "Hibernate RegisteredSynchronization successfully registered with JTA platform", + id = NAMESPACE + 33 + ) + void registeredSynchronization(); + + @LogMessage(level = TRACE) + @Message( + value = "JTA transaction was already joined (RegisteredSynchronization already registered)", + id = NAMESPACE + 34 + ) + void alreadyJoinedJtaTransaction(); + + @LogMessage(level = TRACE) + @Message( + value = "Notifying JTA transaction observers before completion", + id = NAMESPACE + 35 + ) + void notifyingJtaObserversBeforeCompletion(); + + @LogMessage(level = TRACE) + @Message( + value = "Notifying JTA transaction observers after completion", + id = NAMESPACE + 36 + ) + void notifyingJtaObserversAfterCompletion(); + + @LogMessage(level = TRACE) + @Message( + value = "Registered JTA Synchronization: beforeCompletion()", + id = NAMESPACE + 37 + ) + void registeredSynchronizationBeforeCompletion(); + + @LogMessage(level = TRACE) + @Message( + value = "Registered JTA Synchronization: afterCompletion(%s)", + id = NAMESPACE + 38 + ) + void registeredSynchronizationAfterCompletion(int status); + + @LogMessage(level = TRACE) + @Message( + value = "Synchronization coordinator: beforeCompletion()", + id = NAMESPACE + 39 + ) + void synchronizationCoordinatorBeforeCompletion(); + + @LogMessage(level = TRACE) + @Message( + value = "Synchronization coordinator: afterCompletion(status=%s)", + id = NAMESPACE + 40 + ) + void synchronizationCoordinatorAfterCompletion(int status); + + @LogMessage(level = TRACE) + @Message( + value = "Synchronization coordinator: doAfterCompletion(successful=%s, delayed=%s)", + id = NAMESPACE + 41 + ) + void synchronizationCoordinatorDoAfterCompletion(boolean successful, boolean delayed); + @LogMessage(level = DEBUG) + @Message( + value = "Unable to access TransactionManager, attempting to use UserTransaction instead", + id = NAMESPACE + 42 + ) + void unableToAccessTransactionManagerTryingUserTransaction(); + + @LogMessage(level = DEBUG) + @Message( + value = "Unable to access UserTransaction, attempting to use TransactionManager instead", + id = NAMESPACE + 43 + ) + void unableToAccessUserTransactionTryingTransactionManager(); + + @LogMessage(level = DEBUG) + @Message( + value = "JtaPlatform.retrieveUserTransaction() returned null", + id = NAMESPACE + 44 + ) + void userTransactionReturnedNull(); + + @LogMessage(level = DEBUG) + @Message( + value = "JtaPlatform.retrieveUserTransaction() threw an exception [%s]", + id = NAMESPACE + 45 + ) + void exceptionRetrievingUserTransaction(String message, @Cause Exception cause); + + @LogMessage(level = DEBUG) + @Message( + value = "JtaPlatform.retrieveTransactionManager() returned null", + id = NAMESPACE + 46 + ) + void transactionManagerReturnedNull(); + + @LogMessage(level = DEBUG) + @Message( + value = "JtaPlatform.retrieveTransactionManager() threw an exception [%s]", + id = NAMESPACE + 47 + ) + void exceptionRetrievingTransactionManager(String message, @Cause Exception cause); } diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaTransactionCoordinatorImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaTransactionCoordinatorImpl.java index c48c84e0697a..a088ad437868 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaTransactionCoordinatorImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/JtaTransactionCoordinatorImpl.java @@ -71,13 +71,11 @@ public class JtaTransactionCoordinatorImpl implements TransactionCoordinator, Sy this.transactionCoordinatorBuilder = transactionCoordinatorBuilder; this.transactionCoordinatorOwner = owner; this.autoJoinTransactions = autoJoinTransactions; - - final var jdbcSessionContext = owner.getJdbcSessionOwner().getJdbcSessionContext(); - this.jtaPlatform = jtaPlatform; - this.preferUserTransactions = jdbcSessionContext.isPreferUserTransaction(); - this.performJtaThreadTracking = jdbcSessionContext.isJtaTrackByThread(); + final var jdbcSessionContext = owner.getJdbcSessionOwner().getJdbcSessionContext(); + preferUserTransactions = jdbcSessionContext.isPreferUserTransaction(); + performJtaThreadTracking = jdbcSessionContext.isJtaTrackByThread(); synchronizationRegistered = false; @@ -134,7 +132,7 @@ public void pulse() { if ( autoJoinTransactions && !synchronizationRegistered ) { // Can we register a synchronization according to the JtaPlatform? if ( !jtaPlatform.canRegisterSynchronization() ) { - JTA_LOGGER.trace( "JTA platform says we cannot currently register synchronization; skipping" ); + JTA_LOGGER.cannotRegisterSynchronization(); } else { joinJtaTransaction(); @@ -152,7 +150,7 @@ private void joinJtaTransaction() { new RegisteredSynchronization( getSynchronizationCallbackCoordinator() ) ); getSynchronizationCallbackCoordinator().synchronizationRegistered(); synchronizationRegistered = true; - JTA_LOGGER.trace( "Hibernate RegisteredSynchronization successfully registered with JTA platform" ); + JTA_LOGGER.registeredSynchronization(); // report entering into a "transactional context" getTransactionCoordinatorOwner().startTransactionBoundary(); } @@ -161,7 +159,7 @@ private void joinJtaTransaction() { @Override public void explicitJoin() { if ( synchronizationRegistered ) { - JTA_LOGGER.trace( "JTA transaction was already joined (RegisteredSynchronization already registered)" ); + JTA_LOGGER.alreadyJoinedJtaTransaction(); } else { if ( getTransactionDriverControl().getStatus() != ACTIVE ) { @@ -224,7 +222,7 @@ private TransactionDriverControlImpl makePhysicalTransactionDelegate() { private JtaTransactionAdapter getTransactionAdapterPreferringTransactionManager() { final var adapter = makeTransactionManagerAdapter(); if ( adapter == null ) { - JTA_LOGGER.debug( "Unable to access TransactionManager, attempting to use UserTransaction instead" ); + JTA_LOGGER.unableToAccessTransactionManagerTryingUserTransaction(); return makeUserTransactionAdapter(); } return adapter; @@ -233,7 +231,7 @@ private JtaTransactionAdapter getTransactionAdapterPreferringTransactionManager( private JtaTransactionAdapter getTransactionAdapterPreferringUserTransaction() { final var adapter = makeUserTransactionAdapter(); if ( adapter == null ) { - JTA_LOGGER.debug( "Unable to access UserTransaction, attempting to use TransactionManager instead" ); + JTA_LOGGER.unableToAccessUserTransactionTryingTransactionManager(); return makeTransactionManagerAdapter(); } return adapter; @@ -243,7 +241,7 @@ private JtaTransactionAdapter makeUserTransactionAdapter() { try { final var userTransaction = jtaPlatform.retrieveUserTransaction(); if ( userTransaction == null ) { - JTA_LOGGER.debug( "JtaPlatform.retrieveUserTransaction() returned null" ); + JTA_LOGGER.userTransactionReturnedNull(); return null; } else { @@ -251,7 +249,7 @@ private JtaTransactionAdapter makeUserTransactionAdapter() { } } catch ( Exception exception ) { - JTA_LOGGER.debugf( "JtaPlatform.retrieveUserTransaction() threw an exception [%s]", exception.getMessage() ); + JTA_LOGGER.exceptionRetrievingUserTransaction( exception.getMessage(), exception ); return null; } } @@ -260,7 +258,7 @@ private JtaTransactionAdapter makeTransactionManagerAdapter() { try { final var transactionManager = jtaPlatform.retrieveTransactionManager(); if ( transactionManager == null ) { - JTA_LOGGER.debug( "JtaPlatform.retrieveTransactionManager() returned null" ); + JTA_LOGGER.transactionManagerReturnedNull(); return null; } else { @@ -268,7 +266,7 @@ private JtaTransactionAdapter makeTransactionManagerAdapter() { } } catch ( Exception exception ) { - JTA_LOGGER.debugf( "JtaPlatform.retrieveTransactionManager() threw an exception [%s]", exception.getMessage() ); + JTA_LOGGER.exceptionRetrievingTransactionManager( exception.getMessage(), exception ); return null; } } @@ -320,7 +318,7 @@ public void invalidate() { @Override public void beforeCompletion() { - JTA_LOGGER.trace( "Notifying JTA transaction observers before completion" ); + JTA_LOGGER.notifyingJtaObserversBeforeCompletion(); try { transactionCoordinatorOwner.beforeTransactionCompletion(); } @@ -339,7 +337,7 @@ public void beforeCompletion() { @Override public void afterCompletion(boolean successful, boolean delayed) { if ( transactionCoordinatorOwner.isActive() ) { - JTA_LOGGER.trace( "Notifying JTA transaction observers after completion" ); + JTA_LOGGER.notifyingJtaObserversAfterCompletion(); final int statusToSend = successful ? Status.STATUS_COMMITTED : Status.STATUS_UNKNOWN; synchronizationRegistry.notifySynchronizationsAfterTransactionCompletion( statusToSend ); diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/RegisteredSynchronization.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/RegisteredSynchronization.java index 7f8d09014e16..85869a786730 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/RegisteredSynchronization.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/RegisteredSynchronization.java @@ -28,15 +28,13 @@ public RegisteredSynchronization(SynchronizationCallbackCoordinator synchronizat @Override public void beforeCompletion() { - JTA_LOGGER.trace( "Registered JTA Synchronization: beforeCompletion()" ); - + JTA_LOGGER.registeredSynchronizationBeforeCompletion(); synchronizationCallbackCoordinator.beforeCompletion(); } @Override public void afterCompletion(int status) { - JTA_LOGGER.tracef( "Registered JTA Synchronization: afterCompletion(%s)", status ); - + JTA_LOGGER.registeredSynchronizationAfterCompletion( status ); synchronizationCallbackCoordinator.afterCompletion( status ); } } diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorNonTrackingImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorNonTrackingImpl.java index 41d1d8f2837c..b02c03d98480 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorNonTrackingImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorNonTrackingImpl.java @@ -33,7 +33,7 @@ public void synchronizationRegistered() { @Override public void beforeCompletion() { - JTA_LOGGER.trace( "Synchronization coordinator: beforeCompletion()" ); + JTA_LOGGER.synchronizationCoordinatorBeforeCompletion(); if ( target.isActive() ) { target.beforeCompletion(); } @@ -41,13 +41,12 @@ public void beforeCompletion() { @Override public void afterCompletion(int status) { - JTA_LOGGER.tracef( "Synchronization coordinator: afterCompletion(status=%s)", status ); + JTA_LOGGER.synchronizationCoordinatorAfterCompletion( status ); doAfterCompletion( isCommitted( status ), false ); } protected void doAfterCompletion(boolean successful, boolean delayed) { - JTA_LOGGER.tracef( "Synchronization coordinator: doAfterCompletion(successful=%s, delayed=%s)", - successful, delayed ); + JTA_LOGGER.synchronizationCoordinatorDoAfterCompletion( successful, delayed ); try { target.afterCompletion( successful, delayed ); } diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorTrackingImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorTrackingImpl.java index 10ef463d487c..a955044ff01a 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorTrackingImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/backend/jta/internal/synchronization/SynchronizationCallbackCoordinatorTrackingImpl.java @@ -43,7 +43,7 @@ public void reset() { @Override public void afterCompletion(int status) { - JTA_LOGGER.tracef( "Synchronization coordinator: afterCompletion(status=%s)", status ); + JTA_LOGGER.synchronizationCoordinatorAfterCompletion( status ); // The whole concept of "tracking" comes down to this code block. // Essentially, we need to see if we can process the callback immediately. So here we check whether the diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationLogging.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationLogging.java new file mode 100644 index 000000000000..b3d0a18a7515 --- /dev/null +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationLogging.java @@ -0,0 +1,78 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * Copyright Red Hat Inc. and Hibernate Authors + */ +package org.hibernate.resource.transaction.internal; + +import jakarta.transaction.Synchronization; +import org.hibernate.Internal; +import org.hibernate.internal.log.SubSystemLogging; + +import org.jboss.logging.BasicLogger; +import org.jboss.logging.Logger; +import org.jboss.logging.annotations.Cause; +import org.jboss.logging.annotations.LogMessage; +import org.jboss.logging.annotations.Message; +import org.jboss.logging.annotations.MessageLogger; +import org.jboss.logging.annotations.ValidIdRange; + +import java.lang.invoke.MethodHandles; + +import static org.jboss.logging.Logger.Level.ERROR; +import static org.jboss.logging.Logger.Level.INFO; +import static org.jboss.logging.Logger.Level.TRACE; + +/** + * Logging interface for local Synchronization registry operations. + */ +@MessageLogger(projectCode = "HHH") +@ValidIdRange(min = 90008001, max = 90009000) +@SubSystemLogging( + name = SynchronizationLogging.LOGGER_NAME, + description = "Logging related to local Synchronization registry management" +) +@Internal +public interface SynchronizationLogging extends BasicLogger { + String LOGGER_NAME = SubSystemLogging.BASE + ".synchronization"; + + SynchronizationLogging SYNCHRONIZATION_LOGGER = Logger.getMessageLogger( + MethodHandles.lookup(), SynchronizationLogging.class, LOGGER_NAME + ); + + int NAMESPACE = 90008000; + + @LogMessage(level = TRACE) + @Message( + value = "Notifying Synchronizations (before completion)", + id = NAMESPACE + 1 + ) + void notifyingSynchronizationsBefore(); + + @LogMessage(level = TRACE) + @Message( + value = "Notifying Synchronizations (after completion with status %s)", + id = NAMESPACE + 2 + ) + void notifyingSynchronizationsAfter(int status); + + @LogMessage(level = TRACE) + @Message( + value = "Clearing local Synchronizations", + id = NAMESPACE + 3 + ) + void clearingSynchronizations(); + + @LogMessage(level = INFO) + @Message( + value = "Synchronization [%s] was already registered", + id = NAMESPACE + 4 + ) + void synchronizationAlreadyRegistered(Synchronization synchronization); + + @LogMessage(level = ERROR) + @Message( + value = "Exception calling user Synchronization [%s]", + id = NAMESPACE + 5 + ) + void synchronizationFailed(Synchronization synchronization, @Cause Throwable t); +} diff --git a/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationRegistryStandardImpl.java b/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationRegistryStandardImpl.java index 1c38252c0e5c..5414d73587e3 100644 --- a/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationRegistryStandardImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/resource/transaction/internal/SynchronizationRegistryStandardImpl.java @@ -7,19 +7,18 @@ import java.util.LinkedHashSet; import jakarta.transaction.Synchronization; -import org.hibernate.internal.CoreLogging; -import org.hibernate.internal.CoreMessageLogger; import org.hibernate.resource.transaction.LocalSynchronizationException; import org.hibernate.resource.transaction.NullSynchronizationException; import org.hibernate.resource.transaction.spi.SynchronizationRegistryImplementor; +import static org.hibernate.resource.transaction.internal.SynchronizationLogging.SYNCHRONIZATION_LOGGER; + /** * The standard implementation of the {@link org.hibernate.resource.transaction.spi.SynchronizationRegistry} contract. * * @author Steve Ebersole */ public class SynchronizationRegistryStandardImpl implements SynchronizationRegistryImplementor { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( SynchronizationRegistryStandardImpl.class ); private LinkedHashSet synchronizations; @@ -44,20 +43,20 @@ public void registerSynchronization(Synchronization synchronization) { final boolean added = synchronizations.add( synchronization ); if ( !added ) { - LOG.synchronizationAlreadyRegistered( synchronization ); + SYNCHRONIZATION_LOGGER.synchronizationAlreadyRegistered( synchronization ); } } @Override public void notifySynchronizationsBeforeTransactionCompletion() { - LOG.trace( "Notifying Synchronizations (before completion)" ); + SYNCHRONIZATION_LOGGER.notifyingSynchronizationsBefore(); if ( synchronizations != null ) { for ( var synchronization : synchronizations ) { try { synchronization.beforeCompletion(); } catch (Throwable t) { - LOG.synchronizationFailed( synchronization, t ); + SYNCHRONIZATION_LOGGER.synchronizationFailed( synchronization, t ); throw new LocalSynchronizationException( "Exception calling user Synchronization (beforeCompletion): " + synchronization.getClass().getName(), t @@ -69,7 +68,7 @@ public void notifySynchronizationsBeforeTransactionCompletion() { @Override public void notifySynchronizationsAfterTransactionCompletion(int status) { - LOG.tracef( "Notifying Synchronizations (after completion with status %s)", status ); + SYNCHRONIZATION_LOGGER.notifyingSynchronizationsAfter( status ); if ( synchronizations != null ) { try { for ( var synchronization : synchronizations ) { @@ -77,7 +76,7 @@ public void notifySynchronizationsAfterTransactionCompletion(int status) { synchronization.afterCompletion( status ); } catch (Throwable t) { - LOG.synchronizationFailed( synchronization, t ); + SYNCHRONIZATION_LOGGER.synchronizationFailed( synchronization, t ); throw new LocalSynchronizationException( "Exception calling user Synchronization (afterCompletion): " + synchronization.getClass().getName(), t @@ -93,7 +92,7 @@ public void notifySynchronizationsAfterTransactionCompletion(int status) { @Override public void clearSynchronizations() { - LOG.trace( "Clearing local Synchronizations" ); + SYNCHRONIZATION_LOGGER.clearingSynchronizations(); if ( synchronizations != null ) { synchronizations.clear(); }