HSEARCH-4995 Use suppressed exceptions instead of logging for nested failures in RootFailureCollector

engine/src/main/java/org/hibernate/search/engine/logging/impl/Log.java

@@ -29,10 +29,12 @@
 import org.hibernate.search.util.common.SearchTimeoutException;
 import org.hibernate.search.util.common.logging.impl.ClassFormatter;
 import org.hibernate.search.util.common.logging.impl.DurationInSecondsAndFractionsFormatter;
+import org.hibernate.search.util.common.logging.impl.EventContextFormatter;
 import org.hibernate.search.util.common.logging.impl.EventContextNoPrefixFormatter;
 import org.hibernate.search.util.common.logging.impl.MessageConstants;
 import org.hibernate.search.util.common.logging.impl.SimpleNameClassFormatter;
 import org.hibernate.search.util.common.reporting.EventContext;
+import org.hibernate.search.util.common.reporting.spi.EventContextProvider;
 
 import org.jboss.logging.BasicLogger;
 import org.jboss.logging.Logger;
@@ -127,23 +129,26 @@ IllegalArgumentException invalidGeoPolygonFirstPointNotIdenticalToLastPoint(GeoP
 	@Message(id = ID_OFFSET + 19,
 			value = "Hibernate Search encountered %3$s failures during %1$s."
 					+ " Only the first %2$s failures are displayed here."
-					+ " See the logs for extra failures.")
+					+ " See the TRACE logs for extra failures.")
 	String collectedFailureLimitReached(String process, int failureLimit, int failureCount);
 
 	@Message(id = ID_OFFSET + 20,
 			value = "Hibernate Search encountered failures during %1$s."
 					+ " Failures:\n%2$s")
-	SearchException collectedFailures(String process, String renderedFailures);
+	SearchException collectedFailures(String process, String renderedFailures,
+			@Suppressed Collection<Throwable> failures);
 
-	@LogMessage(level = Logger.Level.ERROR)
+	@LogMessage(level = Logger.Level.TRACE)
 	@Message(id = ID_OFFSET + 21,
 			value = "Hibernate Search encountered a failure during %1$s;"
 					+ " continuing for now to list all problems,"
 					+ " but the process will ultimately be aborted.\n"
-					+ "Context: %2$s\n"
+					+ "%2$s\n" // Context
 					+ "Failure:" // The stack trace follows
 	)
