Skip to content

Commit aff4e0d

Browse files
stephane-airbytestephane-airbyte
committed
add proper logging to junit runs
1 parent 820c392 commit aff4e0d

File tree

6 files changed

+167
-31
lines changed

6 files changed

+167
-31
lines changed

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

Lines changed: 136 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,136 @@
1+
package io.airbyte.cdk.extensions;
2+
3+
import java.io.PrintWriter;
4+
import java.io.StringWriter;
5+
import java.io.Writer;
6+
import java.lang.reflect.Constructor;
7+
import java.lang.reflect.InvocationHandler;
8+
import java.lang.reflect.Method;
9+
import java.lang.reflect.Proxy;
10+
import java.util.Arrays;
11+
import java.util.StringJoiner;
12+
import java.util.stream.Collectors;
13+
import org.apache.commons.lang3.StringUtils;
14+
import org.apache.commons.lang3.builder.ToStringBuilder;
15+
import org.apache.commons.lang3.exception.ExceptionUtils;
16+
import org.junit.jupiter.api.extension.DynamicTestInvocationContext;
17+
import org.junit.jupiter.api.extension.ExtensionContext;
18+
import org.junit.jupiter.api.extension.InvocationInterceptor;
19+
import org.junit.jupiter.api.extension.ReflectiveInvocationContext;
20+
import org.slf4j.Logger;
21+
import org.slf4j.LoggerFactory;
22+
23+
/**
24+
* This allows us to have junit loglines in our test logs.
25+
* This is instanciated via Java's ServiceLoader (https://docs.oracle.com/javase%2F9%2Fdocs%2Fapi%2F%2F/java/util/ServiceLoader.html)
26+
* The declaration can be found in resources/META-INF/services/org.junit.jupiter.api.extension.Extension
27+
*/
28+
public class LoggingInvocationInterceptor implements InvocationInterceptor {
29+
private static final class LoggingInvocationInterceptorHandler implements InvocationHandler {
30+
private static Logger LOGGER = LoggerFactory.getLogger(LoggingInvocationInterceptor.class);
31+
@Override
32+
public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
33+
if (LoggingInvocationInterceptor.class.getDeclaredMethod(method.getName(), Invocation.class, ReflectiveInvocationContext.class, ExtensionContext.class) == null) {
34+
LOGGER.error("Junit LoggingInvocationInterceptor executing unkown interception point " + method.getName());
35+
return method.invoke(proxy, args);
36+
}
37+
Invocation<?> invocation= (Invocation<?>)args[0];
38+
ReflectiveInvocationContext<Method> invocationContext = (ReflectiveInvocationContext<Method>)args[1];
39+
ExtensionContext extensionContext = (ExtensionContext) args[2];
40+
String methodName = method.getName();
41+
String logLineSuffix;
42+
if (methodName.equals("interceptDynamicTest")) {
43+
logLineSuffix = "execution of DynamicTest " + extensionContext.getDisplayName();
44+
} else if (methodName.equals("interceptTestClassConstructor")) {
45+
logLineSuffix = "instance creation for " + invocationContext.getTargetClass();
46+
} else if (methodName.startsWith("intercept") && methodName.endsWith("Method")) {
47+
String interceptedEvent = methodName.substring("intercept".length(), methodName.length() - "Method".length());
48+
logLineSuffix = "execution of @" + interceptedEvent + " method " + invocationContext.getExecutable().getDeclaringClass().getSimpleName()
49+
+ "." + invocationContext.getExecutable().getName();
50+
} else {
51+
logLineSuffix = "execution of unknown intercepted call " + methodName;
52+
}
53+
LOGGER.info("Junit starting " + logLineSuffix);
54+
try {
55+
long start = System.nanoTime();
56+
Object retVal = invocation.proceed();
57+
long elapsedMs = (System.nanoTime() - start)/1_000_000;
58+
LOGGER.info("Junit completed " + logLineSuffix + " in " + elapsedMs + "ms");
59+
return retVal;
60+
} catch (Throwable t) {
61+
String stackTrace = Arrays.stream(ExceptionUtils.getStackFrames(t)).takeWhile(s->!s.startsWith("\tat org.junit")).collect(
62+
Collectors.joining("\n "));
63+
LOGGER.warn("Junit exception throw during " + logLineSuffix + ":\n" + stackTrace);
64+
throw t;
65+
}
66+
}
67+
}
68+
69+
private final InvocationInterceptor proxy = (InvocationInterceptor) Proxy.newProxyInstance(
70+
getClass().getClassLoader(),
71+
new Class[] {InvocationInterceptor.class },
72+
new LoggingInvocationInterceptorHandler());
73+
74+
@Override
75+
public void interceptAfterAllMethod(Invocation<Void> invocation,
76+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
77+
throws Throwable {
78+
proxy.interceptAfterAllMethod(invocation, invocationContext, extensionContext);
79+
}
80+
81+
@Override
82+
public void interceptAfterEachMethod(Invocation<Void> invocation,
83+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
84+
throws Throwable {
85+
proxy.interceptAfterEachMethod(invocation, invocationContext, extensionContext);
86+
}
87+
88+
@Override
89+
public void interceptBeforeAllMethod(Invocation<Void> invocation,
90+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
91+
throws Throwable {
92+
proxy.interceptBeforeAllMethod(invocation, invocationContext, extensionContext);
93+
}
94+
95+
@Override
96+
public void interceptBeforeEachMethod(Invocation<Void> invocation,
97+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
98+
throws Throwable {
99+
proxy.interceptBeforeEachMethod(invocation, invocationContext, extensionContext);
100+
}
101+
102+
@Override
103+
public void interceptDynamicTest(Invocation<Void> invocation,
104+
DynamicTestInvocationContext invocationContext, ExtensionContext extensionContext)
105+
throws Throwable {
106+
proxy.interceptDynamicTest(invocation, invocationContext, extensionContext);
107+
}
108+
109+
@Override
110+
public void interceptTestMethod(Invocation<Void> invocation,
111+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
112+
throws Throwable {
113+
proxy.interceptTestMethod(invocation, invocationContext, extensionContext);
114+
}
115+
116+
@Override
117+
public void interceptTestTemplateMethod(Invocation<Void> invocation,
118+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
119+
throws Throwable {
120+
proxy.interceptTestTemplateMethod(invocation, invocationContext, extensionContext);
121+
}
122+
123+
@Override
124+
public <T> T interceptTestFactoryMethod(Invocation<T> invocation,
125+
ReflectiveInvocationContext<Method> invocationContext, ExtensionContext extensionContext)
126+
throws Throwable {
127+
return proxy.interceptTestFactoryMethod(invocation, invocationContext, extensionContext);
128+
}
129+
130+
@Override
131+
public <T> T interceptTestClassConstructor(Invocation<T> invocation,
132+
ReflectiveInvocationContext<Constructor<T>> invocationContext,
133+
ExtensionContext extensionContext) throws Throwable {
134+
return proxy.interceptTestClassConstructor(invocation, invocationContext, extensionContext);
135+
}
136+
}

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

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -117,7 +117,9 @@ private GenericContainer<?> createAndStartContainer(DockerImageName imageName, L
117117
}
118118
final var logConsumer = new Slf4jLogConsumer(LOGGER) {
119119
public void accept(OutputFrame frame) {
120-
super.accept(frame);
120+
if (frame.getUtf8StringWithoutLineEnding().trim().length() > 0) {
121+
super.accept(frame);
122+
}
121123
}
122124
};
123125
getTestContainerLogMdcBuilder(imageName, methodNames, containerId.getAndIncrement(), container.getContainerId()).produceMappings(logConsumer::withMdc);

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
io.airbyte.cdk.extensions.LoggingInvocationInterceptor

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -41,9 +41,10 @@ public String getCode() {
4141

4242
@VisibleForTesting
4343
public static final String RESET = "\u001B[0m";
44+
public static final String PREPARE_COLOR_CHAR = "\u001b[m";
4445

4546
public static String applyColor(final Color color, final String msg) {
46-
return color.getCode() + msg + RESET;
47+
return PREPARE_COLOR_CHAR + color.getCode() + msg + PREPARE_COLOR_CHAR + RESET;
4748
}
4849

4950
}

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

Lines changed: 24 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -2,9 +2,9 @@
22
<Configuration status="INFO">
33
<Properties>
44
<!-- Set the LOG_SCRUB_PATTERN env var to a regex pattern to scrub the log messages of secrets or any other unwanted content. -->
5-
<Property name="jvm-log-pattern">%d{yyyy-MM-dd'T'HH:mm:ss,SSS}{GMT+0}`%highlight{%p}`%C{1.}(%M):%L - %replace{%m}{$${env:LOG_SCRUB_PATTERN:-\*\*\*\*\*}}{*****}%n</Property>
5+
<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>
66
<!--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.-->
7-
<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>
7+
<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>
88
<!-- Always log INFO by default. -->
99
<Property name="log-level">${sys:LOG_LEVEL:-${env:LOG_LEVEL:-INFO}}</Property>
1010
<Property name="logSubDir">${env:AIRBYTE_LOG_SUBDIR:-${date:yyyy-MM-dd'T'HH:mm:ss}}</Property>
@@ -13,53 +13,48 @@
1313

1414
<Appenders>
1515
<Console name="JvmLogsStdOut" target="SYSTEM_OUT">
16-
<ContextMapFilter onMatch="DENY" onMismatch="ACCEPT">
17-
<KeyValuePair key="simple" value="true"/>
18-
</ContextMapFilter>
1916
<PatternLayout pattern="${jvm-log-pattern}"/>
2017
</Console>
21-
2218
<Console name="ContainerLogsStdOut" target="SYSTEM_OUT">
23-
<ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
24-
<KeyValuePair key="simple" value="true"/>
25-
</ContextMapFilter>
2619
<PatternLayout pattern="${container-log-pattern}"/>
2720
</Console>
28-
2921
<File name="JvmLogsFile" fileName="${logDir}/airbyte_jvm.log">
30-
<ContextMapFilter onMatch="DENY" onMismatch="ACCEPT">
31-
<KeyValuePair key="simple" value="true"/>
32-
</ContextMapFilter>
33-
<PatternLayout pattern="${jvm-log-pattern}"/>
22+
<PatternLayout disableAnsi="true" pattern="${jvm-log-pattern}"/>
3423
</File>
3524
<File name="ContainerLogFiles" fileName="${logDir}/airbyte_containers.log">
36-
<ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
37-
<KeyValuePair key="simple" value="true"/>
38-
</ContextMapFilter>
39-
<PatternLayout pattern="${container-log-pattern}"/>
25+
<PatternLayout disableAnsi="true" pattern="${container-log-pattern}"/>
4026
</File>
4127
<File name="UnifiedFile-JvmLogs" fileName="${logDir}/airbyte_unified.log">
42-
<ContextMapFilter onMatch="DENY" onMismatch="ACCEPT">
43-
<KeyValuePair key="simple" value="true"/>
44-
</ContextMapFilter>
4528
<PatternLayout pattern="${jvm-log-pattern}"/>
4629
</File>
4730
<File name="UnifiedFile-ContainerLogs" fileName="${logDir}/airbyte_unified.log">
48-
<ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
49-
<KeyValuePair key="simple" value="true"/>
50-
</ContextMapFilter>
5131
<PatternLayout pattern="${container-log-pattern}"/>
5232
</File>
53-
</Appenders>
5433

55-
<Loggers>
56-
<Root level="${log-level}">
34+
<ASync name="JvmLogs" includeLocation="true">
5735
<AppenderRef ref="JvmLogsStdOut"/>
58-
<AppenderRef ref="ContainerLogsStdOut"/>
5936
<AppenderRef ref="JvmLogsFile"/>
60-
<AppenderRef ref="ContainerLogFiles"/>
6137
<AppenderRef ref="UnifiedFile-JvmLogs"/>
38+
</ASync>
39+
<ASync name="ContainerLogs">
40+
<AppenderRef ref="ContainerLogsStdOut"/>
41+
<AppenderRef ref="ContainerLogFiles"/>
6242
<AppenderRef ref="UnifiedFile-ContainerLogs"/>
43+
</ASync>
44+
45+
<Routing name="AllLogs">
46+
<Routes pattern="$${ctx:simple}">
47+
<Route key="true" ref="ContainerLogs">
48+
</Route>
49+
<Route ref="JvmLogs">
50+
</Route>
51+
</Routes>
52+
</Routing>
53+
</Appenders>
54+
55+
<Loggers>
56+
<Root level="${log-level}">
57+
<AppenderRef ref="AllLogs"/>
6358
</Root>
6459

6560
<Logger name="org.eclipse.jetty" level="INFO" />

‎build.gradle

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,7 @@ allprojects {
104104
systemProperty 'junit.jupiter.execution.parallel.config.fixed.parallelism', 1
105105
// Order test classes by annotation.
106106
systemProperty 'junit.jupiter.testclass.order.default', 'org.junit.jupiter.api.ClassOrderer$OrderAnnotation'
107+
systemProperty 'junit.jupiter.extensions.autodetection.enabled', 'true'
107108

108109
if (!project.hasProperty('testExecutionConcurrency')) {
109110
// By default, let gradle spawn as many independent workers as it wants.

0 commit comments

Comments
 (0)