From e40e6859e4ebda7a27db15fd5c621656b1ac2fec Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Wed, 25 Jan 2023 15:38:08 -0800 Subject: [PATCH 1/3] Support slf4j to log4j2 --- .../javaagent/build.gradle.kts | 52 ++++- .../v2_17/Log4jAppenderInstrumentation.java | 36 ++++ .../appender/v2_17/Slf4jToLog4j2Test.java | 177 ++++++++++++++++++ .../appender/v2_17/Slf4jToLog4j2Test.java | 177 ++++++++++++++++++ .../logback/appender/v1_0/LogbackTest.java | 4 +- .../testing/AgentTestRunner.java | 8 +- 6 files changed, 448 insertions(+), 6 deletions(-) create mode 100644 instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java create mode 100644 instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts index 01814acaaa5b..82c4ddd8ac1d 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts @@ -26,12 +26,62 @@ dependencies { } tasks { + test { + filter { + excludeTestsMatching("Slf4jToLog4j2Test") + } + exclude("**/Slf4jToLog4j2Test.*") + } + val testAsync by registering(Test::class) { + filter { + excludeTestsMatching("Slf4jToLog4j2Test") + } jvmArgs("-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector") } - named("test") { + val testSlf4j1ToLog4j2 by registering(Test::class) { + filter { + includeTestsMatching("Slf4jToLog4j2Test") + } + include("**/Slf4jToLog4j2Test.*") + configurations { + testImplementation { + // need to exclude logback in order to test slf4j -> log4j2 + exclude(group = "ch.qos.logback", module = "logback-classic") + } + } + dependencies { + testImplementation("org.slf4j:slf4j-api") { + version { + strictly("1.5.8") + } + } + testImplementation("org.apache.logging.log4j:log4j-slf4j-impl:2.17.0") + } + } + + val testSlf4j2ToLog4j2 by registering(Test::class) { + filter { + includeTestsMatching("Slf4jToLog4j2Test") + } + configurations { + testImplementation { + // need to exclude logback in order to test slf4j -> log4j2 + exclude(group = "ch.qos.logback", module = "logback-classic") + } + } + dependencies { + // 2.19.0 is the first version of log4j-slf4j2-impl + testLibrary("org.apache.logging.log4j:log4j-core:2.19.0") + testImplementation("org.apache.logging.log4j:log4j-slf4j2-impl:2.19.0") + } + } + + check { dependsOn(testAsync) + dependsOn(testSlf4j1ToLog4j2) + dependsOn(testSlf4j2ToLog4j2) } } diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java index fe3d742bb42b..9e89793aef38 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java @@ -52,6 +52,17 @@ public void transform(TypeTransformer transformer) { .and(takesArgument(4, named("org.apache.logging.log4j.message.Message"))) .and(takesArgument(5, Throwable.class)), Log4jAppenderInstrumentation.class.getName() + "$LogAdvice"); + transformer.applyAdviceToMethod( + isMethod() + .and(isProtected().or(isPublic())) + .and(named("logMessage")) + .and(takesArguments(5)) + .and(takesArgument(0, String.class)) + .and(takesArgument(1, named("org.apache.logging.log4j.Level"))) + .and(takesArgument(2, named("org.apache.logging.log4j.Marker"))) + .and(takesArgument(3, named("org.apache.logging.log4j.message.Message"))) + .and(takesArgument(4, Throwable.class)), + Log4jAppenderInstrumentation.class.getName() + "$LogMessageAdvice"); } @SuppressWarnings("unused") @@ -78,4 +89,29 @@ public static void methodExit(@Advice.Local("otelCallDepth") CallDepth callDepth callDepth.decrementAndGet(); } } + + @SuppressWarnings("unused") + public static class LogMessageAdvice { + + @Advice.OnMethodEnter(suppress = Throwable.class) + public static void methodEnter( + @Advice.This Logger logger, + @Advice.Argument(1) Level level, + @Advice.Argument(2) Marker marker, + @Advice.Argument(3) Message message, + @Advice.Argument(4) Throwable t, + @Advice.Local("otelCallDepth") CallDepth callDepth) { + // need to track call depth across all loggers in order to avoid double capture when one + // logging framework delegates to another + callDepth = CallDepth.forClass(LoggerProvider.class); + if (callDepth.getAndIncrement() == 0) { + Log4jHelper.capture(logger, level, marker, message, t); + } + } + + @Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class) + public static void methodExit(@Advice.Local("otelCallDepth") CallDepth callDepth) { + callDepth.decrementAndGet(); + } + } } diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java new file mode 100644 index 000000000000..aab139b49fb9 --- /dev/null +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java @@ -0,0 +1,177 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.log4j.appender.v2_17; + +import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; + +import io.opentelemetry.api.common.AttributeKey; +import io.opentelemetry.api.logs.Severity; +import io.opentelemetry.instrumentation.testing.junit.AgentInstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.sdk.common.InstrumentationScopeInfo; +import io.opentelemetry.sdk.logs.data.LogRecordData; +import io.opentelemetry.semconv.trace.attributes.SemanticAttributes; +import java.util.stream.Stream; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; +import org.slf4j.Marker; +import org.slf4j.MarkerFactory; + +class Slf4jToLog4j2Test { + + @RegisterExtension + static final InstrumentationExtension testing = AgentInstrumentationExtension.create(); + + private static final Logger logger = LoggerFactory.getLogger("abc"); + + private static Stream provideParameters() { + return Stream.of( + Arguments.of(false, false), + Arguments.of(false, true), + Arguments.of(true, false), + Arguments.of(true, true)); + } + + @ParameterizedTest + @MethodSource("provideParameters") + public void test(boolean logException, boolean withParent) throws InterruptedException { + test(Logger::debug, Logger::debug, logException, withParent, null, null, null); + testing.clearData(); + test(Logger::info, Logger::info, logException, withParent, "abc", Severity.INFO, "INFO"); + testing.clearData(); + test(Logger::warn, Logger::warn, logException, withParent, "abc", Severity.WARN, "WARN"); + testing.clearData(); + test(Logger::error, Logger::error, logException, withParent, "abc", Severity.ERROR, "ERROR"); + testing.clearData(); + } + + private static void test( + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException, + boolean withParent, + String expectedLoggerName, + Severity expectedSeverity, + String expectedSeverityText) + throws InterruptedException { + + // when + if (withParent) { + testing.runWithSpan( + "parent", () -> performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException)); + } else { + performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException); + } + + // then + if (withParent) { + testing.waitForTraces(1); + } + + if (expectedSeverity != null) { + LogRecordData log = testing.waitForLogRecords(1).get(0); + assertThat(log) + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build()) + .hasSeverity(expectedSeverity) + .hasSeverityText(expectedSeverityText); + if (logException) { + assertThat(log) + .hasAttributesSatisfyingExactly( + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), + equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + SemanticAttributes.EXCEPTION_STACKTRACE, + v -> v.contains(Slf4jToLog4j2Test.class.getName()))); + } else { + assertThat(log) + .hasAttributesSatisfyingExactly( + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())); + } + + if (withParent) { + assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); + } else { + assertThat(log.getSpanContext().isValid()).isFalse(); + } + + } else { + Thread.sleep(500); // sleep a bit just to make sure no log is captured + assertThat(testing.logRecords()).isEmpty(); + } + } + + @Test + void testMdc() { + MDC.put("key1", "val1"); + MDC.put("key2", "val2"); + try { + logger.info("xyz: {}", 123); + } finally { + MDC.clear(); + } + + LogRecordData log = testing.waitForLogRecords(1).get(0); + assertThat(log) + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("log4j.context_data.key1"), "val1"), + equalTo(AttributeKey.stringKey("log4j.context_data.key2"), "val2"), + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())); + } + + @Test + public void testMarker() { + + String markerName = "aMarker"; + Marker marker = MarkerFactory.getMarker(markerName); + + logger.info(marker, "Message"); + + LogRecordData log = testing.waitForLogRecords(1).get(0); + assertThat(log) + .hasAttributesSatisfyingExactly( + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(AttributeKey.stringKey("log4j.marker"), markerName)); + } + + private static void performLogging( + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException) { + if (logException) { + twoArgLoggerMethod.call(logger, "xyz: {}", 123, new IllegalStateException("hello")); + } else { + oneArgLoggerMethod.call(logger, "xyz: {}", 123); + } + } + + @FunctionalInterface + interface OneArgLoggerMethod { + void call(Logger logger, String msg, Object arg); + } + + @FunctionalInterface + interface TwoArgLoggerMethod { + void call(Logger logger, String msg, Object arg1, Object arg2); + } +} diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java new file mode 100644 index 000000000000..aab139b49fb9 --- /dev/null +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java @@ -0,0 +1,177 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.log4j.appender.v2_17; + +import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; + +import io.opentelemetry.api.common.AttributeKey; +import io.opentelemetry.api.logs.Severity; +import io.opentelemetry.instrumentation.testing.junit.AgentInstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.sdk.common.InstrumentationScopeInfo; +import io.opentelemetry.sdk.logs.data.LogRecordData; +import io.opentelemetry.semconv.trace.attributes.SemanticAttributes; +import java.util.stream.Stream; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; +import org.slf4j.Marker; +import org.slf4j.MarkerFactory; + +class Slf4jToLog4j2Test { + + @RegisterExtension + static final InstrumentationExtension testing = AgentInstrumentationExtension.create(); + + private static final Logger logger = LoggerFactory.getLogger("abc"); + + private static Stream provideParameters() { + return Stream.of( + Arguments.of(false, false), + Arguments.of(false, true), + Arguments.of(true, false), + Arguments.of(true, true)); + } + + @ParameterizedTest + @MethodSource("provideParameters") + public void test(boolean logException, boolean withParent) throws InterruptedException { + test(Logger::debug, Logger::debug, logException, withParent, null, null, null); + testing.clearData(); + test(Logger::info, Logger::info, logException, withParent, "abc", Severity.INFO, "INFO"); + testing.clearData(); + test(Logger::warn, Logger::warn, logException, withParent, "abc", Severity.WARN, "WARN"); + testing.clearData(); + test(Logger::error, Logger::error, logException, withParent, "abc", Severity.ERROR, "ERROR"); + testing.clearData(); + } + + private static void test( + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException, + boolean withParent, + String expectedLoggerName, + Severity expectedSeverity, + String expectedSeverityText) + throws InterruptedException { + + // when + if (withParent) { + testing.runWithSpan( + "parent", () -> performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException)); + } else { + performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException); + } + + // then + if (withParent) { + testing.waitForTraces(1); + } + + if (expectedSeverity != null) { + LogRecordData log = testing.waitForLogRecords(1).get(0); + assertThat(log) + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build()) + .hasSeverity(expectedSeverity) + .hasSeverityText(expectedSeverityText); + if (logException) { + assertThat(log) + .hasAttributesSatisfyingExactly( + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), + equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + SemanticAttributes.EXCEPTION_STACKTRACE, + v -> v.contains(Slf4jToLog4j2Test.class.getName()))); + } else { + assertThat(log) + .hasAttributesSatisfyingExactly( + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())); + } + + if (withParent) { + assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); + } else { + assertThat(log.getSpanContext().isValid()).isFalse(); + } + + } else { + Thread.sleep(500); // sleep a bit just to make sure no log is captured + assertThat(testing.logRecords()).isEmpty(); + } + } + + @Test + void testMdc() { + MDC.put("key1", "val1"); + MDC.put("key2", "val2"); + try { + logger.info("xyz: {}", 123); + } finally { + MDC.clear(); + } + + LogRecordData log = testing.waitForLogRecords(1).get(0); + assertThat(log) + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("log4j.context_data.key1"), "val1"), + equalTo(AttributeKey.stringKey("log4j.context_data.key2"), "val2"), + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())); + } + + @Test + public void testMarker() { + + String markerName = "aMarker"; + Marker marker = MarkerFactory.getMarker(markerName); + + logger.info(marker, "Message"); + + LogRecordData log = testing.waitForLogRecords(1).get(0); + assertThat(log) + .hasAttributesSatisfyingExactly( + equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(AttributeKey.stringKey("log4j.marker"), markerName)); + } + + private static void performLogging( + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException) { + if (logException) { + twoArgLoggerMethod.call(logger, "xyz: {}", 123, new IllegalStateException("hello")); + } else { + oneArgLoggerMethod.call(logger, "xyz: {}", 123); + } + } + + @FunctionalInterface + interface OneArgLoggerMethod { + void call(Logger logger, String msg, Object arg); + } + + @FunctionalInterface + interface TwoArgLoggerMethod { + void call(Logger logger, String msg, Object arg1, Object arg2); + } +} diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java index 705ebda69bed..ff1dc7b9e1e6 100644 --- a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java +++ b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java @@ -121,9 +121,7 @@ private static void test( if (withParent) { testing.runWithSpan( "parent", - () -> { - performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException); - }); + () -> performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException)); } else { performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException); } diff --git a/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/AgentTestRunner.java b/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/AgentTestRunner.java index dab38d0a8ddb..553e9bab9138 100644 --- a/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/AgentTestRunner.java +++ b/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/AgentTestRunner.java @@ -26,8 +26,12 @@ */ public final class AgentTestRunner extends InstrumentationTestRunner { static { - LoggerUtils.setLevel(LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME), Level.WARN); - LoggerUtils.setLevel(LoggerFactory.getLogger("io.opentelemetry"), Level.DEBUG); + try { + LoggerUtils.setLevel(LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME), Level.WARN); + LoggerUtils.setLevel(LoggerFactory.getLogger("io.opentelemetry"), Level.DEBUG); + } catch (NoClassDefFoundError e) { + // this happens when excluding logback in order to test slf4j -> log4j2 + } } private static final AgentTestRunner INSTANCE = new AgentTestRunner(); From 1bafb72246da2d65da49c70496b99cf0c732dfcb Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Sat, 4 Feb 2023 15:20:53 -0800 Subject: [PATCH 2/3] Rework to work --- .../javaagent/build.gradle.kts | 74 +++----- ...oLog4j2Test.java => Slf4jToLog4jTest.java} | 4 +- .../appender/v2_17/Slf4jToLog4j2Test.java | 177 ------------------ 3 files changed, 26 insertions(+), 229 deletions(-) rename instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/{Slf4jToLog4j2Test.java => Slf4jToLog4jTest.java} (98%) delete mode 100644 instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts index 82c4ddd8ac1d..d570a2c09057 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts @@ -21,67 +21,34 @@ dependencies { testImplementation("org.awaitility:awaitility") + // this dependency is needed for the slf4j->log4j test + if (findProperty("testLatestDeps") as Boolean) { + testImplementation("org.apache.logging.log4j:log4j-slf4j2-impl:2.19.0") + } else { + // log4j 2.17 doesn't have an slf4j2 bridge + testImplementation("org.apache.logging.log4j:log4j-slf4j-impl:2.17.0") + testImplementation("org.slf4j:slf4j-api") { + version { + strictly("1.7.36") + } + } + } + // this is needed for the async logging test testImplementation("com.lmax:disruptor:3.4.2") } -tasks { - test { - filter { - excludeTestsMatching("Slf4jToLog4j2Test") - } - exclude("**/Slf4jToLog4j2Test.*") - } +tasks.withType().configureEach { + systemProperty("testLatestDeps", findProperty("testLatestDeps") as Boolean) +} +tasks { val testAsync by registering(Test::class) { - filter { - excludeTestsMatching("Slf4jToLog4j2Test") - } jvmArgs("-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector") } - val testSlf4j1ToLog4j2 by registering(Test::class) { - filter { - includeTestsMatching("Slf4jToLog4j2Test") - } - include("**/Slf4jToLog4j2Test.*") - configurations { - testImplementation { - // need to exclude logback in order to test slf4j -> log4j2 - exclude(group = "ch.qos.logback", module = "logback-classic") - } - } - dependencies { - testImplementation("org.slf4j:slf4j-api") { - version { - strictly("1.5.8") - } - } - testImplementation("org.apache.logging.log4j:log4j-slf4j-impl:2.17.0") - } - } - - val testSlf4j2ToLog4j2 by registering(Test::class) { - filter { - includeTestsMatching("Slf4jToLog4j2Test") - } - configurations { - testImplementation { - // need to exclude logback in order to test slf4j -> log4j2 - exclude(group = "ch.qos.logback", module = "logback-classic") - } - } - dependencies { - // 2.19.0 is the first version of log4j-slf4j2-impl - testLibrary("org.apache.logging.log4j:log4j-core:2.19.0") - testImplementation("org.apache.logging.log4j:log4j-slf4j2-impl:2.19.0") - } - } - check { dependsOn(testAsync) - dependsOn(testSlf4j1ToLog4j2) - dependsOn(testSlf4j2ToLog4j2) } } @@ -92,3 +59,10 @@ tasks.withType().configureEach { jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true") jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-marker-attribute=true") } + +configurations { + testImplementation { + // this is needed for the slf4j->log4j test + exclude("ch.qos.logback", "logback-classic") + } +} diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java similarity index 98% rename from instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java rename to instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java index aab139b49fb9..be724d6b9e9f 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java @@ -28,7 +28,7 @@ import org.slf4j.Marker; import org.slf4j.MarkerFactory; -class Slf4jToLog4j2Test { +class Slf4jToLog4jTest { @RegisterExtension static final InstrumentationExtension testing = AgentInstrumentationExtension.create(); @@ -95,7 +95,7 @@ private static void test( equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "hello"), satisfies( SemanticAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(Slf4jToLog4j2Test.class.getName()))); + v -> v.contains(Slf4jToLog4jTest.class.getName()))); } else { assertThat(log) .hasAttributesSatisfyingExactly( diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java deleted file mode 100644 index aab139b49fb9..000000000000 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/testSlf4j1/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4j2Test.java +++ /dev/null @@ -1,177 +0,0 @@ -/* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ - -package io.opentelemetry.instrumentation.log4j.appender.v2_17; - -import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; - -import io.opentelemetry.api.common.AttributeKey; -import io.opentelemetry.api.logs.Severity; -import io.opentelemetry.instrumentation.testing.junit.AgentInstrumentationExtension; -import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; -import io.opentelemetry.sdk.common.InstrumentationScopeInfo; -import io.opentelemetry.sdk.logs.data.LogRecordData; -import io.opentelemetry.semconv.trace.attributes.SemanticAttributes; -import java.util.stream.Stream; -import org.junit.jupiter.api.Test; -import org.junit.jupiter.api.extension.RegisterExtension; -import org.junit.jupiter.params.ParameterizedTest; -import org.junit.jupiter.params.provider.Arguments; -import org.junit.jupiter.params.provider.MethodSource; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; -import org.slf4j.MDC; -import org.slf4j.Marker; -import org.slf4j.MarkerFactory; - -class Slf4jToLog4j2Test { - - @RegisterExtension - static final InstrumentationExtension testing = AgentInstrumentationExtension.create(); - - private static final Logger logger = LoggerFactory.getLogger("abc"); - - private static Stream provideParameters() { - return Stream.of( - Arguments.of(false, false), - Arguments.of(false, true), - Arguments.of(true, false), - Arguments.of(true, true)); - } - - @ParameterizedTest - @MethodSource("provideParameters") - public void test(boolean logException, boolean withParent) throws InterruptedException { - test(Logger::debug, Logger::debug, logException, withParent, null, null, null); - testing.clearData(); - test(Logger::info, Logger::info, logException, withParent, "abc", Severity.INFO, "INFO"); - testing.clearData(); - test(Logger::warn, Logger::warn, logException, withParent, "abc", Severity.WARN, "WARN"); - testing.clearData(); - test(Logger::error, Logger::error, logException, withParent, "abc", Severity.ERROR, "ERROR"); - testing.clearData(); - } - - private static void test( - OneArgLoggerMethod oneArgLoggerMethod, - TwoArgLoggerMethod twoArgLoggerMethod, - boolean logException, - boolean withParent, - String expectedLoggerName, - Severity expectedSeverity, - String expectedSeverityText) - throws InterruptedException { - - // when - if (withParent) { - testing.runWithSpan( - "parent", () -> performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException)); - } else { - performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException); - } - - // then - if (withParent) { - testing.waitForTraces(1); - } - - if (expectedSeverity != null) { - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("xyz: 123") - .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build()) - .hasSeverity(expectedSeverity) - .hasSeverityText(expectedSeverityText); - if (logException) { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(SemanticAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(SemanticAttributes.EXCEPTION_MESSAGE, "hello"), - satisfies( - SemanticAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(Slf4jToLog4j2Test.class.getName()))); - } else { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())); - } - - if (withParent) { - assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); - } else { - assertThat(log.getSpanContext().isValid()).isFalse(); - } - - } else { - Thread.sleep(500); // sleep a bit just to make sure no log is captured - assertThat(testing.logRecords()).isEmpty(); - } - } - - @Test - void testMdc() { - MDC.put("key1", "val1"); - MDC.put("key2", "val2"); - try { - logger.info("xyz: {}", 123); - } finally { - MDC.clear(); - } - - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("xyz: 123") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(AttributeKey.stringKey("log4j.context_data.key1"), "val1"), - equalTo(AttributeKey.stringKey("log4j.context_data.key2"), "val2"), - equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId())); - } - - @Test - public void testMarker() { - - String markerName = "aMarker"; - Marker marker = MarkerFactory.getMarker(markerName); - - logger.info(marker, "Message"); - - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(AttributeKey.stringKey("log4j.marker"), markerName)); - } - - private static void performLogging( - OneArgLoggerMethod oneArgLoggerMethod, - TwoArgLoggerMethod twoArgLoggerMethod, - boolean logException) { - if (logException) { - twoArgLoggerMethod.call(logger, "xyz: {}", 123, new IllegalStateException("hello")); - } else { - oneArgLoggerMethod.call(logger, "xyz: {}", 123); - } - } - - @FunctionalInterface - interface OneArgLoggerMethod { - void call(Logger logger, String msg, Object arg); - } - - @FunctionalInterface - interface TwoArgLoggerMethod { - void call(Logger logger, String msg, Object arg1, Object arg2); - } -} From eb7a63a422787ef73da778dfb7615e0567544ba4 Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Mon, 6 Feb 2023 16:37:15 -0800 Subject: [PATCH 3/3] val --- .../log4j/log4j-appender-2.17/javaagent/build.gradle.kts | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts index d570a2c09057..7c21b004a49f 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts @@ -11,6 +11,8 @@ muzzle { } } +val testLatestDeps = findProperty("testLatestDeps") as Boolean + dependencies { library("org.apache.logging.log4j:log4j-core:2.17.0") @@ -22,7 +24,7 @@ dependencies { testImplementation("org.awaitility:awaitility") // this dependency is needed for the slf4j->log4j test - if (findProperty("testLatestDeps") as Boolean) { + if (testLatestDeps) { testImplementation("org.apache.logging.log4j:log4j-slf4j2-impl:2.19.0") } else { // log4j 2.17 doesn't have an slf4j2 bridge @@ -39,7 +41,7 @@ dependencies { } tasks.withType().configureEach { - systemProperty("testLatestDeps", findProperty("testLatestDeps") as Boolean) + systemProperty("testLatestDeps", testLatestDeps) } tasks {