forked from airbytehq/airbyte
-
Notifications
You must be signed in to change notification settings - Fork 1
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
add proper logging to junit runs (airbytehq#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.
- Loading branch information
1 parent
ad4e381
commit f4634d2
Showing
9 changed files
with
228 additions
and
59 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
2 changes: 1 addition & 1 deletion
2
airbyte-cdk/java/airbyte-cdk/core/src/main/resources/version.properties
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1 +1 @@ | ||
| version=0.21.2 | ||
| version=0.21.3 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
160 changes: 160 additions & 0 deletions
160
...dk/core/src/testFixtures/java/io/airbyte/cdk/extensions/LoggingInvocationInterceptor.java
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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); | ||
| } | ||
|
|
||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
1 change: 1 addition & 0 deletions
1
...re/src/testFixtures/resources/META-INF/services/org.junit.jupiter.api.extension.Extension
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1 @@ | ||
| io.airbyte.cdk.extensions.LoggingInvocationInterceptor |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.