add proper logging to junit runs (#35394)

Basically, Junit is not logging any thing about its progress outside of the console. This is aimed at fixing that by outputing progress logs along with the standard logs. So there's going to be a line before each step of a test run, and a line after with the elapsed time. Also, exception are now part of the logs instead of being only part of the junit report.
In the process of doing that, I decided to clean up and simplify the log4j2.xml file.
I also noted a few issues with ANSI coloring, so there's a fix for that.
Finally, I'm removing empty lines from container logs (MSSQL is full of them).

The junit printing is done through an intereceptor. That interceptor uses introspection. I wanted to use a factory method, but java's ServiceLoader only allows classes that extends the service interface,  hence the need to override every method in the interceptor class, and to plop a proxy on top of that.

airbyte-cdk/java/airbyte-cdk/README.md

@@ -166,6 +166,7 @@ MavenLocal debugging steps:
 
 | Version | Date       | Pull Request                                               | Subject                                                                                                                                                        |
 |:--------|:-----------|:-----------------------------------------------------------|:---------------------------------------------------------------------------------------------------------------------------------------------------------------|
+| 0.21.3  | 2024-02-20 | [\#35394](https://github.com/airbytehq/airbyte/pull/35394) | Add Junit progress information to the test logs                                                                                                                                  |
 | 0.21.2  | 2024-02-20 | [\#34978](https://github.com/airbytehq/airbyte/pull/34978) | Reduce log noise in NormalizationLogParser.                                                                                                                    |
 | 0.21.1  | 2024-02-20 | [\#35199](https://github.com/airbytehq/airbyte/pull/35199) | Add thread names to the logs.                                                                                                                                  |
 | 0.21.0  | 2024-02-16 | [\#35314](https://github.com/airbytehq/airbyte/pull/35314) | Delete S3StreamCopier classes. These have been superseded by the async destinations framework.                                                                 |

airbyte-cdk/java/airbyte-cdk/core/src/main/resources/version.properties

@@ -1 +1 @@
-version=0.21.2
+version=0.21.3

airbyte-cdk/java/airbyte-cdk/core/src/test/java/io/airbyte/cdk/integrations/base/AirbyteLogMessageTemplateTest.java

@@ -25,51 +25,45 @@ import org.apache.logging.log4j.core.appender.OutputStreamAppender;
 import org.apache.logging.log4j.core.config.Configuration;
 import org.apache.logging.log4j.core.config.Configurator;
 import org.apache.logging.log4j.core.config.LoggerConfig;
-import org.junit.jupiter.api.AfterAll;
+import org.apache.logging.log4j.spi.ExtendedLogger;
-import org.junit.jupiter.api.BeforeAll;
+import org.junit.jupiter.api.AfterEach;
-import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.params.ParameterizedTest;
 import org.junit.jupiter.params.provider.ValueSource;
 import org.junit.platform.commons.util.StringUtils;
-import org.slf4j.Logger;
-import org.slf4j.LoggerFactory;
 
 public class AirbyteLogMessageTemplateTest {
 
-  private static final ByteArrayOutputStream outputContent = new ByteArrayOutputStream();
-  private static final Logger LOGGER = LoggerFactory.getLogger(AirbyteLogMessageTemplateTest.class);
   public static final String OUTPUT_STREAM_APPENDER = "OutputStreamAppender";
   public static final String CONSOLE_JSON_APPENDER = "ConsoleJSONAppender";
-  private static OutputStreamAppender outputStreamAppender;
+  private LoggerContext loggerContext;
-  private static LoggerConfig rootLoggerConfig;
+  private LoggerConfig rootLoggerConfig;
-  private static LoggerContext loggerContext;
+  private ExtendedLogger logger;
+  private OutputStreamAppender outputStreamAppender;
+  private ByteArrayOutputStream outputContent;
 
-  @BeforeAll
+  void getLogger() {
-  static void init() {
     // We are creating a log appender with the same output pattern
     // as the console json appender defined in this project's log4j2.xml file.
     // We then attach this log appender with the LOGGER instance so that we can validate the logs
     // produced by code and assert that it matches the expected format.
     loggerContext = Configurator.initialize(null, "log4j2.xml");
+
     final Configuration configuration = loggerContext.getConfiguration();
     rootLoggerConfig = configuration.getLoggerConfig("");
 
+    outputContent = new ByteArrayOutputStream();
     outputStreamAppender = OutputStreamAppender.createAppender(
         rootLoggerConfig.getAppenders().get(CONSOLE_JSON_APPENDER).getLayout(),
         null, outputContent, OUTPUT_STREAM_APPENDER, false, true);
     outputStreamAppender.start();
 
     rootLoggerConfig.addAppender(outputStreamAppender, Level.ALL, null);
+    logger = loggerContext.getLogger(AirbyteLogMessageTemplateTest.class);
   }
 
-  @BeforeEach
+  @AfterEach
-  void setup() {
+  void closeLogger() {
-    outputContent.reset();
-  }
-
-  @AfterAll
-  static void cleanUp() {
     outputStreamAppender.stop();
     rootLoggerConfig.removeAppender(OUTPUT_STREAM_APPENDER);
     loggerContext.close();
@@ -77,7 +71,8 @@ public class AirbyteLogMessageTemplateTest {
 
   @Test
   public void testAirbyteLogMessageFormat() throws java.io.IOException {
-    LOGGER.info("hello");
+    getLogger();
+    logger.info("hello");
 
     outputContent.flush();
     final String logMessage = outputContent.toString(StandardCharsets.UTF_8);
@@ -114,12 +109,13 @@ public class AirbyteLogMessageTemplateTest {
 
   @ParameterizedTest
   @ValueSource(ints = {2, 100, 9000})
-  public void testAirbyteLogMessageLength(int stringRepeatitions) throws java.io.IOException {
+  public void testAirbyteLogMessageLength(int stringRepetitions) throws java.io.IOException {
+    getLogger();
     final StringBuilder sb = new StringBuilder();
-    for (int i = 0; i < stringRepeatitions; i++) {
+    for (int i = 0; i < stringRepetitions; i++) {
       sb.append("abcd");
     }
-    LOGGER.info(sb.toString(), new RuntimeException("aaaaa bbbbbb ccccccc dddddd"));
+    logger.info(sb.toString(), new RuntimeException("aaaaa bbbbbb ccccccc dddddd"));
     outputContent.flush();
     final String logMessage = outputContent.toString(StandardCharsets.UTF_8);
 

airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/extensions/LoggingInvocationInterceptor.java

@@ -0,0 +1,160 @@
+/*
+ * Copyright (c) 2023 Airbyte, Inc., all rights reserved.
+ */
+
+package io.airbyte.cdk.extensions;
+
+import java.lang.reflect.Constructor;
+import java.lang.reflect.InvocationHandler;
+import java.lang.reflect.Method;
+import java.lang.reflect.Proxy;
+import java.time.Duration;
+import java.time.Instant;
+import java.util.Arrays;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+import java.util.stream.Collectors;
+import org.apache.commons.lang3.exception.ExceptionUtils;
+import org.junit.jupiter.api.extension.DynamicTestInvocationContext;
+import org.junit.jupiter.api.extension.ExtensionContext;
+import org.junit.jupiter.api.extension.InvocationInterceptor;
+import org.junit.jupiter.api.extension.ReflectiveInvocationContext;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * By default, junit only output logs to the console, and nothing makes it into log4j logs. This
+ * class fixes that by using the interceptor facility to print progress and timing information. This
+ * allows us to have junit loglines in our test logs. This is instanciated via <a href=
+ * "https://docs.oracle.com/javase%2F9%2Fdocs%2Fapi%2F%2F/java/util/ServiceLoader.html">Java's
+ * ServiceLoader</a> The declaration can be found in
+ * resources/META-INF/services/org.junit.jupiter.api.extension.Extension
+ */
+public class LoggingInvocationInterceptor implements InvocationInterceptor {
+
+  private static final class LoggingInvocationInterceptorHandler implements InvocationHandler {
+
+    private static final Logger LOGGER = LoggerFactory.getLogger(LoggingInvocationInterceptor.class);
+
+    private static final Pattern methodPattern = Pattern.compile("intercept(.*)Method");
+
+    @Override
+    @SuppressWarnings("unchecked")
+    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
+      if (LoggingInvocationInterceptor.class.getDeclaredMethod(method.getName(), Invocation.class, ReflectiveInvocationContext.class,
+          ExtensionContext.class) == null) {
+        LOGGER.error("Junit LoggingInvocationInterceptor executing unknown interception point {}", method.getName());
+        return method.invoke(proxy, args);
+      }
+      var invocation = (Invocation<?>) args[0];
+      var invocationContext = (ReflectiveInvocationContext<Method>) args[1];
+      var extensionContext = (ExtensionContext) args[2];
+      String methodName = method.getName();
+      String logLineSuffix;
+      Matcher methodMatcher = methodPattern.matcher(methodName);
+      if (methodName.equals("interceptDynamicTest")) {
+        logLineSuffix = "execution of DynamicTest %s".formatted(extensionContext.getDisplayName());
+      } else if (methodName.equals("interceptTestClassConstructor")) {
+        logLineSuffix = "instance creation for %s".formatted(invocationContext.getTargetClass());
+      } else if (methodMatcher.matches()) {
+        String interceptedEvent = methodMatcher.group(1);
+        logLineSuffix = "execution of @%s method %s.%s".formatted(invocationContext.getExecutable().getDeclaringClass().getSimpleName(),
+            interceptedEvent, invocationContext.getExecutable().getName());
+      } else {
+        logLineSuffix = "execution of unknown intercepted call %s".formatted(methodName);
+      }
+      LOGGER.info("Junit starting {}", logLineSuffix);
+      try {
+        Instant start = Instant.now();
+        Object retVal = invocation.proceed();
+        long elapsedMs = Duration.between(start, Instant.now()).toMillis();
+        LOGGER.info("Junit completed {} in {} ms", logLineSuffix, elapsedMs);
+        return retVal;
+      } catch (Throwable t) {
+        String stackTrace = Arrays.stream(ExceptionUtils.getStackFrames(t)).takeWhile(s -> !s.startsWith("\tat org.junit")).collect(
+            Collectors.joining("\n  "));
+        LOGGER.warn("Junit exception throw during {}:\n{}", logLineSuffix, stackTrace);
+        throw t;
+      }
+    }
+
+  }
+
+  private final InvocationInterceptor proxy = (InvocationInterceptor) Proxy.newProxyInstance(
+      getClass().getClassLoader(),
+      new Class[] {InvocationInterceptor.class},
+      new LoggingInvocationInterceptorHandler());
+
+  @Override
+  public void interceptAfterAllMethod(Invocation<Void> invocation,
+                                      ReflectiveInvocationContext<Method> invocationContext,
+                                      ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptAfterAllMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public void interceptAfterEachMethod(Invocation<Void> invocation,
+                                       ReflectiveInvocationContext<Method> invocationContext,
+                                       ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptAfterEachMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public void interceptBeforeAllMethod(Invocation<Void> invocation,
+                                       ReflectiveInvocationContext<Method> invocationContext,
+                                       ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptBeforeAllMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public void interceptBeforeEachMethod(Invocation<Void> invocation,
+                                        ReflectiveInvocationContext<Method> invocationContext,
+                                        ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptBeforeEachMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public void interceptDynamicTest(Invocation<Void> invocation,
+                                   DynamicTestInvocationContext invocationContext,
+                                   ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptDynamicTest(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public void interceptTestMethod(Invocation<Void> invocation,
+                                  ReflectiveInvocationContext<Method> invocationContext,
+                                  ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptTestMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public void interceptTestTemplateMethod(Invocation<Void> invocation,
+                                          ReflectiveInvocationContext<Method> invocationContext,
+                                          ExtensionContext extensionContext)
+      throws Throwable {
+    proxy.interceptTestTemplateMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public <T> T interceptTestFactoryMethod(Invocation<T> invocation,
+                                          ReflectiveInvocationContext<Method> invocationContext,
+                                          ExtensionContext extensionContext)
+      throws Throwable {
+    return proxy.interceptTestFactoryMethod(invocation, invocationContext, extensionContext);
+  }
+
+  @Override
+  public <T> T interceptTestClassConstructor(Invocation<T> invocation,
+                                             ReflectiveInvocationContext<Constructor<T>> invocationContext,
+                                             ExtensionContext extensionContext)
+      throws Throwable {
+    return proxy.interceptTestClassConstructor(invocation, invocationContext, extensionContext);
+  }
+
+}

airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/testutils/ContainerFactory.java

@@ -12,12 +12,15 @@ import java.util.ArrayList;
 import java.util.List;
 import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.ConcurrentMap;
+import java.util.concurrent.atomic.AtomicInteger;
 import java.util.function.Supplier;
 import java.util.stream.Stream;
+import org.apache.commons.lang3.StringUtils;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.testcontainers.containers.GenericContainer;
 import org.testcontainers.containers.JdbcDatabaseContainer;
+import org.testcontainers.containers.output.OutputFrame;
 import org.testcontainers.containers.output.Slf4jLogConsumer;
 import org.testcontainers.utility.DockerImageName;
 
@@ -65,10 +68,13 @@ public abstract class ContainerFactory<C extends JdbcDatabaseContainer<?>> {
   }
 
   private static final ConcurrentMap<ContainerKey, ContainerOrException> SHARED_CONTAINERS = new ConcurrentHashMap<>();
+  private static final AtomicInteger containerId = new AtomicInteger(0);
 
-  private static final MdcScope.Builder TESTCONTAINER_LOG_MDC_BUILDER = new MdcScope.Builder()
+  private static final MdcScope.Builder getTestContainerLogMdcBuilder(DockerImageName imageName, List<String> methods) {
-      .setLogPrefix("testcontainer")
+    return new MdcScope.Builder()
+        .setLogPrefix("testcontainer %s (%s[%s]):".formatted(containerId.incrementAndGet(), imageName, StringUtils.join(methods, ",")))
         .setPrefixColor(LoggingHelper.Color.RED_BACKGROUND);
+  }
 
   /**
    * Creates a new, unshared testcontainer instance. This usually wraps the default constructor for
@@ -108,8 +114,16 @@ public abstract class ContainerFactory<C extends JdbcDatabaseContainer<?>> {
       for (String methodName : methodNames) {
         methods.add(getClass().getMethod(methodName, container.getClass()));
       }
-      final var logConsumer = new Slf4jLogConsumer(LOGGER);
+      final var logConsumer = new Slf4jLogConsumer(LOGGER) {
-      TESTCONTAINER_LOG_MDC_BUILDER.produceMappings(logConsumer::withMdc);
+
+        public void accept(OutputFrame frame) {
+          if (frame.getUtf8StringWithoutLineEnding().trim().length() > 0) {
+            super.accept(frame);
+          }
+        }
+
+      };
+      getTestContainerLogMdcBuilder(imageName, methodNames).produceMappings(logConsumer::withMdc);
       container.withLogConsumer(logConsumer);
       for (Method method : methods) {
         LOGGER.info("Calling {} in {} on new shared container based on {}.",

airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/resources/META-INF/services/org.junit.jupiter.api.extension.Extension

@@ -0,0 +1 @@
+io.airbyte.cdk.extensions.LoggingInvocationInterceptor

airbyte-cdk/java/airbyte-cdk/dependencies/src/main/java/io/airbyte/commons/logging/LoggingHelper.java

@@ -41,9 +41,10 @@ public class LoggingHelper {
 
   @VisibleForTesting
   public static final String RESET = "\u001B[0m";
+  public static final String PREPARE_COLOR_CHAR = "\u001b[m";
 
   public static String applyColor(final Color color, final String msg) {
-    return color.getCode() + msg + RESET;
+    return PREPARE_COLOR_CHAR + color.getCode() + msg + PREPARE_COLOR_CHAR + RESET;
   }
 
 }

airbyte-cdk/java/airbyte-cdk/dependencies/src/main/resources/log4j2-test.xml

@@ -2,7 +2,7 @@
 <Configuration status="INFO">
     <Properties>
         <!-- Set the LOG_SCRUB_PATTERN env var to a regex pattern to scrub the log messages of secrets or any other unwanted content. -->
-        <Property name="jvm-log-pattern">%d{yyyy-MM-dd'T'HH:mm:ss,SSS}{GMT+0} %thread `%highlight{%p}`%C{1.}(%M):%L - %replace{%m}{$${env:LOG_SCRUB_PATTERN:-\*\*\*\*\*}}{*****}%n</Property>
+        <Property name="jvm-log-pattern">%d{yyyy-MM-dd'T'HH:mm:ss,SSS}{GMT+0}`%t`%T`%highlight{%p}`%C{1.}(%M):%L - %replace{%m}{$${env:LOG_SCRUB_PATTERN:-\*\*\*\*\*}}{*****}%n</Property>
         <!--Logs the timestamp and log_source/application name in the beginning of the line if it exists with a > separator, and then always the rest of the line.-->
         <Property name="container-log-pattern">%d{yyyy-MM-dd'T'HH:mm:ss,SSS}{GMT+0}`%replace{%X{log_source}}{^ -}{} > %replace{%m}{$${env:LOG_SCRUB_PATTERN:-\*\*\*\*\*}}{*****}%n</Property>
         <!-- Always log INFO by default. -->
@@ -13,53 +13,48 @@
 
     <Appenders>
         <Console name="JvmLogsStdOut" target="SYSTEM_OUT">
-            <ContextMapFilter onMatch="DENY" onMismatch="ACCEPT">
-                <KeyValuePair key="simple" value="true"/>
-            </ContextMapFilter>
             <PatternLayout pattern="${jvm-log-pattern}"/>
         </Console>
-
         <Console name="ContainerLogsStdOut" target="SYSTEM_OUT">
-            <ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
-                <KeyValuePair key="simple" value="true"/>
-            </ContextMapFilter>
             <PatternLayout pattern="${container-log-pattern}"/>
         </Console>
-
         <File name="JvmLogsFile" fileName="${logDir}/airbyte_jvm.log">
-            <ContextMapFilter onMatch="DENY" onMismatch="ACCEPT">
+            <PatternLayout disableAnsi="true"  pattern="${jvm-log-pattern}"/>
-                <KeyValuePair key="simple" value="true"/>
-            </ContextMapFilter>
-            <PatternLayout pattern="${jvm-log-pattern}"/>
         </File>
         <File name="ContainerLogFiles" fileName="${logDir}/airbyte_containers.log">
-            <ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
+            <PatternLayout disableAnsi="true" pattern="${container-log-pattern}"/>
-                <KeyValuePair key="simple" value="true"/>
-            </ContextMapFilter>
-            <PatternLayout pattern="${container-log-pattern}"/>
         </File>
         <File name="UnifiedFile-JvmLogs" fileName="${logDir}/airbyte_unified.log">
-            <ContextMapFilter onMatch="DENY" onMismatch="ACCEPT">
-                <KeyValuePair key="simple" value="true"/>
-            </ContextMapFilter>
             <PatternLayout pattern="${jvm-log-pattern}"/>
         </File>
         <File name="UnifiedFile-ContainerLogs" fileName="${logDir}/airbyte_unified.log">
-            <ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
-                <KeyValuePair key="simple" value="true"/>
-            </ContextMapFilter>
             <PatternLayout pattern="${container-log-pattern}"/>
         </File>
+
+        <ASync name="JvmLogs" includeLocation="true">
+            <AppenderRef ref="JvmLogsStdOut"/>
+            <AppenderRef ref="JvmLogsFile"/>
+            <AppenderRef ref="UnifiedFile-JvmLogs"/>
+        </ASync>
+        <ASync name="ContainerLogs">
+            <AppenderRef ref="ContainerLogsStdOut"/>
+            <AppenderRef ref="ContainerLogFiles"/>
+            <AppenderRef ref="UnifiedFile-ContainerLogs"/>
+        </ASync>
+
+        <Routing name="AllLogs">
+            <Routes pattern="$${ctx:simple}">
+                <Route key="true" ref="ContainerLogs">
+                </Route>
+                <Route ref="JvmLogs">
+                </Route>
+            </Routes>
+        </Routing>
     </Appenders>
 
     <Loggers>
         <Root level="${log-level}">
-            <AppenderRef ref="JvmLogsStdOut"/>
+            <AppenderRef ref="AllLogs"/>
-            <AppenderRef ref="ContainerLogsStdOut"/>
-            <AppenderRef ref="JvmLogsFile"/>
-            <AppenderRef ref="ContainerLogFiles"/>
-            <AppenderRef ref="UnifiedFile-JvmLogs"/>
-            <AppenderRef ref="UnifiedFile-ContainerLogs"/>
         </Root>
 
         <Logger name="org.eclipse.jetty" level="INFO" />

build.gradle

@@ -104,6 +104,7 @@ allprojects {
         systemProperty 'junit.jupiter.execution.parallel.config.fixed.parallelism', 1
         // Order test classes by annotation.
         systemProperty 'junit.jupiter.testclass.order.default', 'org.junit.jupiter.api.ClassOrderer$OrderAnnotation'
+        systemProperty 'junit.jupiter.extensions.autodetection.enabled', 'true'
 
         if (!project.hasProperty('testExecutionConcurrency')) {
             // By default, let gradle spawn as many independent workers as it wants.