HSEARCH-4995 Prevent logging of trace events to stdout in tests relyi…

…ng on ExpectedLog4jLog
hibernate · Nov 14, 2023 · cd8d181 · cd8d181
1 parent 66f97c2
commit cd8d181
Show file tree

Hide file tree

Showing 7 changed files with 100 additions and 34 deletions.
diff --git a/...mapper/orm/schema/management/strategy/SchemaManagementStrategyDropAndCreateAndDropIT.java b/...mapper/orm/schema/management/strategy/SchemaManagementStrategyDropAndCreateAndDropIT.java
@@ -10,6 +10,7 @@
 
 import org.hibernate.SessionFactory;
 import org.hibernate.search.mapper.orm.schema.management.SchemaManagementStrategyName;
+import org.hibernate.search.util.common.SearchException;
 import org.hibernate.search.util.impl.integrationtest.common.extension.SchemaManagementWorkBehavior;
 import org.hibernate.search.util.impl.integrationtest.common.stub.backend.index.StubSchemaManagementWork;
 import org.hibernate.search.util.impl.test.ExceptionMatcherBuilder;
@@ -44,9 +45,12 @@ void close_drop_exception_single() {
 
 		logged.expectEvent(
 				Level.ERROR,
-				ExceptionMatcherBuilder.isException( exception ).build(),
-				"Hibernate Search encountered a failure during shutdown",
-				IndexedEntity2.class.getName()
+				ExceptionMatcherBuilder.isException( SearchException.class )
+						.withMessage( "Hibernate Search encountered failures during shutdown" )
+						.withMessage( IndexedEntity2.class.getName() )
+						.withSuppressed( exception )
+						.build(),
+				"Unable to shut down Hibernate Search"
 		);
 		sessionFactory.close();
 		backendMock.verifyExpectationsMet();
@@ -67,15 +71,14 @@ void close_drop_exception_multiple() {
 
 		logged.expectEvent(
 				Level.ERROR,
-				ExceptionMatcherBuilder.isException( exception1 ).build(),
-				"Hibernate Search encountered a failure during shutdown",
-				IndexedEntity1.class.getName()
-		);
-		logged.expectEvent(
-				Level.ERROR,
-				ExceptionMatcherBuilder.isException( exception2 ).build(),
-				"Hibernate Search encountered a failure during shutdown",
-				IndexedEntity2.class.getName()
+				ExceptionMatcherBuilder.isException( SearchException.class )
+						.withMessage( "Hibernate Search encountered failures during shutdown" )
+						.withMessage( IndexedEntity1.class.getName() )
+						.withMessage( IndexedEntity2.class.getName() )
+						.withSuppressed( exception1 )
+						.withSuppressed( exception2 )
+						.build(),
+				"Unable to shut down Hibernate Search"
 		);
 		sessionFactory.close();
 		backendMock.verifyExpectationsMet();

diff --git a/...test/java/org/hibernate/search/integrationtest/mapper/pojo/bootstrap/FailureReportIT.java b/...test/java/org/hibernate/search/integrationtest/mapper/pojo/bootstrap/FailureReportIT.java
@@ -6,6 +6,7 @@
  */
 package org.hibernate.search.integrationtest.mapper.pojo.bootstrap;
 
+import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.assertThatThrownBy;
 
 import java.lang.invoke.MethodHandles;
@@ -74,15 +75,17 @@ class IndexedEntity {
 				() -> new SearchException( field2FailureMessage )
 		);
 
+		// We want trace logs all along the process,
+		// just in case a critical failure prevents the failure report from being thrown.
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field1FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
 						+ "Standalone POJO mapping, type '" + IndexedEntity.class.getName() + "', path '.myProperty'\n"
 		);
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field2FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
@@ -100,7 +103,17 @@ class IndexedEntity {
 								+ "                failures: \n"
 								+ "                  - " + field1FailureMessage + "\n"
 								+ "                  - " + field2FailureMessage
-				);
+				)
+				// We also want the stack traces for debugging purposes
+				.satisfies( e -> assertThat( e.getSuppressed() )
+						.satisfiesExactlyInAnyOrder(
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage( field1FailureMessage ),
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage( field2FailureMessage )
+						) );
 	}
 
 	/**
@@ -131,15 +144,17 @@ class IndexedEntity {
 				() -> new SearchException( field2FailureMessage )
 		);
 
+		// We want trace logs all along the process,
+		// just in case a critical failure prevents the failure report from being thrown.
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field1FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
 						+ "Standalone POJO mapping, type '" + IndexedEntity.class.getName() + "', path '.myProperty1'\n"
 		);
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field2FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
@@ -159,7 +174,17 @@ class IndexedEntity {
 								+ "            path '.myProperty2': \n"
 								+ "                failures: \n"
 								+ "                  - " + field2FailureMessage
-				);
+				)
+				// We also want the stack traces for debugging purposes
+				.satisfies( e -> assertThat( e.getSuppressed() )
+						.satisfiesExactlyInAnyOrder(
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage( field1FailureMessage ),
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage( field2FailureMessage )
+						) );
 	}
 
 	/**
@@ -196,15 +221,17 @@ class IndexedEntity2 {
 				() -> new SearchException( field2FailureMessage )
 		);
 
+		// We want trace logs all along the process,
+		// just in case a critical failure prevents the failure report from being thrown.
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field1FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
 						+ "Standalone POJO mapping, type '" + IndexedEntity1.class.getName() + "', path '.myProperty1'\n"
 		);
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field2FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
@@ -225,7 +252,17 @@ class IndexedEntity2 {
 								+ "            path '.myProperty2': \n"
 								+ "                failures: \n"
 								+ "                  - " + field2FailureMessage
-				);
+				)
+				// We also want the stack traces for debugging purposes
+				.satisfies( e -> assertThat( e.getSuppressed() )
+						.satisfiesExactlyInAnyOrder(
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage( field1FailureMessage ),
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage( field2FailureMessage )
+						) );
 	}
 
 	@Test
@@ -258,16 +295,18 @@ class IndexedEntity {
 				)
 		);
 
+		// We want trace logs all along the process,
+		// just in case a critical failure prevents the failure report from being thrown.
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field1FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
 						+ "Standalone POJO mapping, type '" + IndexedEntity.class.getName() + "', path '.myProperty',"
 						+ " index '" + indexName + "', field 'failingField1'\n"
 		);
 		logged.expectEvent(
-				Level.ERROR,
+				Level.TRACE,
 				ExceptionMatcherBuilder.isException( SearchException.class )
 						.withMessage( field2FailureMessage ).build(),
 				FAILURE_LOG_INTRODUCTION
@@ -290,7 +329,19 @@ class IndexedEntity {
 								+ "                    field 'failingField2': \n"
 								+ "                        failures: \n"
 								+ "                          - " + field2FailureMessage
-				);
+				)
+				// We also want the stack traces for debugging purposes
+				.satisfies( e -> assertThat( e.getSuppressed() )
+						.satisfiesExactlyInAnyOrder(
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage(
+												field1FailureMessage + "\nContext: index 'indexName', field 'failingField1'" ),
+								s -> assertThat( s )
+										.isInstanceOf( SearchException.class )
+										.hasMessage(
+												field2FailureMessage + "\nContext: index 'indexName', field 'failingField2'" )
+						) );
 	}
 
 }
diff --git a/...apper/pojo/schema/management/strategy/SchemaManagementStrategyDropAndCreateAndDropIT.java b/...apper/pojo/schema/management/strategy/SchemaManagementStrategyDropAndCreateAndDropIT.java
@@ -56,7 +56,8 @@ void close_drop_exception_single() {
 				.hasMessageContainingAll(
 						"Hibernate Search encountered failures during shutdown",
 						IndexedEntity2.class.getName()
-				);
+				)
+				.hasSuppressedException( exception );
 		backendMock.verifyExpectationsMet();
 	}
 
@@ -76,7 +77,9 @@ void close_drop_exception_multiple() {
 						"Hibernate Search encountered failures during shutdown",
 						IndexedEntity1.class.getName(),
 						IndexedEntity2.class.getName()
-				);
+				)
+				.hasSuppressedException( exception1 )
+				.hasSuppressedException( exception2 );
 		mapping.close();
 		backendMock.verifyExpectationsMet();
 	}

diff --git a/...ava/org/hibernate/search/mapper/orm/bootstrap/impl/HibernateOrmIntegrationBooterImpl.java b/...ava/org/hibernate/search/mapper/orm/bootstrap/impl/HibernateOrmIntegrationBooterImpl.java
@@ -167,7 +167,7 @@ CompletableFuture<HibernateSearchContextProviderService> orchestrateBootAndShutd
 				// to skip further cleanup of other resources.
 				.whenComplete( Futures.handler( (ignored, throwable) -> {
 					if ( throwable != null ) {
-						log.shutdownFailed( throwable.getMessage(), throwable );
+						log.shutdownFailed( throwable );
 					}
 				} ) );
 

diff --git a/mapper/orm/src/main/java/org/hibernate/search/mapper/orm/logging/impl/Log.java b/mapper/orm/src/main/java/org/hibernate/search/mapper/orm/logging/impl/Log.java
@@ -207,8 +207,8 @@ SearchException unknownClassForIndexedEntityType(@FormatWith(ClassFormatter.clas
 	SearchException unknownEntityNameForIndexedEntityType(String invalidName, Collection<String> validNames);
 
 	@LogMessage(level = Logger.Level.ERROR)
-	@Message(id = ID_OFFSET + 35, value = "Unable to shut down Hibernate Search: %1$s")
-	void shutdownFailed(String causeMessage, @Cause Throwable cause);
+	@Message(id = ID_OFFSET + 35, value = "Unable to shut down Hibernate Search:")
+	void shutdownFailed(@Cause Throwable cause);
 
 	@Message(id = ID_OFFSET + 36, value = "Cannot use scroll() with scroll mode '%1$s' with Hibernate Search queries:"
 			+ " only ScrollMode.FORWARDS_ONLY is supported.")

diff --git a/util/common/src/test/resources/log4j2.properties b/util/common/src/test/resources/log4j2.properties
@@ -3,6 +3,8 @@ appender.stdout.type=Console
 appender.stdout.name=STDOUT
 appender.stdout.layout.type=PatternLayout
 appender.stdout.layout.pattern=%d{ABSOLUTE} (%t) %5p %c{1}:%L - %m%n
+appender.stdout.filter.threshold.type=ThresholdFilter
+appender.stdout.filter.threshold.level=debug
 
 ## Loggers
 rootLogger.level=info
@@ -14,8 +16,10 @@ logger.jboss.level=info
 
 ### Search logger
 logger.search.name=org.hibernate.search
-logger.search.level=debug
+# See the appender threshold above to actually log trace events
+logger.search.level=trace
 
 ### Elasticsearch logger
 logger.elasticsearch.name=org.elasticsearch.client
-logger.elasticsearch.level=debug
+# See the appender threshold above to actually log trace events
+logger.elasticsearch.level=trace
diff --git a/util/internal/test/common/src/main/resources/log4j2.properties b/util/internal/test/common/src/main/resources/log4j2.properties
@@ -3,6 +3,8 @@ appender.stdout.type=Console
 appender.stdout.name=STDOUT
 appender.stdout.layout.type=PatternLayout
 appender.stdout.layout.pattern=%d{ABSOLUTE} (%t) %5p %c{1}:%L - %m%n
+appender.stdout.filter.threshold.type=ThresholdFilter
+appender.stdout.filter.threshold.level=debug
 
 ## Loggers
 rootLogger.level=info
@@ -14,12 +16,15 @@ logger.jboss.level=info
 
 ### ORM parameter binding logger
 logger.types.name=org.hibernate.type
-#logger.types.level=trace
+# See the appender threshold above to actually log trace events
+logger.types.level=trace
 
 ### Search logger
 logger.search.name=org.hibernate.search
-logger.search.level=debug
+# See the appender threshold above to actually log trace events
+logger.search.level=trace
 
 ### Elasticsearch logger
 logger.elasticsearch.name=org.elasticsearch.client
-logger.elasticsearch.level=debug
+# See the appender threshold above to actually log trace events
+logger.elasticsearch.level=trace