More work on logging

hibernate-core/src/main/java/org/hibernate/action/internal/UnresolvedEntityInsertActions.java

@@ -7,7 +7,6 @@
 import java.io.IOException;
 import java.io.ObjectInputStream;
 import java.io.ObjectOutputStream;
-import java.lang.invoke.MethodHandles;
 import java.util.IdentityHashMap;
 import java.util.Map;
 import java.util.Set;
@@ -21,10 +20,10 @@
 import org.hibernate.engine.spi.SharedSessionContractImplementor;
 import org.hibernate.engine.spi.Status;
 import org.hibernate.event.spi.EventSource;
+import org.hibernate.internal.CoreLogging;
 import org.hibernate.internal.CoreMessageLogger;
 import org.hibernate.internal.util.collections.IdentitySet;
 
-import org.jboss.logging.Logger;
 
 import static java.util.Collections.emptySet;
 import static org.hibernate.pretty.MessageHelper.infoString;
@@ -43,11 +42,7 @@
  * @author Gail Badner
  */
 public class UnresolvedEntityInsertActions {
-	private static final CoreMessageLogger LOG = Logger.getMessageLogger(
-			MethodHandles.lookup(),
-			CoreMessageLogger.class,
-			UnresolvedEntityInsertActions.class.getName()
-	);
+	private static final CoreMessageLogger LOG = CoreLogging.messageLogger( UnresolvedEntityInsertActions.class );
 
 	private static final int INIT_SIZE = 5;
 

hibernate-core/src/main/java/org/hibernate/boot/model/convert/internal/AttributeConverterManager.java

@@ -49,7 +49,7 @@ public RegisteredConversion findRegisteredConversion(Class<?> domainType) {
 
 	public void addConverter(ConverterDescriptor<?,?> descriptor) {
 		if ( log.isTraceEnabled() ) {
-			log.tracef( "Starting AttributeConverterManager#addConverter : `%s`",
+			log.tracef( "Registering AttributeConverter '%s'",
 					descriptor.getAttributeConverterClass().getName() );
 		}
 
@@ -59,7 +59,7 @@ public void addConverter(ConverterDescriptor<?,?> descriptor) {
 			if ( registeredConversion != null ) {
 				// we can skip registering the converter, the RegisteredConversion will always take precedence
 				if ( log.isDebugEnabled() ) {
-					log.debugf( "Skipping registration of discovered AttributeConverter `%s` for auto-apply",
+					log.debugf( "Skipping registration of discovered AttributeConverter '%s' for auto-apply",
 							descriptor.getAttributeConverterClass().getName() );
 				}
 				return;
@@ -114,7 +114,7 @@ public void addRegistration(RegisteredConversion conversion, BootstrapContext co
 		if ( attributeConverterDescriptorsByClass != null ) {
 			final var removed = attributeConverterDescriptorsByClass.remove( conversion.getConverterType() );
 			if ( removed != null && log.isDebugEnabled() ) {
-				log.debugf( "Removed potentially auto-applicable converter `%s` due to @ConverterRegistration",
+				log.debugf( "Removed potentially auto-applicable converter '%s' due to @ConverterRegistration",
 						removed.getAttributeConverterClass().getName() );
 			}
 		}

hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java

@@ -21,6 +21,7 @@
 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;
 import static org.jboss.logging.Logger.Level.WARN;
 
@@ -139,7 +140,27 @@ public interface JdbcLogging extends BasicLogger {
 			id = 100018)
 	void logDriverInfo(String name, String version, int major, int minor, int jdbcMajor, int jdbcMinor);
 
+	@LogMessage(level = TRACE)
+	@Message(value = "Unable to reset connection back to auto-commit", id = 100019)
+	void unableToResetAutoCommit();
+
+	@LogMessage(level = INFO)
+	@Message(value = "Unable to release isolated connection", id = 100020)
+	void unableToReleaseIsolatedConnection(@Cause Throwable ignored);
+
+	@LogMessage(level = INFO)
+	@Message(value = "Unable to roll back isolated connection on exception ", id = 100021)
+	void unableToRollBackIsolatedConnection(@Cause Exception ignored);
+
 	@LogMessage(level = WARN)
-	@Message(value = "Called joinTransaction() on a non-JTA EntityManager (ignoring)", id = 100020)
+	@Message(value = "Called joinTransaction() on a non-JTA EntityManager (ignoring)", id = 100025)
 	void callingJoinTransactionOnNonJtaEntityManager();
+
+	@LogMessage(level = TRACE)
+	@Message(value = "Current timestamp retrieved from database: %s (nanos=%s, time=%s)", id = 100031)
+	void currentTimestampRetrievedFromDatabase(Object timestamp, int nanos, long time);
+
+	@LogMessage(level = TRACE)
+	@Message(value = "Sequence value retrieved from database: %s", id = 100032)
+	void sequenceValueRetrievedFromDatabase(Number sequenceValue);
 }

hibernate-core/src/main/java/org/hibernate/engine/spi/CollectionEntry.java

@@ -261,7 +261,7 @@ public void afterAction(PersistentCollection<?> collection) {
 	 * Reset the stored snapshot for both the persistent collection and this collection entry.
 	 * Used during the merge of detached collections.
 	 *
-	 * @param collection the persistentcollection to be updated
+	 * @param collection the persistent collection to be updated
 	 * @param storedSnapshot the new stored snapshot
 	 */
 	public void resetStoredSnapshot(PersistentCollection<?> collection, Serializable storedSnapshot) {

hibernate-core/src/main/java/org/hibernate/generator/internal/CurrentTimestampGeneration.java

@@ -216,24 +216,23 @@ static CurrentTimestampGeneratorDelegate getGeneratorDelegate(
 						context.getDatabase().getDialect(),
 						basicValue.getMetadata()
 				);
-				final Clock baseClock = context.getServiceRegistry()
-						.requireService( ConfigurationService.class )
-						.getSetting( CLOCK_SETTING_NAME, value -> (Clock) value );
+				final Clock baseClock =
+						context.getServiceRegistry().requireService( ConfigurationService.class )
+								.getSetting( CLOCK_SETTING_NAME, value -> (Clock) value );
 				final Key key = new Key( propertyType, baseClock, size.getPrecision() == null ? 0 : size.getPrecision() );
 				final CurrentTimestampGeneratorDelegate delegate = GENERATOR_DELEGATES.get( key );
 				if ( delegate != null ) {
 					return delegate;
 				}
-				final BiFunction<@Nullable Clock, Integer, CurrentTimestampGeneratorDelegate> producer = GENERATOR_PRODUCERS.get( key.clazz );
+				final var producer = GENERATOR_PRODUCERS.get( key.clazz );
 				if ( producer == null ) {
 					return null;
 				}
-				final CurrentTimestampGeneratorDelegate generatorDelegate = producer.apply( key.clock, key.precision );
-				final CurrentTimestampGeneratorDelegate old = GENERATOR_DELEGATES.putIfAbsent(
-						key,
-						generatorDelegate
-				);
-				return old != null ? old : generatorDelegate;
+				else {
+					final var generatorDelegate = producer.apply( key.clock, key.precision );
+					final var old = GENERATOR_DELEGATES.putIfAbsent( key, generatorDelegate );
+					return old != null ? old : generatorDelegate;
+				}
 			case DB:
 				return null;
 			default:
@@ -280,40 +279,6 @@ interface CurrentTimestampGeneratorDelegate {
 		Object generate();
 	}
 
-	private static class Key {
-		private final Class<?> clazz;
-		private final @Nullable Clock clock;
-		private final int precision;
-
-		public Key(Class<?> clazz, @Nullable Clock clock, int precision) {
-			this.clazz = clazz;
-			this.clock = clock;
-			this.precision = precision;
-		}
-
-		@Override
-		public boolean equals(Object o) {
-			if ( this == o ) {
-				return true;
-			}
-			if ( o == null || getClass() != o.getClass() ) {
-				return false;
-			}
-
-			Key key = (Key) o;
-
-			if ( precision != key.precision ) {
-				return false;
-			}
-			return clock == key.clock && clazz.equals( key.clazz );
-		}
-
-		@Override
-		public int hashCode() {
-			int result = clazz.hashCode();
-			result = 31 * result + ( clock == null ? 0 : clock.hashCode() );
-			result = 31 * result + precision;
-			return result;
-		}
+	private record Key(Class<?> clazz, @Nullable Clock clock, int precision) {
 	}
 }

hibernate-core/src/main/java/org/hibernate/generator/internal/SourceGeneration.java

@@ -15,12 +15,9 @@
 import org.hibernate.generator.EventTypeSets;
 import org.hibernate.generator.GeneratorCreationContext;
 import org.hibernate.generator.BeforeExecutionGenerator;
-import org.hibernate.internal.CoreMessageLogger;
 import org.hibernate.type.descriptor.java.JavaType;
 
-import org.jboss.logging.Logger;
 
-import java.lang.invoke.MethodHandles;
 import java.lang.reflect.Member;
 import java.sql.CallableStatement;
 import java.sql.PreparedStatement;
@@ -30,6 +27,7 @@
 import java.util.EnumSet;
 
 import static java.sql.Types.TIMESTAMP;
+import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER;
 import static org.hibernate.generator.EventTypeSets.INSERT_AND_UPDATE;
 
 /**
@@ -52,12 +50,6 @@
 @Internal
 public class SourceGeneration implements BeforeExecutionGenerator {
 
-	private static final CoreMessageLogger log = Logger.getMessageLogger(
-			MethodHandles.lookup(),
-			CoreMessageLogger.class,
-			SourceGeneration.class.getName()
-	);
-
 	private final JavaType<?> propertyType;
 	private final CurrentTimestampGeneration.CurrentTimestampGeneratorDelegate valueGenerator;
 
@@ -97,7 +89,9 @@ private Timestamp getCurrentTimestamp(SharedSessionContractImplementor session)
 			final Timestamp ts = callable
 					? extractCalledResult( statement, coordinator, timestampSelectString )
 					: extractResult( statement, coordinator, timestampSelectString );
-			logResult( ts );
+			if ( JDBC_MESSAGE_LOGGER.isTraceEnabled() ) {
+				JDBC_MESSAGE_LOGGER.currentTimestampRetrievedFromDatabase( ts, ts.getNanos(), ts.getTime() );
+			}
 			return ts;
 		}
 		catch (SQLException e) {
@@ -130,14 +124,4 @@ private static Timestamp extractCalledResult(PreparedStatement statement, JdbcCo
 		return callable.getTimestamp( 1 );
 	}
 
-	private static void logResult(Timestamp ts) {
-		if ( log.isTraceEnabled() ) {
-			log.tracev(
-					"Current timestamp retrieved from db : {0} (nanos={1}, time={2})",
-					ts,
-					ts.getNanos(),
-					ts.getTime()
-			);
-		}
-	}
 }

hibernate-core/src/main/java/org/hibernate/id/enhanced/HiLoOptimizer.java

@@ -75,7 +75,8 @@ public HiLoOptimizer(Class<?> returnClass, int incrementSize) {
 			throw new HibernateException( "increment size cannot be less than 1" );
 		}
 		if ( log.isTraceEnabled() ) {
-			log.tracev( "Creating hilo optimizer with [incrementSize={0}; returnClass={1}]", incrementSize, returnClass.getName() );
+			log.tracev( "Creating hilo optimizer with [incrementSize={0}; returnClass={1}]",
+					incrementSize, returnClass.getName() );
 		}
 	}
 

hibernate-core/src/main/java/org/hibernate/id/enhanced/LegacyHiLoAlgorithmOptimizer.java

@@ -47,7 +47,8 @@ public LegacyHiLoAlgorithmOptimizer(Class<?> returnClass, int incrementSize) {
 			throw new HibernateException( "increment size cannot be less than 1" );
 		}
 		if ( log.isTraceEnabled() ) {
-			log.tracev( "Creating hilo optimizer (legacy) with [incrementSize={0}; returnClass={1}]", incrementSize, returnClass.getName() );
+			log.tracev( "Creating hilo optimizer (legacy) with [incrementSize={0}; returnClass={1}]",
+					incrementSize, returnClass.getName() );
 		}
 		initialMaxLo = incrementSize;
 	}

hibernate-core/src/main/java/org/hibernate/id/enhanced/PooledOptimizer.java

@@ -57,11 +57,8 @@ public PooledOptimizer(Class<?> returnClass, int incrementSize) {
 			throw new HibernateException( "increment size cannot be less than 1" );
 		}
 		if ( log.isTraceEnabled() ) {
-			log.tracev(
-					"Creating pooled optimizer with [incrementSize={0}; returnClass={1}]",
-					incrementSize,
-					returnClass.getName()
-			);
+			log.tracev( "Creating pooled optimizer with [incrementSize={0}; returnClass={1}]",
+					incrementSize, returnClass.getName() );
 		}
 	}
 

hibernate-core/src/main/java/org/hibernate/id/enhanced/SequenceGeneratorLogger.java

@@ -0,0 +1,64 @@
+/*
+ * SPDX-License-Identifier: Apache-2.0
+ * Copyright Red Hat Inc. and Hibernate Authors
+ */
+package org.hibernate.id.enhanced;
+
+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.INFO;
+import static org.jboss.logging.Logger.Level.WARN;
+
+/**
+ * Logging related to {@link TableGenerator} operations
+ *
+ * @author Gavin King
+ */
+@SubSystemLogging(
+		name = SequenceGeneratorLogger.NAME,
+		description = "Logging related to sequence-based identifier generation"
+)
+@MessageLogger(projectCode = "HHH")
+@ValidIdRange(min = 90201, max = 90300)
+@Internal
+public interface SequenceGeneratorLogger extends BasicLogger {
+	String NAME = SubSystemLogging.BASE + ".id.table";
+
+	Logger SEQUENCE_GENERATOR_LOGGER = Logger.getLogger(NAME);
+	SequenceGeneratorLogger SEQUENCE_GENERATOR_MESSAGE_LOGGER = Logger.getMessageLogger(
+			MethodHandles.lookup(),
+			SequenceGeneratorLogger.class,
+			NAME
+	);
+
+	@LogMessage(level = INFO)
+	@Message(value = "Forcing table use for sequence-style generator due to pooled optimizer selection where db does not support pooled sequences",
+			id = 90201)
+	void forcingTableUse();
+
+	@LogMessage(level = WARN)
+	@Message(value = "The increment size of the sequence '%s' is set to [%d] in the entity mapping while the associated database sequence increment size is [%d]"
+					+ " - the database sequence increment size will take precedence to avoid identifier allocation conflicts.",
+			id = 90202)
+	void sequenceIncrementSizeMismatch(String sequenceName, int incrementSize, int databaseIncrementSize);
+
+	@LogMessage(level = WARN)
+	@Message(value = "Sequence-style generator configuration specified explicit optimizer [%s], but [%s=%s]; using optimizer [%s] increment default of [%s]",
+			id = 90203)
+	void honoringOptimizerSetting(
+			String none,
+			String incrementParam,
+			int incrementSize,
+			String positiveOrNegative,
+			int defaultIncrementSize);
+
+}

hibernate-core/src/main/java/org/hibernate/id/enhanced/SequenceStructure.java

@@ -4,7 +4,6 @@
  */
 package org.hibernate.id.enhanced;
 
-import java.lang.invoke.MethodHandles;
 import java.sql.PreparedStatement;
 import java.sql.ResultSet;
 import java.sql.SQLException;
@@ -18,10 +17,8 @@
 import org.hibernate.engine.jdbc.spi.JdbcCoordinator;
 import org.hibernate.engine.spi.SharedSessionContractImplementor;
 import org.hibernate.id.IntegralDataTypeHolder;
-import org.hibernate.internal.CoreMessageLogger;
-
-import org.jboss.logging.Logger;
 
+import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER;
 import static org.hibernate.id.IdentifierGeneratorHelper.getIntegralDataTypeHolder;
 
 /**
@@ -30,11 +27,6 @@
  * @author Steve Ebersole
  */
 public class SequenceStructure implements DatabaseStructure {
-	private static final CoreMessageLogger LOG = Logger.getMessageLogger(
-			MethodHandles.lookup(),
-			CoreMessageLogger.class,
-			SequenceStructure.class.getName()
-	);
 
 	private final String contributor;
 	private final QualifiedName logicalQualifiedSequenceName;
@@ -123,8 +115,8 @@ public IntegralDataTypeHolder getNextValue() {
 							rs.next();
 							final IntegralDataTypeHolder value = getIntegralDataTypeHolder( numberType );
 							value.initialize( rs, 1 );
-							if ( LOG.isTraceEnabled() ) {
-								LOG.tracef( "Sequence value obtained: %s", value.makeValue() );
+							if ( JDBC_MESSAGE_LOGGER.isTraceEnabled() ) {
+								JDBC_MESSAGE_LOGGER.sequenceValueRetrievedFromDatabase( value.makeValue() );
 							}
 							return value;
 						}