From 21aa4823f48e60f63154841232ed4625aad20c93 Mon Sep 17 00:00:00 2001 From: Stephane Geneix <147216312+stephane-airbyte@users.noreply.github.com> Date: Tue, 20 Feb 2024 13:25:23 -0800 Subject: [PATCH] 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 | 1 + .../src/main/resources/version.properties | 2 +- .../base/AirbyteLogMessageTemplateTest.java | 42 +++-- .../LoggingInvocationInterceptor.java | 160 ++++++++++++++++++ .../cdk/testutils/ContainerFactory.java | 24 ++- .../org.junit.jupiter.api.extension.Extension | 1 + .../commons/logging/LoggingHelper.java | 3 +- .../src/main/resources/log4j2-test.xml | 53 +++--- build.gradle | 1 + 9 files changed, 228 insertions(+), 59 deletions(-) create mode 100644 airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/extensions/LoggingInvocationInterceptor.java create mode 100644 airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/resources/META-INF/services/org.junit.jupiter.api.extension.Extension diff --git a/airbyte-cdk/java/airbyte-cdk/README.md b/airbyte-cdk/java/airbyte-cdk/README.md index 6bed59ec00ccf..c3c8979e897b3 100644 --- a/airbyte-cdk/java/airbyte-cdk/README.md +++ b/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. | diff --git a/airbyte-cdk/java/airbyte-cdk/core/src/main/resources/version.properties b/airbyte-cdk/java/airbyte-cdk/core/src/main/resources/version.properties index ef875ad6ca301..177f844ea34a1 100644 --- a/airbyte-cdk/java/airbyte-cdk/core/src/main/resources/version.properties +++ b/airbyte-cdk/java/airbyte-cdk/core/src/main/resources/version.properties @@ -1 +1 @@ -version=0.21.2 +version=0.21.3 diff --git a/airbyte-cdk/java/airbyte-cdk/core/src/test/java/io/airbyte/cdk/integrations/base/AirbyteLogMessageTemplateTest.java b/airbyte-cdk/java/airbyte-cdk/core/src/test/java/io/airbyte/cdk/integrations/base/AirbyteLogMessageTemplateTest.java index 8e9b91c939f80..50307ebd1890c 100644 --- a/airbyte-cdk/java/airbyte-cdk/core/src/test/java/io/airbyte/cdk/integrations/base/AirbyteLogMessageTemplateTest.java +++ b/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.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.junit.jupiter.api.BeforeAll; -import org.junit.jupiter.api.BeforeEach; +import org.apache.logging.log4j.spi.ExtendedLogger; +import org.junit.jupiter.api.AfterEach; 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 static LoggerConfig rootLoggerConfig; - private static LoggerContext loggerContext; + private LoggerContext loggerContext; + private LoggerConfig rootLoggerConfig; + private ExtendedLogger logger; + private OutputStreamAppender outputStreamAppender; + private ByteArrayOutputStream outputContent; - @BeforeAll - static void init() { + void getLogger() { // 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 - void setup() { - outputContent.reset(); - } - - @AfterAll - static void cleanUp() { + @AfterEach + void closeLogger() { outputStreamAppender.stop(); rootLoggerConfig.removeAppender(OUTPUT_STREAM_APPENDER); loggerContext.close(); @@ -77,7 +71,8 @@ static void cleanUp() { @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 @@ private AirbyteLogMessage validateAirbyteMessageIsLog(final AirbyteMessage airby @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); diff --git a/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/extensions/LoggingInvocationInterceptor.java b/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/extensions/LoggingInvocationInterceptor.java new file mode 100644 index 0000000000000..6ccaf15a1255f --- /dev/null +++ b/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 Java's + * ServiceLoader 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) 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 invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptAfterAllMethod(invocation, invocationContext, extensionContext); + } + + @Override + public void interceptAfterEachMethod(Invocation invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptAfterEachMethod(invocation, invocationContext, extensionContext); + } + + @Override + public void interceptBeforeAllMethod(Invocation invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptBeforeAllMethod(invocation, invocationContext, extensionContext); + } + + @Override + public void interceptBeforeEachMethod(Invocation invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptBeforeEachMethod(invocation, invocationContext, extensionContext); + } + + @Override + public void interceptDynamicTest(Invocation invocation, + DynamicTestInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptDynamicTest(invocation, invocationContext, extensionContext); + } + + @Override + public void interceptTestMethod(Invocation invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptTestMethod(invocation, invocationContext, extensionContext); + } + + @Override + public void interceptTestTemplateMethod(Invocation invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + proxy.interceptTestTemplateMethod(invocation, invocationContext, extensionContext); + } + + @Override + public T interceptTestFactoryMethod(Invocation invocation, + ReflectiveInvocationContext invocationContext, + ExtensionContext extensionContext) + throws Throwable { + return proxy.interceptTestFactoryMethod(invocation, invocationContext, extensionContext); + } + + @Override + public T interceptTestClassConstructor(Invocation invocation, + ReflectiveInvocationContext> invocationContext, + ExtensionContext extensionContext) + throws Throwable { + return proxy.interceptTestClassConstructor(invocation, invocationContext, extensionContext); + } + +} diff --git a/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/testutils/ContainerFactory.java b/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/testutils/ContainerFactory.java index 932a7dda3ac05..6c0b8e40e89f1 100644 --- a/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/testutils/ContainerFactory.java +++ b/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/java/io/airbyte/cdk/testutils/ContainerFactory.java @@ -12,12 +12,15 @@ 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 @@ GenericContainer container() { } private static final ConcurrentMap SHARED_CONTAINERS = new ConcurrentHashMap<>(); + private static final AtomicInteger containerId = new AtomicInteger(0); - private static final MdcScope.Builder TESTCONTAINER_LOG_MDC_BUILDER = new MdcScope.Builder() - .setLogPrefix("testcontainer") - .setPrefixColor(LoggingHelper.Color.RED_BACKGROUND); + private static final MdcScope.Builder getTestContainerLogMdcBuilder(DockerImageName imageName, List methods) { + 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 @@ private GenericContainer createAndStartContainer(DockerImageName imageName, L for (String methodName : methodNames) { methods.add(getClass().getMethod(methodName, container.getClass())); } - final var logConsumer = new Slf4jLogConsumer(LOGGER); - TESTCONTAINER_LOG_MDC_BUILDER.produceMappings(logConsumer::withMdc); + final var logConsumer = new Slf4jLogConsumer(LOGGER) { + + 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 {}.", diff --git a/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/resources/META-INF/services/org.junit.jupiter.api.extension.Extension b/airbyte-cdk/java/airbyte-cdk/core/src/testFixtures/resources/META-INF/services/org.junit.jupiter.api.extension.Extension new file mode 100644 index 0000000000000..90378b469448d --- /dev/null +++ b/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 \ No newline at end of file diff --git a/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/java/io/airbyte/commons/logging/LoggingHelper.java b/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/java/io/airbyte/commons/logging/LoggingHelper.java index e351ca2eff44b..d9cca1b780899 100644 --- a/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/java/io/airbyte/commons/logging/LoggingHelper.java +++ b/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/java/io/airbyte/commons/logging/LoggingHelper.java @@ -41,9 +41,10 @@ public String getCode() { @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; } } diff --git a/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/resources/log4j2-test.xml b/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/resources/log4j2-test.xml index 067f667f68547..5fa11880cfbaf 100644 --- a/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/resources/log4j2-test.xml +++ b/airbyte-cdk/java/airbyte-cdk/dependencies/src/main/resources/log4j2-test.xml @@ -2,9 +2,9 @@ - %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 + %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 - %d{yyyy-MM-dd'T'HH:mm:ss,SSS}{GMT+0}`%replace{ %X{log_source}}{^ -}{} > %replace{%m}{$${env:LOG_SCRUB_PATTERN:-\*\*\*\*\*}}{*****}%n + %d{yyyy-MM-dd'T'HH:mm:ss,SSS}{GMT+0}`%replace{%X{log_source}}{^ -}{} > %replace{%m}{$${env:LOG_SCRUB_PATTERN:-\*\*\*\*\*}}{*****}%n ${sys:LOG_LEVEL:-${env:LOG_LEVEL:-INFO}} ${env:AIRBYTE_LOG_SUBDIR:-${date:yyyy-MM-dd'T'HH:mm:ss}} @@ -13,53 +13,48 @@ - - - - - - - - - - - - + - - - - + - - - - - - - - - + - - + + + + + + + + + + + + + + + + + + + diff --git a/build.gradle b/build.gradle index befdc9deaa134..3d13e5f7b2d57 100644 --- a/build.gradle +++ b/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.