Skip to content

Commit

Permalink
add proper logging to junit runs
Browse files Browse the repository at this point in the history
  • Loading branch information
stephane-airbyte committed Feb 18, 2024
1 parent 261ccaa commit ddea01a
Show file tree
Hide file tree
Showing 6 changed files with 161 additions and 31 deletions.
Original file line number Diff line number Diff line change
@@ -0,0 +1,130 @@
package io.airbyte.cdk.extensions;

import java.io.PrintWriter;
import java.io.StringWriter;
import java.io.Writer;
import java.lang.reflect.Constructor;
import java.lang.reflect.InvocationHandler;
import java.lang.reflect.Method;
import java.lang.reflect.Proxy;
import java.util.Arrays;
import java.util.StringJoiner;
import java.util.stream.Collectors;
import org.apache.commons.lang3.StringUtils;
import org.apache.commons.lang3.builder.ToStringBuilder;
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;

/**
* This allows us to have junit loglines in our test logs.
* This is instanciated via Java's ServiceLoader (https://docs.oracle.com/javase%2F9%2Fdocs%2Fapi%2F%2F/java/util/ServiceLoader.html)
* 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 Logger LOGGER = LoggerFactory.getLogger(LoggingInvocationInterceptor.class);
@Override
public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
Invocation<?> invocation= (Invocation<?>)args[0];
ReflectiveInvocationContext<Method> invocationContext = (ReflectiveInvocationContext<Method>)args[1];
ExtensionContext extensionContext = (ExtensionContext) args[2];
String methodName = method.getName();
String logLineSuffix;
if (methodName.equals("interceptDynamicTest")) {
logLineSuffix = "execution of DynamicTest " + extensionContext.getDisplayName();
} else if (methodName.equals("interceptTestClassConstructor")) {
logLineSuffix = "instance creation for " + invocationContext.getTargetClass();
} else {
String interceptedEvent = methodName.substring("intercept".length(), methodName.length() - "Method".length());
logLineSuffix = "execution of @" + interceptedEvent + " method " + invocationContext.getExecutable().getDeclaringClass().getSimpleName()
+ "." + invocationContext.getExecutable().getName();
}
LOGGER.info("Junit starting " + logLineSuffix);
try {
long start = System.nanoTime();
Object retVal = invocation.proceed();
long elapsedMs = (System.nanoTime() - start)/1_000_000;
LOGGER.info("Junit completed " + logLineSuffix + " in " + elapsedMs + "ms");
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 " + logLineSuffix + ":\n" + 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);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -117,7 +117,9 @@ private GenericContainer<?> createAndStartContainer(DockerImageName imageName, L
}
final var logConsumer = new Slf4jLogConsumer(LOGGER) {
public void accept(OutputFrame frame) {
super.accept(frame);
if (frame.getUtf8StringWithoutLineEnding().trim().length() > 0) {
super.accept(frame);
}
}
};
getTestContainerLogMdcBuilder(imageName, methodNames, containerId.getAndIncrement(), container.getContainerId()).produceMappings(logConsumer::withMdc);
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
io.airbyte.cdk.extensions.LoggingInvocationInterceptor
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

}
Original file line number Diff line number Diff line change
Expand Up @@ -2,9 +2,9 @@
<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}`%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>
<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. -->
<Property name="log-level">${sys:LOG_LEVEL:-${env:LOG_LEVEL:-INFO}}</Property>
<Property name="logSubDir">${env:AIRBYTE_LOG_SUBDIR:-${date:yyyy-MM-dd'T'HH:mm:ss}}</Property>
Expand All @@ -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">
<KeyValuePair key="simple" value="true"/>
</ContextMapFilter>
<PatternLayout pattern="${jvm-log-pattern}"/>
<PatternLayout disableAnsi="true" pattern="${jvm-log-pattern}"/>
</File>
<File name="ContainerLogFiles" fileName="${logDir}/airbyte_containers.log">
<ContextMapFilter onMatch="ACCEPT" onMismatch="DENY">
<KeyValuePair key="simple" value="true"/>
</ContextMapFilter>
<PatternLayout pattern="${container-log-pattern}"/>
<PatternLayout disableAnsi="true" 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>
</Appenders>

<Loggers>
<Root level="${log-level}">
<ASync name="JvmLogs" includeLocation="true">
<AppenderRef ref="JvmLogsStdOut"/>
<AppenderRef ref="ContainerLogsStdOut"/>
<AppenderRef ref="JvmLogsFile"/>
<AppenderRef ref="ContainerLogFiles"/>
<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="AllLogs"/>
</Root>

<Logger name="org.eclipse.jetty" level="INFO" />
Expand Down
1 change: 1 addition & 0 deletions build.gradle
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down

0 comments on commit ddea01a

Please sign in to comment.