|
| 1 | +/* |
| 2 | + * Copyright (c) 2023 Airbyte, Inc., all rights reserved. |
| 3 | + */ |
| 4 | + |
| 5 | +package io.airbyte.cdk.extensions; |
| 6 | + |
| 7 | +import java.lang.reflect.Constructor; |
| 8 | +import java.lang.reflect.InvocationHandler; |
| 9 | +import java.lang.reflect.Method; |
| 10 | +import java.lang.reflect.Proxy; |
| 11 | +import java.time.Duration; |
| 12 | +import java.time.Instant; |
| 13 | +import java.util.Arrays; |
| 14 | +import java.util.regex.Matcher; |
| 15 | +import java.util.regex.Pattern; |
| 16 | +import java.util.stream.Collectors; |
| 17 | +import org.apache.commons.lang3.exception.ExceptionUtils; |
| 18 | +import org.junit.jupiter.api.extension.DynamicTestInvocationContext; |
| 19 | +import org.junit.jupiter.api.extension.ExtensionContext; |
| 20 | +import org.junit.jupiter.api.extension.InvocationInterceptor; |
| 21 | +import org.junit.jupiter.api.extension.ReflectiveInvocationContext; |
| 22 | +import org.slf4j.Logger; |
| 23 | +import org.slf4j.LoggerFactory; |
| 24 | + |
| 25 | +/** |
| 26 | + * By default, junit only output logs to the console, and nothing makes it into log4j logs. This |
| 27 | + * class fixes that by using the interceptor facility to print progress and timing information. This |
| 28 | + * allows us to have junit loglines in our test logs. This is instanciated via <a href= |
| 29 | + * "https://docs.oracle.com/javase%2F9%2Fdocs%2Fapi%2F%2F/java/util/ServiceLoader.html">Java's |
| 30 | + * ServiceLoader</a> The declaration can be found in |
| 31 | + * resources/META-INF/services/org.junit.jupiter.api.extension.Extension |
| 32 | + */ |
| 33 | +public class LoggingInvocationInterceptor implements InvocationInterceptor { |
| 34 | + |
| 35 | + private static final class LoggingInvocationInterceptorHandler implements InvocationHandler { |
| 36 | + |
| 37 | + private static final Logger LOGGER = LoggerFactory.getLogger(LoggingInvocationInterceptor.class); |
| 38 | + |
| 39 | + private static final Pattern methodPattern = Pattern.compile("intercept(.*)Method"); |
| 40 | + |
| 41 | + @Override |
| 42 | + @SuppressWarnings("unchecked") |
| 43 | + public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { |
| 44 | + if (LoggingInvocationInterceptor.class.getDeclaredMethod(method.getName(), Invocation.class, ReflectiveInvocationContext.class, |
| 45 | + ExtensionContext.class) == null) { |
| 46 | + LOGGER.error("Junit LoggingInvocationInterceptor executing unknown interception point {}", method.getName()); |
| 47 | + return method.invoke(proxy, args); |
| 48 | + } |
| 49 | + var invocation = (Invocation<?>) args[0]; |
| 50 | + var invocationContext = (ReflectiveInvocationContext<Method>) args[1]; |
| 51 | + var extensionContext = (ExtensionContext) args[2]; |
| 52 | + String methodName = method.getName(); |
| 53 | + String logLineSuffix; |
| 54 | + Matcher methodMatcher = methodPattern.matcher(methodName); |
| 55 | + if (methodName.equals("interceptDynamicTest")) { |
| 56 | + logLineSuffix = "execution of DynamicTest %s".formatted(extensionContext.getDisplayName()); |
| 57 | + } else if (methodName.equals("interceptTestClassConstructor")) { |
| 58 | + logLineSuffix = "instance creation for %s".formatted(invocationContext.getTargetClass()); |
| 59 | + } else if (methodMatcher.matches()) { |
| 60 | + String interceptedEvent = methodMatcher.group(1); |
| 61 | + logLineSuffix = "execution of @%s method %s.%s".formatted(invocationContext.getExecutable().getDeclaringClass().getSimpleName(), |
| 62 | + interceptedEvent, invocationContext.getExecutable().getName()); |
| 63 | + } else { |
| 64 | + logLineSuffix = "execution of unknown intercepted call %s".formatted(methodName); |
| 65 | + } |
| 66 | + LOGGER.info("Junit starting {}", logLineSuffix); |
| 67 | + try { |
| 68 | + Instant start = Instant.now(); |
| 69 | + Object retVal = invocation.proceed(); |
| 70 | + long elapsedMs = Duration.between(start, Instant.now()).toMillis(); |
| 71 | + LOGGER.info("Junit completed {} in {} ms", logLineSuffix, elapsedMs); |
| 72 | + return retVal; |
| 73 | + } catch (Throwable t) { |
| 74 | + String stackTrace = Arrays.stream(ExceptionUtils.getStackFrames(t)).takeWhile(s -> !s.startsWith("\tat org.junit")).collect( |
| 75 | + Collectors.joining("\n ")); |
| 76 | + LOGGER.warn("Junit exception throw during {}:\n{}", logLineSuffix, stackTrace); |
| 77 | + throw t; |
| 78 | + } |
| 79 | + } |
| 80 | + |
| 81 | + } |
| 82 | + |
| 83 | + private final InvocationInterceptor proxy = (InvocationInterceptor) Proxy.newProxyInstance( |
| 84 | + getClass().getClassLoader(), |
| 85 | + new Class[] {InvocationInterceptor.class}, |
| 86 | + new LoggingInvocationInterceptorHandler()); |
| 87 | + |
| 88 | + @Override |
| 89 | + public void interceptAfterAllMethod(Invocation<Void> invocation, |
| 90 | + ReflectiveInvocationContext<Method> invocationContext, |
| 91 | + ExtensionContext extensionContext) |
| 92 | + throws Throwable { |
| 93 | + proxy.interceptAfterAllMethod(invocation, invocationContext, extensionContext); |
| 94 | + } |
| 95 | + |
| 96 | + @Override |
| 97 | + public void interceptAfterEachMethod(Invocation<Void> invocation, |
| 98 | + ReflectiveInvocationContext<Method> invocationContext, |
| 99 | + ExtensionContext extensionContext) |
| 100 | + throws Throwable { |
| 101 | + proxy.interceptAfterEachMethod(invocation, invocationContext, extensionContext); |
| 102 | + } |
| 103 | + |
| 104 | + @Override |
| 105 | + public void interceptBeforeAllMethod(Invocation<Void> invocation, |
| 106 | + ReflectiveInvocationContext<Method> invocationContext, |
| 107 | + ExtensionContext extensionContext) |
| 108 | + throws Throwable { |
| 109 | + proxy.interceptBeforeAllMethod(invocation, invocationContext, extensionContext); |
| 110 | + } |
| 111 | + |
| 112 | + @Override |
| 113 | + public void interceptBeforeEachMethod(Invocation<Void> invocation, |
| 114 | + ReflectiveInvocationContext<Method> invocationContext, |
| 115 | + ExtensionContext extensionContext) |
| 116 | + throws Throwable { |
| 117 | + proxy.interceptBeforeEachMethod(invocation, invocationContext, extensionContext); |
| 118 | + } |
| 119 | + |
| 120 | + @Override |
| 121 | + public void interceptDynamicTest(Invocation<Void> invocation, |
| 122 | + DynamicTestInvocationContext invocationContext, |
| 123 | + ExtensionContext extensionContext) |
| 124 | + throws Throwable { |
| 125 | + proxy.interceptDynamicTest(invocation, invocationContext, extensionContext); |
| 126 | + } |
| 127 | + |
| 128 | + @Override |
| 129 | + public void interceptTestMethod(Invocation<Void> invocation, |
| 130 | + ReflectiveInvocationContext<Method> invocationContext, |
| 131 | + ExtensionContext extensionContext) |
| 132 | + throws Throwable { |
| 133 | + proxy.interceptTestMethod(invocation, invocationContext, extensionContext); |
| 134 | + } |
| 135 | + |
| 136 | + @Override |
| 137 | + public void interceptTestTemplateMethod(Invocation<Void> invocation, |
| 138 | + ReflectiveInvocationContext<Method> invocationContext, |
| 139 | + ExtensionContext extensionContext) |
| 140 | + throws Throwable { |
| 141 | + proxy.interceptTestTemplateMethod(invocation, invocationContext, extensionContext); |
| 142 | + } |
| 143 | + |
| 144 | + @Override |
| 145 | + public <T> T interceptTestFactoryMethod(Invocation<T> invocation, |
| 146 | + ReflectiveInvocationContext<Method> invocationContext, |
| 147 | + ExtensionContext extensionContext) |
| 148 | + throws Throwable { |
| 149 | + return proxy.interceptTestFactoryMethod(invocation, invocationContext, extensionContext); |
| 150 | + } |
| 151 | + |
| 152 | + @Override |
| 153 | + public <T> T interceptTestClassConstructor(Invocation<T> invocation, |
| 154 | + ReflectiveInvocationContext<Constructor<T>> invocationContext, |
| 155 | + ExtensionContext extensionContext) |
| 156 | + throws Throwable { |
| 157 | + return proxy.interceptTestClassConstructor(invocation, invocationContext, extensionContext); |
| 158 | + } |
| 159 | + |
| 160 | +} |
0 commit comments