-	void newCollectedFailure(String process, String context, @Cause Throwable failure);
+	void newCollectedFailure(String process,
+			@FormatWith(EventContextFormatter.class) EventContextProvider contextProvider,
+			@Cause Throwable failure);
 
 	@LogMessage(level = Logger.Level.WARN)
 	@Message(id = ID_OFFSET + 22, value = "Exception while collecting a failure"

engine/src/main/java/org/hibernate/search/engine/reporting/spi/ContextualFailureCollector.java

@@ -6,14 +6,16 @@
  */
 package org.hibernate.search.engine.reporting.spi;
 
+import org.hibernate.search.util.common.reporting.spi.EventContextProvider;
+
 /**
  * A failure collector with an implicit context.
  * <p>
  * Implementations are thread-safe.
  *
  * @see FailureCollector
  */
-public interface ContextualFailureCollector extends FailureCollector {
+public interface ContextualFailureCollector extends FailureCollector, EventContextProvider {
 
 	boolean hasFailure();
 

engine/src/main/java/org/hibernate/search/engine/reporting/spi/RootFailureCollector.java

@@ -7,10 +7,10 @@
 package org.hibernate.search.engine.reporting.spi;
 
 import java.lang.invoke.MethodHandles;
+import java.util.ArrayList;
 import java.util.Collection;
 import java.util.List;
 import java.util.Map;
-import java.util.StringJoiner;
 import java.util.concurrent.ConcurrentLinkedDeque;
 import java.util.concurrent.ConcurrentSkipListMap;
 import java.util.concurrent.atomic.AtomicInteger;
@@ -24,7 +24,6 @@
 import org.hibernate.search.util.common.logging.impl.LoggerFactory;
 import org.hibernate.search.util.common.reporting.EventContext;
 import org.hibernate.search.util.common.reporting.EventContextElement;
-import org.hibernate.search.util.common.reporting.impl.CommonEventContextMessages;
 
 public final class RootFailureCollector implements FailureCollector {
 
@@ -49,30 +48,26 @@ public RootFailureCollector(String process) {
 
 	public void checkNoFailure() {
 		if ( failureCount.get() > 0 ) {
-			String renderedFailures = renderFailures();
-			throw log.collectedFailures( process, renderedFailures );
+			List<Throwable> failures = new ArrayList<>();
+			ToStringStyle style = ToStringStyle.multilineIndentStructure(
+					EngineEventContextMessages.INSTANCE.failureReportContextFailuresSeparator(),
+					EngineEventContextMessages.INSTANCE.failureReportContextIndent(),
+					EngineEventContextMessages.INSTANCE.failureReportFailuresBulletPoint(),
+					EngineEventContextMessages.INSTANCE.failureReportFailuresNoBulletPoint()
+			);
+			ToStringTreeBuilder builder = new ToStringTreeBuilder( style );
+			builder.startObject();
+			if ( failureCount.get() > FAILURE_LIMIT ) {
+				builder.value( log.collectedFailureLimitReached( process, FAILURE_LIMIT, failureCount.get() ) );
+			}
+			if ( delegate != null ) {
+				delegate.appendChildrenFailuresTo( failures, builder );
+			}
+			builder.endObject();
+			throw log.collectedFailures( process, builder.toString(), failures );
 		}
 	}
 
-	private String renderFailures() {
-		ToStringStyle style = ToStringStyle.multilineIndentStructure(
-				EngineEventContextMessages.INSTANCE.failureReportContextFailuresSeparator(),
-				EngineEventContextMessages.INSTANCE.failureReportContextIndent(),
-				EngineEventContextMessages.INSTANCE.failureReportFailuresBulletPoint(),
-				EngineEventContextMessages.INSTANCE.failureReportFailuresNoBulletPoint()
-		);
-		ToStringTreeBuilder builder = new ToStringTreeBuilder( style );
-		builder.startObject();
-		if ( failureCount.get() > FAILURE_LIMIT ) {
-			builder.value( log.collectedFailureLimitReached( process, FAILURE_LIMIT, failureCount.get() ) );
-		}
-		if ( delegate != null ) {
-			delegate.appendChildrenFailuresTo( builder );
-		}
-		builder.endObject();
-		return builder.toString();
-	}
-
 	@Override
 	public ContextualFailureCollector withContext(EventContext context) {
 		return delegate.withContext( context );
@@ -138,36 +133,38 @@ ContextualFailureCollectorImpl withDefaultContext() {
 			return withContext( EventContexts.defaultContext() );
 		}
 
-		void appendContextTo(StringJoiner joiner) {
-			// Nothing to do
+		EventContext createEventContext(EventContextElement contextElement) {
+			return EventContext.create( contextElement );
 		}
 
-		final void appendChildrenFailuresTo(ToStringTreeBuilder builder) {
+		final void appendChildrenFailuresTo(List<Throwable> failures, ToStringTreeBuilder builder) {
 			for ( ContextualFailureCollectorImpl child : children.values() ) {
 				// Some contexts may have been mentioned without any failure being ever reported.
 				// Only display contexts that had at least one failure reported.
 				if ( child.hasFailure() ) {
-					child.appendFailuresTo( builder );
+					child.appendFailuresTo( failures, builder );
 				}
 			}
 		}
 
 		final Collection<ContextualFailureCollectorImpl> children() {
 			return children.values();
 		}
+
 	}
 
 	private static class ContextualFailureCollectorImpl extends NonRootFailureCollector implements ContextualFailureCollector {
 		private final NonRootFailureCollector parent;
-		private final EventContextElement context;
+		private final EventContextElement contextElement;
 
 		// Avoiding blocking implementations because we access this from reactive event loops
+		private final Collection<Throwable> failures = new ConcurrentLinkedDeque<>();
 		private final Collection<String> failureMessages = new ConcurrentLinkedDeque<>();
 
-		private ContextualFailureCollectorImpl(NonRootFailureCollector parent, EventContextElement context) {
+		private ContextualFailureCollectorImpl(NonRootFailureCollector parent, EventContextElement contextElement) {
 			super( parent );
 			this.parent = parent;
-			this.context = context;
+			this.contextElement = contextElement;
 		}
 
 		@Override
@@ -202,7 +199,7 @@ public void add(Throwable t) {
 
 		@Override
 		public void add(String failureMessage) {
-			doAdd( failureMessage );
+			doAdd( null, failureMessage );
 		}
 
 		@Override
@@ -211,31 +208,33 @@ ContextualFailureCollectorImpl withDefaultContext() {
 		}
 
 		@Override
-		void appendContextTo(StringJoiner joiner) {
-			parent.appendContextTo( joiner );
-			joiner.add( context.render() );
+		public EventContext eventContext() {
+			return parent.createEventContext( contextElement );
 		}
 
-		void appendFailuresTo(ToStringTreeBuilder builder) {
-			builder.startObject( context.render() );
+		@Override
+		EventContext createEventContext(EventContextElement contextElement) {
+			return eventContext().append( contextElement );
+		}
+
+		void appendFailuresTo(List<Throwable> failures, ToStringTreeBuilder builder) {
+			builder.startObject( contextElement.render() );
+			failures.addAll( this.failures );
 			if ( !failureMessages.isEmpty() ) {
 				builder.attribute( EngineEventContextMessages.INSTANCE.failureReportFailures(), failureMessages );
 			}
-			appendChildrenFailuresTo( builder );
+			appendChildrenFailuresTo( failures, builder );
 			builder.endObject();
 		}
 
 		private void doAdd(Throwable failure, String failureMessage) {
-			StringJoiner contextJoiner = new StringJoiner( CommonEventContextMessages.INSTANCE.contextSeparator() );
-			appendContextTo( contextJoiner );
-			log.newCollectedFailure( root.process, contextJoiner.toString(), failure );
+			log.newCollectedFailure( root.process, this, failure );
 
-			doAdd( failureMessage );
-		}
-
-		private void doAdd(String failureMessage) {
 			if ( root.shouldAddFailure() ) {
 				failureMessages.add( failureMessage );
+				if ( failure != null ) {
+					failures.add( failure );
+				}
 			}
 		}
 	}

engine/src/test/java/org/hibernate/search/engine/reporting/spi/RootFailureCollectorTest.java

@@ -10,17 +10,60 @@
 import static org.assertj.core.api.Assertions.assertThatThrownBy;
 import static org.awaitility.Awaitility.await;
 
+import java.util.ArrayList;
 import java.util.List;
 import java.util.concurrent.ForkJoinPool;
 import java.util.concurrent.ForkJoinTask;
 import java.util.concurrent.TimeUnit;
 import java.util.stream.Collectors;
 import java.util.stream.IntStream;
 
+import org.hibernate.search.util.common.SearchException;
+
 import org.junit.jupiter.api.Test;
 
 class RootFailureCollectorTest {
 
+	@Test
+	void simple() {
+		RootFailureCollector rootFailureCollector = new RootFailureCollector( "RootName" );
+		List<String> messages = new ArrayList<>();
+		List<Throwable> exceptions = new ArrayList<>();
+		for ( int i = 0; i < 30; i++ ) {
+			ContextualFailureCollector failureCollector = rootFailureCollector.withContext(
+					EventContexts.fromType( "Type #" + i ) );
+			if ( i % 3 == 0 ) {
+				String message = "Failure with RuntimeException #" + i;
+				messages.add( message );
+				Throwable exception = new RuntimeException( message );
+				exceptions.add( exception );
+				failureCollector.add( exception );
+			}
+			else if ( i % 3 == 1 ) {
+				String message = "Failure with SearchException #" + i;
+				messages.add( message );
+				Throwable exception = new SearchException( message, EventContexts.fromIndexFieldAbsolutePath( "path" + i ) );
+				exceptions.add( exception );
+				failureCollector.add( exception );
+			}
+			else {
+				String message = "Failure without exception #" + i;
+				messages.add( message );
+				failureCollector.add( message );
+			}
+		}
+		for ( int i = 0; i < 10; i++ ) {
+			ContextualFailureCollector failureCollector = rootFailureCollector.withContext(
+					EventContexts.fromType( "Type #" + i ) );
+			failureCollector.add( "Error #" + i );
+		}
+		assertThatThrownBy( rootFailureCollector::checkNoFailure )
+				// Check that we mention that some failures are not being reported
+				.hasMessageContaining( "Hibernate Search encountered failures during RootName" )
+				.hasMessageContainingAll( messages.toArray( CharSequence[]::new ) )
+				.satisfies( e -> assertThat( e.getSuppressed() ).containsExactlyInAnyOrderElementsOf( exceptions ) );
+	}
+
 	/**
 	 * Triggers many more failures than the failure limit.
 	 * <p>
@@ -44,7 +87,7 @@ void failureLimit() {
 				.hasMessageContainingAll( "Hibernate Search encountered " + ( RootFailureCollector.FAILURE_LIMIT + 10 )
 						+ " failures during RootName",
 						"Only the first " + RootFailureCollector.FAILURE_LIMIT + " failures are displayed here",
-						"See the logs for extra failures" )
+						"See the TRACE logs for extra failures" )
 				// Check that we didn't report failures after the limit was reached
 				.message().satisfies( message -> {
 					assertThat( countOccurrences( message, "Error #" ) )
@@ -89,7 +132,7 @@ void failureLimit_concurrency() {
 				.hasMessageContainingAll( "Hibernate Search encountered " + ( RootFailureCollector.FAILURE_LIMIT + 1000 )
 						+ " failures during RootName",
 						"Only the first " + RootFailureCollector.FAILURE_LIMIT + " failures are displayed here",
-						"See the logs for extra failures" )
+						"See the TRACE logs for extra failures" )
 				// Check that we didn't report failures after the limit was reached
 				.message().satisfies( message -> {
 					assertThat( countOccurrences( message, "Error #" ) )

integrationtest/mapper/orm-cdi/src/test/java/org/hibernate/search/integrationtest/mapper/orm/cdi/CdiExtendedBeanManagerBootstrapShutdownIT.java

@@ -30,6 +30,7 @@
 import org.hibernate.search.util.impl.integrationtest.common.extension.StubSearchWorkBehavior;
 import org.hibernate.search.util.impl.integrationtest.common.reporting.FailureReportUtils;
 import org.hibernate.search.util.impl.integrationtest.mapper.orm.OrmSetupHelper;
+import org.hibernate.search.util.impl.test.ExceptionMatcherBuilder;
 import org.hibernate.search.util.impl.test.annotation.TestForIssue;
 import org.hibernate.search.util.impl.test.extension.ExpectedLog4jLog;
 import org.hibernate.search.util.impl.test.extension.StaticCounters;
@@ -266,7 +267,12 @@ void failedShutdown() {
 
 			// The bean manager shuts down.
 			// Hibernate Search should fail to shut down, and report the failure through the logs.
-			logged.expectEvent( Level.ERROR, "Simulated shutdown failure" );
+			logged.expectEvent( Level.ERROR,
+					ExceptionMatcherBuilder.isException( SearchException.class )
+							.withMessage( "Hibernate Search encountered failures during shutdown" )
+							.withSuppressed( bootFailedException )
+							.build(),
+					"Unable to shut down Hibernate Search" );
 			extendedBeanManager.simulateShutdown();
 
 			assertThat( StaticCounters.get().get( DependentBean.KEYS.preDestroy ) ).isEqualTo( 1 );

integrationtest/mapper/orm/src/test/java/org/hibernate/search/integrationtest/mapper/orm/bootstrap/ShutdownFailureIT.java

@@ -15,8 +15,10 @@
 import org.hibernate.search.mapper.pojo.bridge.runtime.ValueBridgeToIndexedValueContext;
 import org.hibernate.search.mapper.pojo.mapping.definition.annotation.GenericField;
 import org.hibernate.search.mapper.pojo.mapping.definition.annotation.Indexed;
+import org.hibernate.search.util.common.SearchException;
 import org.hibernate.search.util.impl.integrationtest.common.extension.BackendMock;
 import org.hibernate.search.util.impl.integrationtest.mapper.orm.OrmSetupHelper;
+import org.hibernate.search.util.impl.test.ExceptionMatcherBuilder;
 import org.hibernate.search.util.impl.test.extension.ExpectedLog4jLog;
 
 import org.junit.jupiter.api.Test;
@@ -44,7 +46,14 @@ void logException() {
 		backendMock.expectAnySchema( FailingIndexedEntity.NAME );
 		SessionFactory sessionFactory = ormSetupHelper.start().setup( FailingIndexedEntity.class );
 
-		logged.expectEvent( Level.ERROR, "Simulated shutdown failure" );
+		logged.expectEvent( Level.ERROR,
+				ExceptionMatcherBuilder.isException( SearchException.class )
+						.withMessage( "Hibernate Search encountered failures during shutdown" )
+						.withSuppressed( ExceptionMatcherBuilder.isException( RuntimeException.class )
+								.withMessage( "Simulated shutdown failure" )
+								.build() )
+						.build(),
+				"Unable to shut down Hibernate Search" );
 		sessionFactory.close();
 	}