diff --git a/airbyte-cdk/java/airbyte-cdk/README.md b/airbyte-cdk/java/airbyte-cdk/README.md index 6bed59ec00cc..c3c8979e897b 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 ef875ad6ca30..177f844ea34a 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 8e9b91c939f8..50307ebd1890 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 000000000000..6ccaf15a1255 --- /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 932a7dda3ac0..6c0b8e40e89f 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 000000000000..90378b469448 --- /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 e351ca2eff44..d9cca1b78089 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 067f667f6854..5fa11880cfba 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 befdc9deaa13..3d13e5f7b2d5 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.