From 4f82065c052a4673053c674672c9fbada2c5755e Mon Sep 17 00:00:00 2001 From: Gavin King Date: Sat, 13 Sep 2025 12:08:44 +0200 Subject: [PATCH 1/4] introduce SessionLogging --- .../hibernate/internal/CoreMessageLogger.java | 12 -- .../org/hibernate/internal/SessionImpl.java | 73 ++++---- .../hibernate/internal/SessionLogging.java | 158 ++++++++++++++++++ .../internal/StatelessSessionImpl.java | 27 ++- 4 files changed, 205 insertions(+), 65 deletions(-) create mode 100644 hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java 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 41f4a64ea0e7..e74a2d2cf1bb 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java @@ -16,7 +16,6 @@ import org.hibernate.HibernateException; import org.hibernate.Internal; -import org.hibernate.JDBCException; import org.hibernate.cache.CacheException; import org.hibernate.id.IntegralDataTypeHolder; import org.hibernate.type.SerializationException; @@ -589,12 +588,6 @@ void cannotResolveNonNullableTransientDependencies( id = 516) void enhancementDiscoveryFailed(String className, @Cause Throwable cause); - @LogMessage(level = DEBUG) - @Message(value = "JDBCException was thrown for a transaction marked for rollback. " + - " This is probably due to an operation failing fast due to the transaction being marked for rollback.", - id = 520) - void jdbcExceptionThrownWithTransactionRolledBack(@Cause JDBCException e); - @LogMessage(level = DEBUG) @Message(value = "Flushing and evicting managed instance of type [%s] before removing detached instance with same id", id = 530) @@ -614,11 +607,6 @@ void unableToLocateStaticMetamodelField( String name, String name2); - @LogMessage(level = DEBUG) - @Message(value = "Returning null (as required by JPA spec) rather than throwing EntityNotFoundException " + - "since the entity of type '%s' with id [%s] does not exist", id = 15013) - void ignoringEntityNotFound(String entityName, String identifier); - @LogMessage(level = DEBUG) @Message( id = 15015, diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java index 171fde9b9163..80eab2560ada 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java @@ -107,6 +107,7 @@ import static org.hibernate.event.spi.LoadEventListener.INTERNAL_LOAD_LAZY; import static org.hibernate.event.spi.LoadEventListener.INTERNAL_LOAD_NULLABLE; import static org.hibernate.internal.LockOptionsHelper.applyPropertiesToLockOptions; +import static org.hibernate.internal.SessionLogging.SESSION_LOGGER; import static org.hibernate.jpa.HibernateHints.HINT_BATCH_FETCH_SIZE; import static org.hibernate.jpa.HibernateHints.HINT_ENABLE_SUBSELECT_FETCH; import static org.hibernate.jpa.HibernateHints.HINT_FETCH_PROFILE; @@ -154,7 +155,6 @@ public class SessionImpl extends AbstractSharedSessionContract implements Serializable, SharedSessionContractImplementor, JdbcSessionOwner, SessionImplementor, EventSource, TransactionCoordinatorBuilder.Options, WrapperOptions, LoadAccessContext { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( SessionImpl.class ); // Defaults to null which means the properties are the default // as defined in FastSessionServices#defaultSessionProperties @@ -220,9 +220,8 @@ public SessionImpl(SessionFactoryImpl factory, SessionCreationOptions options) { statistics.openSession(); } - if ( LOG.isTraceEnabled() ) { - LOG.tracef( "Opened Session [%s] at timestamp: %s", - getSessionIdentifier(), currentTimeMillis() ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.openedSession( getSessionIdentifier(), currentTimeMillis() ); } } finally { @@ -359,7 +358,7 @@ public void close() { if ( getSessionFactoryOptions().getJpaCompliance().isJpaClosedComplianceEnabled() ) { throw new IllegalStateException( "EntityManager was already closed" ); } - LOG.trace( "Already closed" ); + SESSION_LOGGER.alreadyClosed(); } else { closeWithoutOpenChecks(); @@ -367,8 +366,8 @@ public void close() { } public void closeWithoutOpenChecks() { - if ( LOG.isTraceEnabled() ) { - LOG.tracef( "Closing session [%s]", getSessionIdentifier() ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.closingSession( getSessionIdentifier() ); } final var eventMonitor = getEventMonitor(); @@ -425,7 +424,7 @@ private boolean isTransactionActiveAndNotMarkedForRollback() { protected void checkBeforeClosingJdbcCoordinator() { final var actionQueue = getActionQueue(); if ( actionQueue.hasBeforeTransactionActions() || actionQueue.hasAfterTransactionActions() ) { - LOG.warn( "Closing shared session with unprocessed transaction completion actions" ); + SESSION_LOGGER.closingSharedSessionWithUnprocessedTxCompletions(); } } @@ -453,17 +452,17 @@ public boolean isOpen() { protected void checkSessionFactoryOpen() { if ( !getFactory().isOpen() ) { - LOG.trace( "Forcing-closing session since factory is already closed" ); + SESSION_LOGGER.forcingCloseBecauseFactoryClosed(); setClosed(); } } private void managedFlush() { if ( !isOpenOrWaitingForAutoClose() ) { - LOG.trace( "Skipping auto-flush since the session is closed" ); + SESSION_LOGGER.skippingAutoFlushSessionClosed(); } else { - LOG.trace( "Automatically flushing session" ); + SESSION_LOGGER.automaticallyFlushingSession(); fireFlush(); } } @@ -484,7 +483,7 @@ else if ( isClosed() ) { } private void managedClose() { - LOG.trace( "Automatically closing session" ); + SESSION_LOGGER.automaticallyClosingSession(); closeWithoutOpenChecks(); } @@ -825,7 +824,7 @@ private void fireMerge(final MergeContext mergeContext, final MergeEvent mergeEv public void delete(String entityName, Object object, boolean isCascadeDeleteEnabled, DeleteContext transientEntities) { checkOpenOrWaitingForAutoClose(); final boolean removingOrphanBeforeUpdates = persistenceContext.isRemovingOrphanBeforeUpdates(); - final boolean traceEnabled = LOG.isTraceEnabled(); + final boolean traceEnabled = SESSION_LOGGER.isTraceEnabled(); if ( traceEnabled && removingOrphanBeforeUpdates ) { logRemoveOrphanBeforeUpdates( "before continuing", entityName, object ); } @@ -842,7 +841,7 @@ public void delete(String entityName, Object object, boolean isCascadeDeleteEnab public void removeOrphanBeforeUpdates(String entityName, Object child) { // TODO: The removeOrphan concept is a temporary "hack" for HHH-6484. // This should be removed once action/task ordering is improved. - final boolean traceEnabled = LOG.isTraceEnabled(); + final boolean traceEnabled = SESSION_LOGGER.isTraceEnabled(); if ( traceEnabled ) { logRemoveOrphanBeforeUpdates( "begin", entityName, child ); } @@ -860,13 +859,10 @@ public void removeOrphanBeforeUpdates(String entityName, Object child) { } private void logRemoveOrphanBeforeUpdates(String timing, String entityName, Object entity) { - if ( LOG.isTraceEnabled() ) { + if ( SESSION_LOGGER.isTraceEnabled() ) { final var entityEntry = persistenceContext.getEntry( entity ); - LOG.tracef( - "%s remove orphan before updates: [%s]", - timing, - entityEntry == null ? entityName : infoString( entityName, entityEntry.getId() ) - ); + final String entityInfo = entityEntry == null ? entityName : infoString( entityName, entityEntry.getId() ); + SESSION_LOGGER.removeOrphanBeforeUpdates( timing, entityInfo ); } } @@ -1002,9 +998,9 @@ public Object get(String entityName, Object id) { */ @Override public Object immediateLoad(String entityName, Object id) { - if ( LOG.isDebugEnabled() ) { + if ( SESSION_LOGGER.isDebugEnabled() ) { final var persister = requireEntityPersister( entityName ); - LOG.tracef( "Initializing proxy: %s", infoString( persister, id, getFactory() ) ); + SESSION_LOGGER.initializingProxy( infoString( persister, id, getFactory() ) ); } final var event = makeLoadEvent( entityName, id, getReadOnlyFromLoadQueryInfluencers(), true ); fireLoadNoChecks( event, IMMEDIATE_LOAD ); @@ -1026,7 +1022,7 @@ public Object internalLoad(String entityName, Object id, boolean eager, boolean clearedEffectiveGraph = false; } else { - LOG.trace( "Clearing effective entity graph for subsequent select" ); + SESSION_LOGGER.clearingEffectiveEntityGraph(); clearedEffectiveGraph = true; effectiveEntityGraph.clear(); } @@ -1467,9 +1463,8 @@ public void forceFlush(EntityEntry entityEntry) { @Override public void forceFlush(EntityKey key) { - if ( LOG.isTraceEnabled() ) { - LOG.tracef("Flushing to force deletion of re-saved object: " - + infoString( key.getPersister(), key.getIdentifier(), getFactory() ) ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.flushingToForceDeletion( infoString( key.getPersister(), key.getIdentifier(), getFactory() ) ); } if ( persistenceContext.getCascadeLevel() > 0 ) { @@ -1839,7 +1834,7 @@ public String toString() { .append( "SessionImpl(" ) .append( System.identityHashCode( this ) ); if ( !isClosed() ) { - if ( LOG.isTraceEnabled() ) { + if ( SESSION_LOGGER.isTraceEnabled() ) { string.append( persistenceContext ) .append( ";" ) .append( actionQueue ); @@ -1991,7 +1986,7 @@ public LobHelper getLobHelper() { @Override public void beforeTransactionCompletion() { - LOG.trace( "SessionImpl#beforeTransactionCompletion()" ); + SESSION_LOGGER.beforeTransactionCompletion(); flushBeforeTransactionCompletion(); actionQueue.beforeTransactionCompletion(); beforeTransactionCompletionEvents(); @@ -2000,8 +1995,8 @@ public void beforeTransactionCompletion() { @Override public void afterTransactionCompletion(boolean successful, boolean delayed) { - if ( LOG.isTraceEnabled() ) { - LOG.tracef( "SessionImpl#afterTransactionCompletion(successful=%s, delayed=%s)", successful, delayed ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.afterTransactionCompletion( successful, delayed ); } final boolean notClosed = isOpenOrWaitingForAutoClose(); @@ -2193,7 +2188,7 @@ private T find(Class entityClass, Object primaryKey, LockOptions lockOpti if ( accessTransaction().isActive() && accessTransaction().getRollbackOnly() ) { // Assume situation HHH-12472 running on WildFly // Just log the exception and return null - LOG.jdbcExceptionThrownWithTransactionRolledBack( e ); + SESSION_LOGGER.jdbcExceptionThrownWithTransactionRolledBack( e ); return null; } else { @@ -2211,8 +2206,8 @@ private T find(Class entityClass, Object primaryKey, LockOptions lockOpti // Hibernate Reactive calls this protected static void logIgnoringEntityNotFound(Class entityClass, Object primaryKey) { - if ( LOG.isDebugEnabled() ) { - LOG.ignoringEntityNotFound( + if ( SESSION_LOGGER.isDebugEnabled() ) { + SESSION_LOGGER.ignoringEntityNotFound( entityClass != null ? entityClass.getName(): null, primaryKey != null ? primaryKey.toString() : null ); @@ -2544,12 +2539,12 @@ public void setProperty(String propertyName, Object value) { checkOpen(); if ( !( value instanceof Serializable ) ) { - LOG.warnf( "Property '%s' is not serializable, value won't be set", propertyName ); + SESSION_LOGGER.nonSerializableProperty( propertyName ); return; } if ( propertyName == null ) { - LOG.warn( "Property having key null is illegal, value won't be set" ); + SESSION_LOGGER.nullPropertyKey(); return; } @@ -2767,8 +2762,8 @@ public Collection getManagedEntities(EntityType entityType) { */ @Serial private void writeObject(ObjectOutputStream oos) throws IOException { - if ( LOG.isTraceEnabled() ) { - LOG.tracef( "Serializing Session [%s]", getSessionIdentifier() ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.serializingSession( getSessionIdentifier() ); } oos.defaultWriteObject(); @@ -2789,8 +2784,8 @@ private void writeObject(ObjectOutputStream oos) throws IOException { */ @Serial private void readObject(ObjectInputStream ois) throws IOException, ClassNotFoundException, SQLException { - if ( LOG.isTraceEnabled() ) { - LOG.tracef( "Deserializing Session [%s]", getSessionIdentifier() ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.deserializingSession( getSessionIdentifier() ); } ois.defaultReadObject(); diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java new file mode 100644 index 000000000000..5d87d63179dc --- /dev/null +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java @@ -0,0 +1,158 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * Copyright Red Hat Inc. and Hibernate Authors + */ +package org.hibernate.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 java.util.UUID; + +import static org.jboss.logging.Logger.Level.DEBUG; +import static org.jboss.logging.Logger.Level.ERROR; +import static org.jboss.logging.Logger.Level.TRACE; +import static org.jboss.logging.Logger.Level.WARN; + +/** + * Sub-system logging related to Session/StatelessSession runtime events + */ +@SubSystemLogging( + name = SessionLogging.NAME, + description = "Logging related to Session / StatelessSession lifecycle and operations" +) +@MessageLogger(projectCode = "HHH") +@ValidIdRange(min = 90006101, max = 90006500) +@Internal +public interface SessionLogging extends BasicLogger { + String NAME = SubSystemLogging.BASE + ".session"; + + SessionLogging SESSION_LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), SessionLogging.class, NAME ); + + @LogMessage(level = TRACE) + @Message("Opened Session [%s] at timestamp: %s") + void openedSession(UUID sessionIdentifier, long timestamp); + + @LogMessage(level = TRACE) + @Message("Already closed") + void alreadyClosed(); + + @LogMessage(level = TRACE) + @Message("Closing session [%s]") + void closingSession(UUID sessionIdentifier); + + @LogMessage(level = WARN) + @Message(id = 90006101, value = "Closing shared session with unprocessed transaction completion actions") + void closingSharedSessionWithUnprocessedTxCompletions(); + + @LogMessage(level = TRACE) + @Message("Forcing-closing session since factory is already closed") + void forcingCloseBecauseFactoryClosed(); + + @LogMessage(level = TRACE) + @Message("Skipping auto-flush since the session is closed") + void skippingAutoFlushSessionClosed(); + + @LogMessage(level = TRACE) + @Message("Automatically flushing session") + void automaticallyFlushingSession(); + + @LogMessage(level = TRACE) + @Message("Automatically closing session") + void automaticallyClosingSession(); + + @LogMessage(level = TRACE) + @Message("%s remove orphan before updates: [%s]") + void removeOrphanBeforeUpdates(String timing, String entityInfo); + + @LogMessage(level = TRACE) + @Message("Initializing proxy: %s") + void initializingProxy(String entityInfo); + + @LogMessage(level = TRACE) + @Message("Clearing effective entity graph for subsequent select") + void clearingEffectiveEntityGraph(); + + @LogMessage(level = TRACE) + @Message("Flushing to force deletion of re-saved object: %s") + void flushingToForceDeletion(String entityInfo); + + @LogMessage(level = TRACE) + @Message("Before transaction completion processing") + void beforeTransactionCompletion(); + + @LogMessage(level = TRACE) + @Message("After transaction completion processing (successful=%s, delayed=%s)") + void afterTransactionCompletion(boolean successful, boolean delayed); + + @LogMessage(level = ERROR) + @Message(id = 90006102, value = "JDBC exception executing SQL; transaction rolled back") + void jdbcExceptionThrownWithTransactionRolledBack(@Cause Exception e); + + @LogMessage(level = DEBUG) + @Message(id = 90006103, value = "Ignoring EntityNotFoundException for '%s.%s'") + void ignoringEntityNotFound(String entityName, Object id); + + @LogMessage(level = WARN) + @Message(id = 90006104, value = "Property '%s' is not serializable, value won't be set") + void nonSerializableProperty(String propertyName); + + @LogMessage(level = WARN) + @Message(id = 90006105, value = "Property having key null is illegal, value won't be set") + void nullPropertyKey(); + + @LogMessage(level = TRACE) + @Message("Serializing Session [%s]") + void serializingSession(UUID sessionIdentifier); + + @LogMessage(level = TRACE) + @Message("Deserializing Session [%s]") + void deserializingSession(UUID sessionIdentifier); + + // StatelessSession-specific + + @LogMessage(level = TRACE) + @Message("Refreshing transient %s") + void refreshingTransient(String entityInfo); + + @LogMessage(level = TRACE) + @Message("Initializing collection %s") + void initializingCollection(String collectionInfo); + + @LogMessage(level = TRACE) + @Message("Collection initialized from cache") + void collectionInitializedFromCache(); + + @LogMessage(level = TRACE) + @Message("Collection initialized") + void collectionInitialized(); + + @LogMessage(level = TRACE) + @Message("Entity proxy found in session cache") + void entityProxyFoundInSessionCache(); + + @LogMessage(level = DEBUG) + @Message("Ignoring NO_PROXY to honor laziness") + void ignoringNoProxyToHonorLaziness(); + + @LogMessage(level = TRACE) + @Message("Creating a HibernateProxy for to-one association with subclasses to honor laziness") + void creatingHibernateProxyToHonorLaziness(); + + @LogMessage(level = TRACE) + @Message("Collection fetched from cache") + void collectionFetchedFromCache(); + + @LogMessage(level = TRACE) + @Message("Collection fetched") + void collectionFetched(); +} diff --git a/hibernate-core/src/main/java/org/hibernate/internal/StatelessSessionImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/StatelessSessionImpl.java index 100168c55926..e3a59f85389f 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/StatelessSessionImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/StatelessSessionImpl.java @@ -81,6 +81,7 @@ import static org.hibernate.engine.transaction.internal.jta.JtaStatusHelper.isRollback; import static org.hibernate.event.internal.DefaultInitializeCollectionEventListener.handlePotentiallyEmptyCollection; import static org.hibernate.generator.EventType.INSERT; +import static org.hibernate.internal.SessionLogging.SESSION_LOGGER; import static org.hibernate.internal.util.NullnessUtil.castNonNull; import static org.hibernate.loader.internal.CacheLoadHelper.initializeCollectionFromCache; import static org.hibernate.pretty.MessageHelper.collectionInfoString; @@ -112,7 +113,6 @@ * @author Steve Ebersole */ public class StatelessSessionImpl extends AbstractSharedSessionContract implements StatelessSessionImplementor { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( StatelessSessionImpl.class ); public static final MultiIdLoadOptions MULTI_ID_LOAD_OPTIONS = new MultiLoadOptions(); @@ -924,8 +924,8 @@ public void refresh(String entityName, Object entity, LockMode lockMode) { checkOpen(); final var persister = getEntityPersister( entityName, entity ); final Object id = persister.getIdentifier( entity, this ); - if ( LOG.isTraceEnabled() ) { - LOG.tracev( "Refreshing transient {0}", infoString( persister, id, getFactory() ) ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.refreshingTransient( infoString( persister, id, getFactory() ) ); } if ( persister.canWriteToCache() ) { @@ -971,19 +971,18 @@ public void initializeCollection(PersistentCollection collection, boolean wri if ( !collection.wasInitialized() ) { final var loadedPersister = ce.getLoadedPersister(); final Object loadedKey = ce.getLoadedKey(); - if ( LOG.isTraceEnabled() ) { - LOG.trace( "Initializing collection " - + collectionInfoString( loadedPersister, collection, loadedKey, this ) ); + if ( SESSION_LOGGER.isTraceEnabled() ) { + SESSION_LOGGER.initializingCollection( collectionInfoString( loadedPersister, collection, loadedKey, this ) ); } final boolean foundInCache = initializeCollectionFromCache( loadedKey, loadedPersister, collection, this ); if ( foundInCache ) { - LOG.trace( "Collection initialized from cache" ); + SESSION_LOGGER.collectionInitializedFromCache(); } else { loadedPersister.initialize( loadedKey, this ); handlePotentiallyEmptyCollection( collection, persistenceContext, loadedKey, loadedPersister ); - LOG.trace( "Collection initialized" ); + SESSION_LOGGER.collectionInitialized(); final var statistics = getStatistics(); if ( statistics.isStatisticsEnabled() ) { statistics.fetchCollection( loadedPersister.getRole() ); @@ -1037,9 +1036,9 @@ public Object internalLoad( final Object proxy = holder == null ? null : holder.getProxy(); if ( proxy != null ) { - LOG.trace( "Entity proxy found in session cache" ); - if ( LOG.isDebugEnabled() && extractLazyInitializer( proxy ).isUnwrap() ) { - LOG.debug( "Ignoring NO_PROXY to honor laziness" ); + SESSION_LOGGER.entityProxyFoundInSessionCache(); + if ( SESSION_LOGGER.isDebugEnabled() && extractLazyInitializer( proxy ).isUnwrap() ) { + SESSION_LOGGER.ignoringNoProxyToHonorLaziness(); } return persistenceContext.narrowProxy( proxy, persister, entityKey, null ); @@ -1048,7 +1047,7 @@ public Object internalLoad( // specialized handling for entities with subclasses with a HibernateProxy factory if ( persister.hasSubclasses() ) { // entities with subclasses that define a ProxyFactory can create a HibernateProxy. - LOG.trace( "Creating a HibernateProxy for to-one association with subclasses to honor laziness" ); + SESSION_LOGGER.creatingHibernateProxyToHonorLaziness(); return createProxy( entityKey ); } return enhancementMetadata.createEnhancedProxy( entityKey, false, this ); @@ -1145,13 +1144,13 @@ else if ( association instanceof PersistentCollection collection ) { final boolean foundInCache = initializeCollectionFromCache( key, collectionDescriptor, collection, this ); if ( foundInCache ) { - LOG.trace( "Collection fetched from cache" ); + SESSION_LOGGER.collectionFetchedFromCache(); } else { collectionDescriptor.initialize( key, this ); handlePotentiallyEmptyCollection( collection, getPersistenceContextInternal(), key, collectionDescriptor ); - LOG.trace( "Collection fetched" ); + SESSION_LOGGER.collectionFetched(); final var statistics = getStatistics(); if ( statistics.isStatisticsEnabled() ) { statistics.fetchCollection( collectionDescriptor.getRole() ); From 135b77c34f48428489974f35bbb02c0f922794be Mon Sep 17 00:00:00 2001 From: Gavin King Date: Sat, 13 Sep 2025 12:24:10 +0200 Subject: [PATCH 2/4] introduce SessionFactoryLogging --- .../hibernate/internal/CoreMessageLogger.java | 21 ---- .../internal/SessionFactoryImpl.java | 50 ++++----- .../internal/SessionFactoryLogging.java | 106 ++++++++++++++++++ .../internal/SessionFactoryRegistry.java | 67 +++++------ .../SessionFactoryRegistryMessageLogger.java | 30 +++-- .../hibernate/internal/SessionLogging.java | 2 +- .../internal/util/xml/DTDEntityResolver.java | 2 +- 7 files changed, 188 insertions(+), 90 deletions(-) create mode 100644 hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java 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 e74a2d2cf1bb..4bfd3f261f04 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java @@ -9,7 +9,6 @@ import java.io.IOException; import java.sql.SQLException; import java.sql.SQLWarning; -import java.util.Map; import java.util.Properties; import java.util.ServiceConfigurationError; import java.util.Set; @@ -67,22 +66,6 @@ public interface CoreMessageLogger extends BasicLogger { @Message(value = "Second-level cache disabled", id = 26) void noRegionFactory(); - @LogMessage(level = DEBUG) - @Message(value = "Instantiating factory [%s] with settings: %s", id = 30) - void instantiatingFactory(String uuid, Map settings); - - @LogMessage(level = DEBUG) - @Message(value = "Closing factory [%s]", id = 31) - void closingFactory(String uuid); - - @LogMessage(level = DEBUG) - @Message(value = "Serializing factory [%s]", id = 32) - void serializingFactory(String uuid); - - @LogMessage(level = DEBUG) - @Message(value = "Deserialized factory [%s]", id = 33) - void deserializedFactory(String uuid); - @LogMessage(level = WARN) @Message(value = "Composite id class does not override equals(): %s", id = 38) void compositeIdClassDoesNotOverrideEquals(String name); @@ -306,10 +289,6 @@ void missingArguments( @Message(value = "Could not close stream on hibernate.properties: %s", id = 297) void unableToCloseStreamError(IOException error); - @LogMessage(level = ERROR) - @Message(value = "Unable to construct current session context [%s]", id = 302) - void unableToConstructCurrentSessionContext(String impl, @Cause Throwable e); - @LogMessage(level = WARN) @Message(value = "Unable to close temporary session used to load lazy collection associated to no session", id = 303) void unableToCloseTemporarySession(); diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java index 89008771e595..f77ba2f5df76 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java @@ -127,6 +127,7 @@ import static java.util.Collections.unmodifiableSet; import static org.hibernate.cfg.AvailableSettings.CURRENT_SESSION_CONTEXT_CLASS; import static org.hibernate.internal.FetchProfileHelper.addFetchProfiles; +import static org.hibernate.internal.SessionFactoryLogging.SESSION_FACTORY_LOGGER; import static org.hibernate.internal.SessionFactorySettings.determineJndiName; import static org.hibernate.internal.SessionFactorySettings.getMaskedSettings; import static org.hibernate.internal.SessionFactorySettings.getSessionFactoryName; @@ -155,7 +156,6 @@ * @author Chris Cranford */ public class SessionFactoryImpl implements SessionFactoryImplementor { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( SessionFactoryImpl.class ); private final String name; private final String jndiName; @@ -211,7 +211,7 @@ public SessionFactoryImpl( final MetadataImplementor bootMetamodel, final SessionFactoryOptions options, final BootstrapContext bootstrapContext) { - LOG.trace( "Building session factory" ); +SESSION_FACTORY_LOGGER.buildingSessionFactory(); typeConfiguration = bootstrapContext.getTypeConfiguration(); sessionFactoryOptions = options; @@ -228,7 +228,7 @@ public SessionFactoryImpl( jdbcServices = serviceRegistry.requireService( JdbcServices.class ); settings = getMaskedSettings( options, serviceRegistry ); - LOG.instantiatingFactory( uuid, settings ); + SESSION_FACTORY_LOGGER.instantiatingFactory( uuid, settings ); sqlStringGenerationContext = createSqlStringGenerationContext( bootMetamodel, options, jdbcServices ); @@ -330,14 +330,12 @@ public SessionFactoryImpl( close(); } catch (Exception closeException) { - LOG.trace( "Eating error closing factory after failed instantiation" ); + SESSION_FACTORY_LOGGER.eatingErrorClosingFactoryAfterFailedInstantiation(); } throw e; } - if ( LOG.isTraceEnabled() ) { - LOG.trace( "Instantiated factory: " + uuid ); - } + SESSION_FACTORY_LOGGER.instantiatedFactory( uuid ); } private JavaType tenantIdentifierType(SessionFactoryOptions options) { @@ -762,7 +760,7 @@ public Interceptor getInterceptor() { @Override public Reference getReference() { // from javax.naming.Referenceable - LOG.trace( "Returning a Reference to the factory" ); + SESSION_FACTORY_LOGGER.returningReferenceToFactory(); return new Reference( SessionFactoryImpl.class.getName(), new StringRefAddr( "uuid", getUuid() ), @@ -792,16 +790,14 @@ public void close() { if ( getSessionFactoryOptions().getJpaCompliance().isJpaClosedComplianceEnabled() ) { throw new IllegalStateException( "EntityManagerFactory is already closed" ); } - - LOG.trace( "Already closed" ); + SESSION_FACTORY_LOGGER.alreadyClosed(); return; } - status = Status.CLOSING; } try { - LOG.closingFactory( getUuid() ); + SESSION_FACTORY_LOGGER.closingFactory( uuid ); observer.sessionFactoryClosing( this ); // NOTE: the null checks below handle cases where close is called @@ -1036,8 +1032,8 @@ private CurrentSessionContext createSessionContext(String sessionContextType) { .getConstructor( new Class[]{ SessionFactoryImplementor.class } ) .newInstance( this ); } - catch ( Throwable t ) { - LOG.unableToConstructCurrentSessionContext( sessionContextType, t ); + catch ( Throwable throwable ) { + SESSION_FACTORY_LOGGER.unableToConstructCurrentSessionContext( sessionContextType, throwable ); return null; } } @@ -1109,9 +1105,9 @@ boolean connectionProviderHandlesConnectionSchema() { */ @Serial private void writeObject(ObjectOutputStream out) throws IOException { - LOG.serializingFactory( getUuid() ); + SESSION_FACTORY_LOGGER.serializingFactory( uuid ); out.defaultWriteObject(); - LOG.trace( "Serialized factory" ); + SESSION_FACTORY_LOGGER.serializedFactory(); } /** @@ -1124,9 +1120,9 @@ private void writeObject(ObjectOutputStream out) throws IOException { */ @Serial private void readObject(ObjectInputStream in) throws IOException, ClassNotFoundException { - LOG.trace( "Deserializing factory" ); + SESSION_FACTORY_LOGGER.deserializingFactory(); in.defaultReadObject(); - LOG.deserializedFactory( getUuid() ); + SESSION_FACTORY_LOGGER.deserializedFactory( uuid ); } /** @@ -1142,16 +1138,16 @@ private void readObject(ObjectInputStream in) throws IOException, ClassNotFoundE */ @Serial private Object readResolve() throws InvalidObjectException { - LOG.trace( "Resolving serialized factory" ); - return locateSessionFactoryOnDeserialization( getUuid(), name ); + SESSION_FACTORY_LOGGER.trace( "Resolving serialized factory" ); + return locateSessionFactoryOnDeserialization( uuid, name ); } private static SessionFactory locateSessionFactoryOnDeserialization(String uuid, String name) throws InvalidObjectException{ - final SessionFactory uuidResult = SessionFactoryRegistry.INSTANCE.getSessionFactory( uuid ); + final var uuidResult = SessionFactoryRegistry.INSTANCE.getSessionFactory( uuid ); if ( uuidResult != null ) { - if ( LOG.isTraceEnabled() ) { - LOG.trace( "Resolved factory by UUID: " + uuid ); + if ( SESSION_FACTORY_LOGGER.isTraceEnabled() ) { + SESSION_FACTORY_LOGGER.resolvedFactoryByUuid( uuid ); } return uuidResult; } @@ -1159,10 +1155,10 @@ private static SessionFactory locateSessionFactoryOnDeserialization(String uuid, // in case we were deserialized in a different JVM, look for an instance with the same name // (provided we were given a name) if ( name != null ) { - final SessionFactory namedResult = SessionFactoryRegistry.INSTANCE.getNamedSessionFactory( name ); + final var namedResult = SessionFactoryRegistry.INSTANCE.getNamedSessionFactory( name ); if ( namedResult != null ) { - if ( LOG.isTraceEnabled() ) { - LOG.trace( "Resolved factory by name: " + name ); + if ( SESSION_FACTORY_LOGGER.isTraceEnabled() ) { + SESSION_FACTORY_LOGGER.resolvedFactoryByName( name ); } return namedResult; } @@ -1193,7 +1189,7 @@ void serialize(ObjectOutputStream oos) throws IOException { * @throws IOException indicates problems reading back serial data stream */ static SessionFactoryImpl deserialize(ObjectInputStream ois) throws IOException { - LOG.trace( "Resolving factory from deserialized session" ); + SESSION_FACTORY_LOGGER.resolvingFactoryFromDeserializedSession(); final String uuid = ois.readUTF(); boolean isNamed = ois.readBoolean(); final String name = isNamed ? ois.readUTF() : null; diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java new file mode 100644 index 000000000000..f32626674198 --- /dev/null +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java @@ -0,0 +1,106 @@ +/* + * SPDX-License-Identifier: Apache-2.0 + * Copyright Red Hat Inc. and Hibernate Authors + */ +package org.hibernate.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 java.util.Map; + +import static org.jboss.logging.Logger.Level.DEBUG; +import static org.jboss.logging.Logger.Level.TRACE; +import static org.jboss.logging.Logger.Level.WARN; + +/** + * Sub-system logging related to SessionFactory and its registry + */ +@SubSystemLogging( + name = SessionFactoryLogging.NAME, + description = "Logging related to SessionFactory lifecycle, serialization, and registry/JNDI operations" +) +@MessageLogger(projectCode = "HHH") +@ValidIdRange(min = 90006001, max = 90006100) +@Internal +public interface SessionFactoryLogging extends BasicLogger { + String NAME = SubSystemLogging.BASE + ".factory"; + + SessionFactoryLogging SESSION_FACTORY_LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), SessionFactoryLogging.class, NAME ); + + // ---- SessionFactoryImpl related --------------------------------------------------------------- + + @LogMessage(level = TRACE) + @Message("Building session factory") + void buildingSessionFactory(); + + @LogMessage(level = DEBUG) + @Message(value = "Instantiating factory [%s] with settings: %s", id = 90006001) + void instantiatingFactory(String uuid, Map settings); + + @LogMessage(level = TRACE) + @Message("Eating error closing factory after failed instantiation") + void eatingErrorClosingFactoryAfterFailedInstantiation(); + + @LogMessage(level = TRACE) + @Message("Instantiated factory: %s") + void instantiatedFactory(String uuid); + + @LogMessage(level = TRACE) + @Message("Returning a Reference to the factory") + void returningReferenceToFactory(); + + @LogMessage(level = TRACE) + @Message("Already closed") + void alreadyClosed(); + + @LogMessage(level = DEBUG) + @Message(value = "Closing factory [%s]", id = 90006005) + void closingFactory(String uuid); + + @LogMessage(level = DEBUG) + @Message(value = "Serializing factory [%s]", id = 90006010) + void serializingFactory(String uuid); + + @LogMessage(level = DEBUG) + @Message(value = "Deserialized factory [%s]", id = 90006011) + void deserializedFactory(String uuid); + + @LogMessage(level = TRACE) + @Message("Serialized factory") + void serializedFactory(); + + @LogMessage(level = TRACE) + @Message("Deserializing factory") + void deserializingFactory(); + + @LogMessage(level = TRACE) + @Message("Resolving serialized factory") + void resolvingSerializedFactory(); + + @LogMessage(level = TRACE) + @Message("Resolved factory by UUID: %s") + void resolvedFactoryByUuid(String uuid); + + @LogMessage(level = TRACE) + @Message("Resolved factory by name: %s") + void resolvedFactoryByName(String name); + + @LogMessage(level = TRACE) + @Message("Resolving factory from deserialized session") + void resolvingFactoryFromDeserializedSession(); + + @LogMessage(level = WARN) + @Message(value = "Unable to construct current session context [%s]", id = 90006030) + void unableToConstructCurrentSessionContext(String sessionContextType, @Cause Throwable throwable); + +} diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistry.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistry.java index 368955923885..5513775cb218 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistry.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistry.java @@ -20,6 +20,7 @@ import org.hibernate.engine.jndi.spi.JndiService; import org.hibernate.engine.spi.SessionFactoryImplementor; +import static org.hibernate.internal.SessionFactoryRegistryMessageLogger.REGISTRY_LOGGER; import static org.hibernate.internal.util.StringHelper.isNotEmpty; /** @@ -30,7 +31,6 @@ * @author Steve Ebersole */ public class SessionFactoryRegistry { - private static final SessionFactoryRegistryMessageLogger LOG = SessionFactoryRegistryMessageLogger.INSTANCE; /** * Singleton access @@ -48,7 +48,7 @@ public class SessionFactoryRegistry { private final ConcurrentHashMap nameUuidXref = new ConcurrentHashMap<>(); private SessionFactoryRegistry() { - LOG.tracef( "Initializing SessionFactoryRegistry @%s", hashCode() ); + REGISTRY_LOGGER.initializingSessionFactoryRegistry( hashCode() ); } /** @@ -70,14 +70,14 @@ public void addSessionFactory( throw new IllegalArgumentException( "SessionFactory UUID cannot be null" ); } - LOG.registeringSessionFactory( uuid, name == null ? "" : name ); + REGISTRY_LOGGER.registeringSessionFactory( uuid, name == null ? "" : name ); sessionFactoryMap.put( uuid, instance ); if ( name != null ) { nameUuidXref.put( name, uuid ); } if ( jndiName == null ) { - LOG.notBindingSessionFactory(); + REGISTRY_LOGGER.notBindingSessionFactory(); return; } @@ -86,21 +86,21 @@ public void addSessionFactory( private void bindToJndi(String jndiName, SessionFactoryImplementor instance, JndiService jndiService) { try { - LOG.attemptingToBindFactoryToJndi( jndiName ); + REGISTRY_LOGGER.attemptingToBindFactoryToJndi( jndiName ); jndiService.bind( jndiName, instance ); - LOG.factoryBoundToJndiName( jndiName ); + REGISTRY_LOGGER.factoryBoundToJndiName( jndiName ); try { jndiService.addListener( jndiName, listener ); } catch (Exception e) { - LOG.couldNotBindJndiListener(); + REGISTRY_LOGGER.couldNotBindJndiListener(); } } catch (JndiNameException e) { - LOG.invalidJndiName( jndiName, e ); + REGISTRY_LOGGER.invalidJndiName( jndiName, e ); } catch (JndiException e) { - LOG.unableToBindFactoryToJndi( e ); + REGISTRY_LOGGER.unableToBindFactoryToJndi( e ); } } @@ -123,15 +123,15 @@ public void removeSessionFactory( if ( jndiName != null ) { try { - LOG.attemptingToUnbindFactoryFromJndi( jndiName ); + REGISTRY_LOGGER.attemptingToUnbindFactoryFromJndi( jndiName ); jndiService.unbind( jndiName ); - LOG.factoryUnboundFromJndiName( jndiName ); + REGISTRY_LOGGER.factoryUnboundFromJndiName( jndiName ); } catch (JndiNameException e) { - LOG.invalidJndiName( jndiName, e ); + REGISTRY_LOGGER.invalidJndiName( jndiName, e ); } catch (JndiException e) { - LOG.unableToUnbindFactoryFromJndi( e ); + REGISTRY_LOGGER.unableToUnbindFactoryFromJndi( e ); } } @@ -146,24 +146,24 @@ public void removeSessionFactory( * @return The SessionFactory */ public SessionFactoryImplementor getNamedSessionFactory(String name) { - LOG.tracef( "Lookup: name=%s", name ); + REGISTRY_LOGGER.jndiLookupByName( name ); final String uuid = nameUuidXref.get( name ); // protect against NPE -- see HHH-8428 return uuid == null ? null : getSessionFactory( uuid ); } public SessionFactoryImplementor getSessionFactory(String uuid) { - LOG.tracef( "Lookup: uid=%s", uuid ); - final SessionFactoryImplementor sessionFactory = sessionFactoryMap.get( uuid ); - if ( sessionFactory == null && LOG.isDebugEnabled() ) { - LOG.debugf( "Not found: %s", uuid ); - LOG.debug( sessionFactoryMap.toString() ); + REGISTRY_LOGGER.jndiLookupByUuid( uuid ); + final var sessionFactory = sessionFactoryMap.get( uuid ); + if ( sessionFactory == null && REGISTRY_LOGGER.isDebugEnabled() ) { + REGISTRY_LOGGER.debugf( "Not found [%s]", uuid ); + REGISTRY_LOGGER.debug( sessionFactoryMap.toString() ); } return sessionFactory; } public SessionFactoryImplementor findSessionFactory(String uuid, String name) { - final SessionFactoryImplementor sessionFactory = getSessionFactory( uuid ); + final var sessionFactory = getSessionFactory( uuid ); return sessionFactory == null && isNotEmpty( name ) ? getNamedSessionFactory( name ) : sessionFactory; @@ -179,7 +179,7 @@ public boolean hasRegistrations() { public void clearRegistrations() { nameUuidXref.clear(); - for ( SessionFactory factory : sessionFactoryMap.values() ) { + for ( var factory : sessionFactoryMap.values() ) { try { factory.close(); } @@ -196,15 +196,15 @@ public void clearRegistrations() { private final NamespaceChangeListener listener = new NamespaceChangeListener() { @Override public void objectAdded(NamingEvent evt) { - if ( LOG.isDebugEnabled() ) { - LOG.factoryBoundToJndi( evt.getNewBinding().getName() ); + if ( REGISTRY_LOGGER.isDebugEnabled() ) { + REGISTRY_LOGGER.factoryBoundToJndi( evt.getNewBinding().getName() ); } } @Override public void objectRemoved(NamingEvent evt) { final String jndiName = evt.getOldBinding().getName(); - LOG.factoryUnboundFromName( jndiName ); + REGISTRY_LOGGER.factoryUnboundFromName( jndiName ); final String uuid = nameUuidXref.remove( jndiName ); //noinspection StatementWithEmptyBody @@ -217,26 +217,27 @@ public void objectRemoved(NamingEvent evt) { } @Override - public void objectRenamed(NamingEvent evt) { - final String oldJndiName = evt.getOldBinding().getName(); - final String newJndiName = evt.getNewBinding().getName(); - LOG.factoryJndiRename( oldJndiName, newJndiName ); + public void objectRenamed(NamingEvent namingEvent) { + final String oldJndiName = namingEvent.getOldBinding().getName(); + final String newJndiName = namingEvent.getNewBinding().getName(); + REGISTRY_LOGGER.factoryJndiRename( oldJndiName, newJndiName ); final String uuid = nameUuidXref.remove( oldJndiName ); nameUuidXref.put( newJndiName, uuid ); } @Override - public void namingExceptionThrown(NamingExceptionEvent evt) { - LOG.namingExceptionAccessingFactory( evt.getException() ); + public void namingExceptionThrown(NamingExceptionEvent namingExceptionEvent) { + REGISTRY_LOGGER.namingExceptionAccessingFactory( namingExceptionEvent.getException() ); } }; public static class ObjectFactoryImpl implements ObjectFactory { @Override public Object getObjectInstance(Object reference, Name name, Context nameCtx, Hashtable environment) { - LOG.tracef( "JNDI lookup: %s", name ); - final String uuid = (String) ( (Reference) reference ).get( 0 ).getContent(); - LOG.tracef( "Resolved to UUID = %s", uuid ); + REGISTRY_LOGGER.jndiLookupByName( String.valueOf( name ) ); + final var refAddr = ((Reference) reference).get( 0 ); + final String uuid = (String) refAddr.getContent(); + REGISTRY_LOGGER.resolvedToUuid( uuid ); return INSTANCE.getSessionFactory( uuid ); } } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistryMessageLogger.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistryMessageLogger.java index 5a4b65f9aaf0..96835db000ea 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistryMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryRegistryMessageLogger.java @@ -35,15 +35,19 @@ public interface SessionFactoryRegistryMessageLogger extends BasicLogger { String LOGGER_NAME = SubSystemLogging.BASE + ".factoryRegistry"; - SessionFactoryRegistryMessageLogger INSTANCE = + SessionFactoryRegistryMessageLogger REGISTRY_LOGGER = getMessageLogger( MethodHandles.lookup(), SessionFactoryRegistryMessageLogger.class, LOGGER_NAME ); + @LogMessage(level = TRACE) + @Message("Initializing SessionFactoryRegistry @%s") + + void initializingSessionFactoryRegistry(int hashCode); @LogMessage(level = WARN) @Message(value = "Naming exception occurred accessing factory: %s", id = 20178) void namingExceptionAccessingFactory(NamingException exception); @LogMessage(level = INFO) - @Message(value = "Bound factory to JNDI name: %s", id = 20194) + @Message(value = "Bound factory to JNDI name: '%s'", id = 20194) void factoryBoundToJndiName(String name); @LogMessage(level = INFO) @@ -55,7 +59,7 @@ public interface SessionFactoryRegistryMessageLogger extends BasicLogger { void couldNotBindJndiListener(); @LogMessage(level = ERROR) - @Message(value = "Invalid JNDI name: %s", id = 20135) + @Message(value = "Invalid JNDI name: '%s'", id = 20135) void invalidJndiName(String name, @Cause JndiNameException e); @LogMessage(level = WARN) @@ -63,11 +67,11 @@ public interface SessionFactoryRegistryMessageLogger extends BasicLogger { void unableToBindFactoryToJndi(@Cause JndiException e); @LogMessage(level = INFO) - @Message(value = "Unbound factory from JNDI name: %s", id = 20197) + @Message(value = "Unbound factory from JNDI name: '%s'", id = 20197) void factoryUnboundFromJndiName(String name); @LogMessage(level = INFO) - @Message(value = "A factory was unbound from name: %s", id = 20198) + @Message(value = "A factory was unbound from name: '%s'", id = 20198) void factoryUnboundFromName(String name); @LogMessage(level = WARN) @@ -75,7 +79,7 @@ public interface SessionFactoryRegistryMessageLogger extends BasicLogger { void unableToUnbindFactoryFromJndi(@Cause JndiException e); @LogMessage(level = DEBUG) - @Message(value = "Registering SessionFactory: %s (%s)", id = 20384) + @Message(value = "Registering SessionFactory [%s] (%s)", id = 20384) void registeringSessionFactory(String uuid, String name); @LogMessage(level = DEBUG) @@ -87,10 +91,22 @@ public interface SessionFactoryRegistryMessageLogger extends BasicLogger { void attemptingToUnbindFactoryFromJndi(String name); @LogMessage(level = DEBUG) - @Message(value = "A SessionFactory was successfully bound to name: %s", id = 20282) + @Message(value = "A SessionFactory was successfully bound to name '%s'", id = 20282) void factoryBoundToJndi(String name); @LogMessage(level = TRACE) @Message(value = "Not binding SessionFactory to JNDI, no JNDI name configured", id = 20385) void notBindingSessionFactory(); + + @LogMessage(level = TRACE) + @Message("JNDI lookup by name '%s'") + void jndiLookupByName(String name); + + @LogMessage(level = TRACE) + @Message("JNDI lookup by UUID [%s]") + void jndiLookupByUuid(String uuid); + + @LogMessage(level = TRACE) + @Message("Resolved to UUID [%s]") + void resolvedToUuid(String uuid); } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java index 5d87d63179dc..5eff81e6b8fd 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java @@ -28,7 +28,7 @@ */ @SubSystemLogging( name = SessionLogging.NAME, - description = "Logging related to Session / StatelessSession lifecycle and operations" + description = "Logging related to session lifecycle and operations" ) @MessageLogger(projectCode = "HHH") @ValidIdRange(min = 90006101, max = 90006500) diff --git a/hibernate-core/src/main/java/org/hibernate/internal/util/xml/DTDEntityResolver.java b/hibernate-core/src/main/java/org/hibernate/internal/util/xml/DTDEntityResolver.java index 44a5637a8ab2..56be4d59d012 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/util/xml/DTDEntityResolver.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/util/xml/DTDEntityResolver.java @@ -53,7 +53,7 @@ public InputSource resolveEntity(String publicId, String systemId) { if ( systemId != null ) { LOG.debugf( "Trying to resolve system-id [%s]", systemId ); if ( systemId.startsWith( HIBERNATE_NAMESPACE ) ) { - LOG.debug( "Recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/" ); + LOG.debug( "Recognized Hibernate namespace; attempting to resolve on classpath under org/hibernate/" ); source = resolveOnClassPath( publicId, systemId, HIBERNATE_NAMESPACE ); } else if ( systemId.startsWith( OLD_HIBERNATE_NAMESPACE ) ) { From 1f3351a8cd657b66cf8c8b9fd7ea952350ba1cd8 Mon Sep 17 00:00:00 2001 From: Gavin King Date: Sat, 13 Sep 2025 12:58:29 +0200 Subject: [PATCH 3/4] move more logging to SessionLogging --- .../AbstractSharedSessionContract.java | 24 ++++++++----------- .../hibernate/internal/CoreMessageLogger.java | 8 ------- .../internal/SessionFactoryImpl.java | 2 +- .../org/hibernate/internal/SessionImpl.java | 13 ++++------ .../hibernate/internal/SessionLogging.java | 18 ++++++++++++++ 5 files changed, 33 insertions(+), 32 deletions(-) diff --git a/hibernate-core/src/main/java/org/hibernate/internal/AbstractSharedSessionContract.java b/hibernate-core/src/main/java/org/hibernate/internal/AbstractSharedSessionContract.java index 251e04f1b21b..822b287dc180 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/AbstractSharedSessionContract.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/AbstractSharedSessionContract.java @@ -120,6 +120,7 @@ import static java.lang.Boolean.TRUE; import static org.hibernate.boot.model.naming.Identifier.toIdentifier; +import static org.hibernate.internal.SessionLogging.SESSION_LOGGER; import static org.hibernate.internal.util.StringHelper.isEmpty; import static org.hibernate.query.sqm.internal.SqmUtil.verifyIsSelectStatement; @@ -139,7 +140,6 @@ * @author Steve Ebersole */ public abstract class AbstractSharedSessionContract implements SharedSessionContractImplementor { - private static final CoreMessageLogger LOG = CoreLogging.messageLogger( SessionImpl.class ); private transient SessionFactoryImpl factory; private transient SessionFactoryOptions factoryOptions; @@ -282,13 +282,12 @@ protected final void setUpMultitenancy(SessionFactoryImplementor factory, LoadQu } private void logInconsistentOptions(SharedSessionCreationOptions sharedOptions) { + // TODO: these should probable be exceptions! if ( sharedOptions.shouldAutoJoinTransactions() ) { - LOG.debug( "Session creation specified 'autoJoinTransactions', which is invalid in conjunction " + - "with sharing JDBC connection between sessions; ignoring" ); + SESSION_LOGGER.invalidAutoJoinTransactionsWithSharedConnection(); } if ( sharedOptions.getPhysicalConnectionHandlingMode() != connectionHandlingMode ) { - LOG.debug( "Session creation specified 'PhysicalConnectionHandlingMode' which is invalid in conjunction " + - "with sharing JDBC connection between sessions; ignoring" ); + SESSION_LOGGER.invalidPhysicalConnectionHandlingModeWithSharedConnection(); } } @@ -357,15 +356,17 @@ void afterTransactionBeginEvents() { } void beforeTransactionCompletionEvents() { + SESSION_LOGGER.beforeTransactionCompletion(); try { getInterceptor().beforeTransactionCompletion( getTransactionIfAccessible() ); } catch (Throwable t) { - LOG.exceptionInBeforeTransactionCompletionInterceptor( t ); + SESSION_LOGGER.exceptionInBeforeTransactionCompletionInterceptor( t ); } } void afterTransactionCompletionEvents(boolean successful) { + SESSION_LOGGER.afterTransactionCompletion( successful, false ); getEventListenerManager().transactionCompletion(successful); final var statistics = getFactory().getStatistics(); @@ -377,7 +378,7 @@ void afterTransactionCompletionEvents(boolean successful) { getInterceptor().afterTransactionCompletion( getTransactionIfAccessible() ); } catch (Throwable t) { - LOG.exceptionInAfterTransactionCompletionInterceptor( t ); + SESSION_LOGGER.exceptionInAfterTransactionCompletionInterceptor( t ); } } @@ -1686,9 +1687,7 @@ public SessionAssociationMarkers getSessionAssociationMarkers() { @Serial private void writeObject(ObjectOutputStream oos) throws IOException { - if ( LOG.isTraceEnabled() ) { - LOG.trace( "Serializing " + getClass().getSimpleName() + " [" ); - } + SESSION_LOGGER.serializingSession( getSessionIdentifier() ); if ( !jdbcCoordinator.isReadyForSerialization() ) { @@ -1721,13 +1720,10 @@ private void writeObject(ObjectOutputStream oos) throws IOException { @Serial private void readObject(ObjectInputStream ois) throws IOException, ClassNotFoundException, SQLException { - if ( LOG.isTraceEnabled() ) { - LOG.trace( "Deserializing " + getClass().getSimpleName() ); - } - // ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // Step 1 :: read back non-transient state... ois.defaultReadObject(); + SESSION_LOGGER.deserializingSession( getSessionIdentifier() ); // ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // Step 2 :: read back transient state... 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 4bfd3f261f04..f3394dde6168 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java @@ -95,14 +95,6 @@ public interface CoreMessageLogger extends BasicLogger { id = 84) void entityMappedAsNonAbstract(String name); - @LogMessage(level = ERROR) - @Message(value = "Exception in interceptor afterTransactionCompletion()", id = 87) - void exceptionInAfterTransactionCompletionInterceptor(@Cause Throwable e); - - @LogMessage(level = ERROR) - @Message(value = "Exception in interceptor beforeTransactionCompletion()", id = 88) - void exceptionInBeforeTransactionCompletionInterceptor(@Cause Throwable e); - @LogMessage(level = INFO) @Message(value = "Sub-resolver threw unexpected exception, continuing to next: %s", id = 89) void exceptionInSubResolver(String message); diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java index f77ba2f5df76..76fd82e06b0c 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java @@ -211,7 +211,7 @@ public SessionFactoryImpl( final MetadataImplementor bootMetamodel, final SessionFactoryOptions options, final BootstrapContext bootstrapContext) { -SESSION_FACTORY_LOGGER.buildingSessionFactory(); + SESSION_FACTORY_LOGGER.buildingSessionFactory(); typeConfiguration = bootstrapContext.getTypeConfiguration(); sessionFactoryOptions = options; diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java index 80eab2560ada..057257ee6942 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionImpl.java @@ -358,7 +358,7 @@ public void close() { if ( getSessionFactoryOptions().getJpaCompliance().isJpaClosedComplianceEnabled() ) { throw new IllegalStateException( "EntityManager was already closed" ); } - SESSION_LOGGER.alreadyClosed(); + SESSION_LOGGER.alreadyClosed(); } else { closeWithoutOpenChecks(); @@ -483,7 +483,7 @@ else if ( isClosed() ) { } private void managedClose() { - SESSION_LOGGER.automaticallyClosingSession(); + SESSION_LOGGER.automaticallyClosingSession(); closeWithoutOpenChecks(); } @@ -841,10 +841,7 @@ public void delete(String entityName, Object object, boolean isCascadeDeleteEnab public void removeOrphanBeforeUpdates(String entityName, Object child) { // TODO: The removeOrphan concept is a temporary "hack" for HHH-6484. // This should be removed once action/task ordering is improved. - final boolean traceEnabled = SESSION_LOGGER.isTraceEnabled(); - if ( traceEnabled ) { - logRemoveOrphanBeforeUpdates( "begin", entityName, child ); - } + logRemoveOrphanBeforeUpdates( "begin", entityName, child ); persistenceContext.beginRemoveOrphanBeforeUpdates(); try { checkOpenOrWaitingForAutoClose(); @@ -852,9 +849,7 @@ public void removeOrphanBeforeUpdates(String entityName, Object child) { } finally { persistenceContext.endRemoveOrphanBeforeUpdates(); - if ( traceEnabled ) { - logRemoveOrphanBeforeUpdates( "end", entityName, child ); - } + logRemoveOrphanBeforeUpdates( "end", entityName, child ); } } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java index 5eff81e6b8fd..53df60be17d9 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java @@ -38,6 +38,16 @@ public interface SessionLogging extends BasicLogger { SessionLogging SESSION_LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), SessionLogging.class, NAME ); + @LogMessage(level = DEBUG) + @Message("Session creation specified 'autoJoinTransactions', " + + "which is invalid in conjunction with sharing JDBC connection between sessions; ignoring") + void invalidAutoJoinTransactionsWithSharedConnection(); + + @LogMessage(level = DEBUG) + @Message("Session creation specified a 'PhysicalConnectionHandlingMode', " + + "which is invalid in conjunction with sharing JDBC connection between sessions; ignoring") + void invalidPhysicalConnectionHandlingModeWithSharedConnection(); + @LogMessage(level = TRACE) @Message("Opened Session [%s] at timestamp: %s") void openedSession(UUID sessionIdentifier, long timestamp); @@ -118,6 +128,14 @@ public interface SessionLogging extends BasicLogger { @Message("Deserializing Session [%s]") void deserializingSession(UUID sessionIdentifier); + @LogMessage(level = ERROR) + @Message(id = 90006106, value = "Exception in interceptor beforeTransactionCompletion()") + void exceptionInBeforeTransactionCompletionInterceptor(@Cause Throwable e); + + @LogMessage(level = ERROR) + @Message(id = 90006107, value = "Exception in interceptor afterTransactionCompletion()") + void exceptionInAfterTransactionCompletionInterceptor(@Cause Throwable e); + // StatelessSession-specific @LogMessage(level = TRACE) From 17bb300781c063dcc160579b00807be3e35c3db6 Mon Sep 17 00:00:00 2001 From: Gavin King Date: Sat, 13 Sep 2025 13:16:21 +0200 Subject: [PATCH 4/4] small fixes to new session/factory logging --- .../hibernate/internal/SessionFactoryImpl.java | 2 +- .../internal/SessionFactoryLogging.java | 18 +++++++++--------- .../org/hibernate/internal/SessionLogging.java | 16 ++++++++-------- 3 files changed, 18 insertions(+), 18 deletions(-) diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java index 76fd82e06b0c..2ed74965ce80 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java @@ -1138,7 +1138,7 @@ private void readObject(ObjectInputStream in) throws IOException, ClassNotFoundE */ @Serial private Object readResolve() throws InvalidObjectException { - SESSION_FACTORY_LOGGER.trace( "Resolving serialized factory" ); + SESSION_FACTORY_LOGGER.resolvingSerializedFactory(); return locateSessionFactoryOnDeserialization( uuid, name ); } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java index f32626674198..5697463fdfe2 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryLogging.java @@ -27,10 +27,10 @@ */ @SubSystemLogging( name = SessionFactoryLogging.NAME, - description = "Logging related to SessionFactory lifecycle, serialization, and registry/JNDI operations" + description = "Logging related to SessionFactory lifecycle and serialization" ) @MessageLogger(projectCode = "HHH") -@ValidIdRange(min = 90006001, max = 90006100) +@ValidIdRange(min = 90020001, max = 90030000) @Internal public interface SessionFactoryLogging extends BasicLogger { String NAME = SubSystemLogging.BASE + ".factory"; @@ -44,7 +44,7 @@ public interface SessionFactoryLogging extends BasicLogger { void buildingSessionFactory(); @LogMessage(level = DEBUG) - @Message(value = "Instantiating factory [%s] with settings: %s", id = 90006001) + @Message(value = "Instantiating factory [%s] with settings: %s", id = 90020001) void instantiatingFactory(String uuid, Map settings); @LogMessage(level = TRACE) @@ -64,15 +64,15 @@ public interface SessionFactoryLogging extends BasicLogger { void alreadyClosed(); @LogMessage(level = DEBUG) - @Message(value = "Closing factory [%s]", id = 90006005) + @Message(value = "Closing factory [%s]", id = 90020005) void closingFactory(String uuid); @LogMessage(level = DEBUG) - @Message(value = "Serializing factory [%s]", id = 90006010) + @Message(value = "Serializing factory [%s]", id = 90020010) void serializingFactory(String uuid); @LogMessage(level = DEBUG) - @Message(value = "Deserialized factory [%s]", id = 90006011) + @Message(value = "Deserialized factory [%s]", id = 90020011) void deserializedFactory(String uuid); @LogMessage(level = TRACE) @@ -88,11 +88,11 @@ public interface SessionFactoryLogging extends BasicLogger { void resolvingSerializedFactory(); @LogMessage(level = TRACE) - @Message("Resolved factory by UUID: %s") + @Message("Resolved factory by UUID: [%s]") void resolvedFactoryByUuid(String uuid); @LogMessage(level = TRACE) - @Message("Resolved factory by name: %s") + @Message("Resolved factory by name: '%s'") void resolvedFactoryByName(String name); @LogMessage(level = TRACE) @@ -100,7 +100,7 @@ public interface SessionFactoryLogging extends BasicLogger { void resolvingFactoryFromDeserializedSession(); @LogMessage(level = WARN) - @Message(value = "Unable to construct current session context [%s]", id = 90006030) + @Message(value = "Unable to construct current session context [%s]", id = 90020030) void unableToConstructCurrentSessionContext(String sessionContextType, @Cause Throwable throwable); } diff --git a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java index 53df60be17d9..813f184a9635 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/SessionLogging.java @@ -31,7 +31,7 @@ description = "Logging related to session lifecycle and operations" ) @MessageLogger(projectCode = "HHH") -@ValidIdRange(min = 90006101, max = 90006500) +@ValidIdRange(min = 90010001, max = 90020000) @Internal public interface SessionLogging extends BasicLogger { String NAME = SubSystemLogging.BASE + ".session"; @@ -61,7 +61,7 @@ public interface SessionLogging extends BasicLogger { void closingSession(UUID sessionIdentifier); @LogMessage(level = WARN) - @Message(id = 90006101, value = "Closing shared session with unprocessed transaction completion actions") + @Message(id = 90010101, value = "Closing shared session with unprocessed transaction completion actions") void closingSharedSessionWithUnprocessedTxCompletions(); @LogMessage(level = TRACE) @@ -105,19 +105,19 @@ public interface SessionLogging extends BasicLogger { void afterTransactionCompletion(boolean successful, boolean delayed); @LogMessage(level = ERROR) - @Message(id = 90006102, value = "JDBC exception executing SQL; transaction rolled back") + @Message(id = 90010102, value = "JDBC exception executing SQL; transaction rolled back") void jdbcExceptionThrownWithTransactionRolledBack(@Cause Exception e); @LogMessage(level = DEBUG) - @Message(id = 90006103, value = "Ignoring EntityNotFoundException for '%s.%s'") + @Message(id = 90010103, value = "Ignoring EntityNotFoundException for '%s.%s'") void ignoringEntityNotFound(String entityName, Object id); @LogMessage(level = WARN) - @Message(id = 90006104, value = "Property '%s' is not serializable, value won't be set") + @Message(id = 90010104, value = "Property '%s' is not serializable, value won't be set") void nonSerializableProperty(String propertyName); @LogMessage(level = WARN) - @Message(id = 90006105, value = "Property having key null is illegal, value won't be set") + @Message(id = 90010105, value = "Property having key null is illegal, value won't be set") void nullPropertyKey(); @LogMessage(level = TRACE) @@ -129,11 +129,11 @@ public interface SessionLogging extends BasicLogger { void deserializingSession(UUID sessionIdentifier); @LogMessage(level = ERROR) - @Message(id = 90006106, value = "Exception in interceptor beforeTransactionCompletion()") + @Message(id = 90010106, value = "Exception in interceptor beforeTransactionCompletion()") void exceptionInBeforeTransactionCompletionInterceptor(@Cause Throwable e); @LogMessage(level = ERROR) - @Message(id = 90006107, value = "Exception in interceptor afterTransactionCompletion()") + @Message(id = 90010107, value = "Exception in interceptor afterTransactionCompletion()") void exceptionInAfterTransactionCompletionInterceptor(@Cause Throwable e); // StatelessSession-specific