From 3624e0c82b3fe51ab5e72d7cab859e726f561f86 Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Tue, 7 Oct 2025 19:44:35 -0700 Subject: [PATCH 1/2] Unify Log4j2 appender tests --- .../javaagent/build.gradle.kts | 2 + .../log4j/appender/v2_17/Log4j2Test.java | 272 +---------------- .../library/build.gradle.kts | 1 + .../v2_17/internal/LogEventMapper.java | 10 +- .../AbstractOpenTelemetryAppenderTest.java | 204 ------------- .../log4j/appender/v2_17/Log4j2Test.java | 49 +++ .../v2_17/OpenTelemetryAppenderTest.java | 30 -- .../library/src/test/resources/log4j2.xml | 6 +- .../testing/build.gradle.kts | 10 + .../appender/v2_17/AbstractLog4j2Test.java | 285 ++++++++++++++++++ settings.gradle.kts | 1 + 11 files changed, 366 insertions(+), 504 deletions(-) create mode 100644 instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java create mode 100644 instrumentation/log4j/log4j-appender-2.17/testing/build.gradle.kts create mode 100644 instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.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 09ab724ab340..b70672938292 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts @@ -20,6 +20,7 @@ dependencies { implementation(project(":instrumentation:log4j:log4j-appender-2.17:library")) + testImplementation(project(":instrumentation:log4j:log4j-appender-2.17:testing")) testImplementation("org.awaitility:awaitility") if (testLatestDeps) { @@ -64,6 +65,7 @@ tasks.withType().configureEach { jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-map-message-attributes=true") jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-mdc-attributes=*") jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-marker-attribute=true") + jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-event-name=true") } configurations { diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java index 875a7b24f13d..8fc308089f3e 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java @@ -5,281 +5,17 @@ package io.opentelemetry.instrumentation.log4j.appender.v2_17; -import static io.opentelemetry.instrumentation.testing.junit.code.SemconvCodeStabilityUtil.codeFileAndLineAssertions; -import static io.opentelemetry.instrumentation.testing.junit.code.SemconvCodeStabilityUtil.codeFunctionAssertions; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; -import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_MESSAGE; -import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_STACKTRACE; -import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_TYPE; -import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_ID; -import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_NAME; -import static java.util.concurrent.TimeUnit.MILLISECONDS; - -import io.opentelemetry.api.common.AttributeKey; -import io.opentelemetry.api.common.Value; -import io.opentelemetry.api.logs.Severity; -import io.opentelemetry.api.trace.SpanContext; 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.sdk.testing.assertj.AttributeAssertion; -import java.time.Instant; -import java.util.ArrayList; -import java.util.Arrays; -import java.util.List; -import java.util.stream.Stream; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.Marker; -import org.apache.logging.log4j.MarkerManager; -import org.apache.logging.log4j.ThreadContext; -import org.apache.logging.log4j.message.StringMapMessage; -import org.apache.logging.log4j.message.StructuredDataMessage; -import org.assertj.core.api.AssertAccess; -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; -class Log4j2Test { +class Log4j2Test extends AbstractLog4j2Test { @RegisterExtension static final InstrumentationExtension testing = AgentInstrumentationExtension.create(); - private static final Logger logger = LogManager.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)); - } - - private static List threadAttributesAssertions() { - return Arrays.asList( - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId())); - } - - @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 { - - Instant start = Instant.now(); - - // when - if (withParent) { - testing.runWithSpan( - "parent", () -> performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException)); - } else { - performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException); - } - - // then - if (withParent) { - testing.waitForTraces(1); - } - - if (expectedSeverity != null) { - testing.waitAndAssertLogRecords( - logRecord -> { - logRecord - .hasBody("xyz: 123") - .hasInstrumentationScope( - InstrumentationScopeInfo.builder(expectedLoggerName).build()) - .hasSeverity(expectedSeverity) - .hasSeverityText(expectedSeverityText) - .hasSpanContext( - withParent - ? testing.spans().get(0).getSpanContext() - : SpanContext.getInvalid()); - - List attributeAsserts = - new ArrayList<>( - Arrays.asList( - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId()))); - - attributeAsserts.addAll(codeFunctionAssertions(Log4j2Test.class, "performLogging")); - attributeAsserts.addAll(codeFileAndLineAssertions("Log4j2Test.java")); - - if (logException) { - attributeAsserts.addAll( - Arrays.asList( - equalTo(EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(EXCEPTION_MESSAGE, "hello"), - satisfies( - EXCEPTION_STACKTRACE, v -> v.contains(Log4j2Test.class.getName())))); - } - logRecord.hasAttributesSatisfyingExactly(attributeAsserts); - - LogRecordData logRecordData = AssertAccess.getActual(logRecord); - assertThat(logRecordData.getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); - }); - } else { - Thread.sleep(500); // sleep a bit just to make sure no log is captured - assertThat(testing.logRecords()).isEmpty(); - } - } - - @Test - void testContextData() { - ThreadContext.put("key1", "val1"); - ThreadContext.put("key2", "val2"); - try { - logger.info("xyz: {}", 123); - } finally { - ThreadContext.clearMap(); - } - - List assertions = - codeFunctionAssertions(Log4j2Test.class, "testContextData"); - assertions.addAll(codeFileAndLineAssertions("Log4j2Test.java")); - assertions.addAll(threadAttributesAssertions()); - assertions.add(equalTo(AttributeKey.stringKey("key1"), "val1")); - assertions.add(equalTo(AttributeKey.stringKey("key2"), "val2")); - - testing.waitAndAssertLogRecords( - logRecord -> - logRecord - .hasBody("xyz: 123") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly(assertions)); - } - - @Test - void testStringMapMessage() { - StringMapMessage message = new StringMapMessage(); - message.put("key1", "val1"); - message.put("key2", "val2"); - logger.info(message); - - List assertions = - codeFunctionAssertions(Log4j2Test.class, "testStringMapMessage"); - assertions.addAll(codeFileAndLineAssertions("Log4j2Test.java")); - assertions.addAll(threadAttributesAssertions()); - assertions.add(equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1")); - assertions.add(equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2")); - - testing.waitAndAssertLogRecords( - logRecord -> - logRecord - .hasBody((Value) null) - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly(assertions)); - } - - @Test - void testStringMapMessageWithSpecialAttribute() { - StringMapMessage message = new StringMapMessage(); - message.put("key1", "val1"); - message.put("message", "val2"); - logger.info(message); - - List assertions = - codeFunctionAssertions(Log4j2Test.class, "testStringMapMessageWithSpecialAttribute"); - assertions.addAll(codeFileAndLineAssertions("Log4j2Test.java")); - assertions.addAll(threadAttributesAssertions()); - assertions.add(equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1")); - - testing.waitAndAssertLogRecords( - logRecord -> - logRecord - .hasBody("val2") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly(assertions)); - } - - @Test - void testStructuredDataMapMessage() { - StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type"); - message.put("key1", "val1"); - message.put("key2", "val2"); - logger.info(message); - - List assertions = - codeFunctionAssertions(Log4j2Test.class, "testStructuredDataMapMessage"); - assertions.addAll(codeFileAndLineAssertions("Log4j2Test.java")); - assertions.addAll(threadAttributesAssertions()); - assertions.add(equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1")); - assertions.add(equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2")); - - testing.waitAndAssertLogRecords( - logRecord -> - logRecord - .hasBody("a message") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly(assertions)); - } - - @Test - public void testMarker() { - String markerName = "aMarker"; - Marker marker = MarkerManager.getMarker(markerName); - - logger.info(marker, "Message"); - - List assertions = codeFunctionAssertions(Log4j2Test.class, "testMarker"); - assertions.addAll(codeFileAndLineAssertions("Log4j2Test.java")); - assertions.addAll(threadAttributesAssertions()); - assertions.add(equalTo(AttributeKey.stringKey("log4j.marker"), markerName)); - - testing.waitAndAssertLogRecords( - logRecord -> logRecord.hasAttributesSatisfyingExactly(assertions)); - } - - 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); + @Override + protected InstrumentationExtension testing() { + return testing; } } diff --git a/instrumentation/log4j/log4j-appender-2.17/library/build.gradle.kts b/instrumentation/log4j/log4j-appender-2.17/library/build.gradle.kts index b462fb694f2d..c8fd65fd3030 100644 --- a/instrumentation/log4j/log4j-appender-2.17/library/build.gradle.kts +++ b/instrumentation/log4j/log4j-appender-2.17/library/build.gradle.kts @@ -8,6 +8,7 @@ dependencies { implementation(project(":instrumentation:log4j:log4j-context-data:log4j-context-data-2.17:library-autoconfigure")) + testImplementation(project(":instrumentation:log4j:log4j-appender-2.17:testing")) testImplementation("io.opentelemetry:opentelemetry-sdk-testing") testLibrary("com.lmax:disruptor:3.3.4") diff --git a/instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java b/instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java index 6663107e1074..8c18a5c19cce 100644 --- a/instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java +++ b/instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java @@ -16,6 +16,7 @@ import io.opentelemetry.semconv.ExceptionAttributes; import java.io.PrintWriter; import java.io.StringWriter; +import java.util.ArrayList; import java.util.List; import java.util.function.Supplier; import javax.annotation.Nullable; @@ -76,9 +77,16 @@ public LogEventMapper( this.captureExperimentalAttributes = captureExperimentalAttributes; this.captureMapMessageAttributes = captureMapMessageAttributes; this.captureMarkerAttribute = captureMarkerAttribute; - this.captureContextDataAttributes = captureContextDataAttributes; this.captureAllContextDataAttributes = captureContextDataAttributes.size() == 1 && captureContextDataAttributes.get(0).equals("*"); + // If captureEventName is enabled, ensure "event.name" is in the list that we loop over + if (captureEventName + && !captureAllContextDataAttributes + && !captureContextDataAttributes.contains("event.name")) { + captureContextDataAttributes = new ArrayList<>(captureContextDataAttributes); + captureContextDataAttributes.add("event.name"); + } + this.captureContextDataAttributes = captureContextDataAttributes; this.captureEventName = captureEventName; } diff --git a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractOpenTelemetryAppenderTest.java b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractOpenTelemetryAppenderTest.java index 872f5dedc0f2..83a7ba499dbc 100644 --- a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractOpenTelemetryAppenderTest.java +++ b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractOpenTelemetryAppenderTest.java @@ -5,40 +5,21 @@ package io.opentelemetry.instrumentation.log4j.appender.v2_17; -import static io.opentelemetry.api.common.AttributeKey.stringKey; import static io.opentelemetry.instrumentation.testing.junit.code.SemconvCodeStabilityUtil.codeFileAndLineAssertions; import static io.opentelemetry.instrumentation.testing.junit.code.SemconvCodeStabilityUtil.codeFunctionAssertions; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; -import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_MESSAGE; -import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_STACKTRACE; -import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_TYPE; -import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_ID; -import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_NAME; -import static java.util.concurrent.TimeUnit.MILLISECONDS; -import io.opentelemetry.api.logs.Severity; -import io.opentelemetry.api.trace.SpanContext; import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; import io.opentelemetry.sdk.common.InstrumentationScopeInfo; -import io.opentelemetry.sdk.logs.data.LogRecordData; import io.opentelemetry.sdk.resources.Resource; import io.opentelemetry.sdk.testing.assertj.AttributeAssertion; -import java.time.Instant; import java.util.ArrayList; import java.util.Arrays; import java.util.List; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.Marker; -import org.apache.logging.log4j.MarkerManager; import org.apache.logging.log4j.ThreadContext; import org.apache.logging.log4j.core.impl.Log4jLogEvent; import org.apache.logging.log4j.message.FormattedMessage; -import org.apache.logging.log4j.message.StringMapMessage; -import org.apache.logging.log4j.message.StructuredDataMessage; -import org.assertj.core.api.AssertAccess; import org.junit.jupiter.api.AfterAll; import org.junit.jupiter.api.BeforeAll; import org.junit.jupiter.api.Test; @@ -89,191 +70,6 @@ void initializeWithBuilder() { getTesting().waitAndAssertLogRecords(logRecord -> logRecord.hasBody("log message 1")); } - @Test - void logNoSpan() { - logger.info("log message 1"); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> - logRecord - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasAttributesSatisfyingExactly( - addLocationAttributes( - "logNoSpan", - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId())))); - } - - @Test - void logWithSpanInvalid() { - logger.info("log message"); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords(logRecord -> logRecord.hasSpanContext(SpanContext.getInvalid())); - } - - @Test - void logWithExtras() { - Instant start = Instant.now(); - logger.info("log message 1", new IllegalStateException("Error!")); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> { - logRecord - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - addLocationAttributes( - "logWithExtras", - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId()), - equalTo(EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(EXCEPTION_MESSAGE, "Error!"), - satisfies(EXCEPTION_STACKTRACE, v -> v.contains("logWithExtras")))); - - LogRecordData logRecordData = AssertAccess.getActual(logRecord); - assertThat(logRecordData.getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); - }); - } - - @Test - void logContextData() { - ThreadContext.put("key1", "val1"); - ThreadContext.put("key2", "val2"); - ThreadContext.put("event.name", "MyEventName"); - try { - logger.info("log message 1"); - } finally { - ThreadContext.clearMap(); - } - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> - logRecord - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasEventName("MyEventName") - .hasAttributesSatisfyingExactly( - addLocationAttributes( - "logContextData", - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId()), - equalTo(stringKey("key1"), "val1"), - equalTo(stringKey("key2"), "val2")))); - } - - @Test - void logStringMapMessage() { - StringMapMessage message = new StringMapMessage(); - message.put("key1", "val1"); - message.put("key2", "val2"); - logger.info(message); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> - logRecord - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasAttributesSatisfyingExactly( - addLocationAttributes( - "logStringMapMessage", - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId()), - equalTo(stringKey("log4j.map_message.key1"), "val1"), - equalTo(stringKey("log4j.map_message.key2"), "val2")))); - } - - @Test - void logStringMapMessageWithSpecialAttribute() { - StringMapMessage message = new StringMapMessage(); - message.put("key1", "val1"); - message.put("message", "val2"); - logger.info(message); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> - logRecord - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("val2") - .hasAttributesSatisfyingExactly( - addLocationAttributes( - "logStringMapMessageWithSpecialAttribute", - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId()), - equalTo(stringKey("log4j.map_message.key1"), "val1")))); - } - - @Test - void testCaptureMarkerAttribute() { - String markerName = "aMarker"; - Marker marker = MarkerManager.getMarker(markerName); - - logger.info(marker, "Message"); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> - logRecord.hasAttributesSatisfying(equalTo(stringKey("log4j.marker"), markerName))); - } - - @Test - void logStructuredDataMessage() { - StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type"); - message.put("key1", "val1"); - message.put("key2", "val2"); - logger.info(message); - - executeAfterLogsExecution(); - - getTesting() - .waitAndAssertLogRecords( - logRecord -> - logRecord - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("a message") - .hasAttributesSatisfyingExactly( - addLocationAttributes( - "logStructuredDataMessage", - equalTo(THREAD_NAME, Thread.currentThread().getName()), - equalTo(THREAD_ID, Thread.currentThread().getId()), - equalTo(stringKey("log4j.map_message.key1"), "val1"), - equalTo(stringKey("log4j.map_message.key2"), "val2")))); - } - - private static List addLocationAttributes( - String methodName, AttributeAssertion... assertions) { - return addLocationAttributes(AbstractOpenTelemetryAppenderTest.class, methodName, assertions); - } - protected static List addLocationAttributes( Class testClass, String methodName, AttributeAssertion... assertions) { String selector = System.getProperty("Log4j2.contextSelector"); diff --git a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java new file mode 100644 index 000000000000..1cff5bb981ec --- /dev/null +++ b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java @@ -0,0 +1,49 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.log4j.appender.v2_17; + +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; +import io.opentelemetry.sdk.testing.assertj.AttributeAssertion; +import java.util.ArrayList; +import java.util.List; +import org.junit.jupiter.api.AfterAll; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.extension.RegisterExtension; + +class Log4j2Test extends AbstractLog4j2Test { + + @RegisterExtension + static final LibraryInstrumentationExtension testing = LibraryInstrumentationExtension.create(); + + @BeforeEach + void setup() { + OpenTelemetryAppender.install(testing.getOpenTelemetry()); + } + + @AfterAll + static void cleanup() { + OpenTelemetryAppender.install(null); + } + + @Override + protected InstrumentationExtension testing() { + return testing; + } + + @Override + protected List addCodeLocationAttributes(String methodName) { + // For library tests, AsyncLogger can't capture code location in older versions + String selector = System.getProperty("Log4j2.contextSelector"); + boolean async = selector != null && selector.endsWith("AsyncLoggerContextSelector"); + if (async && !Boolean.getBoolean("testLatestDeps")) { + // source info is not available by default when async logger is used in non latest dep tests + return new ArrayList<>(); + } + + return super.addCodeLocationAttributes(methodName); + } +} diff --git a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderTest.java b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderTest.java index b20cae81297a..99457a2ec112 100644 --- a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderTest.java +++ b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppenderTest.java @@ -5,14 +5,9 @@ package io.opentelemetry.instrumentation.log4j.appender.v2_17; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; - -import io.opentelemetry.api.trace.Span; import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; -import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes; import org.junit.jupiter.api.BeforeEach; -import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; class OpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest { @@ -31,29 +26,4 @@ void setup() { protected InstrumentationExtension getTesting() { return testing; } - - @Test - void logWithSpan() { // Does not work for log replay, but it is not likely to occur because - // the log replay is related to the case where an OpenTelemetry object is not yet available - // at the time the log is executed (and if no OpenTelemetry is available, the context - // propagation can't happen) - Span span1 = - testing.runWithSpan( - "span1", - () -> { - logger.info("log message"); - return Span.current(); - }); - - executeAfterLogsExecution(); - - testing.waitAndAssertLogRecords( - logRecord -> - logRecord - .hasSpanContext(span1.getSpanContext()) - .hasAttributesSatisfying( - equalTo( - ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); - } } diff --git a/instrumentation/log4j/log4j-appender-2.17/library/src/test/resources/log4j2.xml b/instrumentation/log4j/log4j-appender-2.17/library/src/test/resources/log4j2.xml index ceb9351c5e81..b1ab81b09fe8 100644 --- a/instrumentation/log4j/log4j-appender-2.17/library/src/test/resources/log4j2.xml +++ b/instrumentation/log4j/log4j-appender-2.17/library/src/test/resources/log4j2.xml @@ -6,13 +6,17 @@ pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} traceId: %X{trace_id} spanId: %X{span_id} flags: %X{trace_flags} - %msg%n"/> - + + + + + diff --git a/instrumentation/log4j/log4j-appender-2.17/testing/build.gradle.kts b/instrumentation/log4j/log4j-appender-2.17/testing/build.gradle.kts new file mode 100644 index 000000000000..aa2c294c2874 --- /dev/null +++ b/instrumentation/log4j/log4j-appender-2.17/testing/build.gradle.kts @@ -0,0 +1,10 @@ +plugins { + id("otel.java-conventions") +} + +dependencies { + api(project(":testing-common")) + api("io.opentelemetry:opentelemetry-sdk-testing") + + api("org.apache.logging.log4j:log4j-api:2.17.0") +} diff --git a/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java new file mode 100644 index 000000000000..4a744aa401b0 --- /dev/null +++ b/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java @@ -0,0 +1,285 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.log4j.appender.v2_17; + +import static io.opentelemetry.api.common.AttributeKey.stringKey; +import static io.opentelemetry.instrumentation.testing.junit.code.SemconvCodeStabilityUtil.codeFileAndLineAssertions; +import static io.opentelemetry.instrumentation.testing.junit.code.SemconvCodeStabilityUtil.codeFunctionAssertions; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; +import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_MESSAGE; +import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_STACKTRACE; +import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_TYPE; +import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_ID; +import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_NAME; +import static java.util.Arrays.asList; +import static java.util.concurrent.TimeUnit.MILLISECONDS; + +import io.opentelemetry.api.common.Value; +import io.opentelemetry.api.logs.Severity; +import io.opentelemetry.api.trace.SpanContext; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.sdk.common.InstrumentationScopeInfo; +import io.opentelemetry.sdk.logs.data.LogRecordData; +import io.opentelemetry.sdk.testing.assertj.AttributeAssertion; +import java.time.Instant; +import java.util.ArrayList; +import java.util.List; +import java.util.stream.Stream; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.Marker; +import org.apache.logging.log4j.MarkerManager; +import org.apache.logging.log4j.ThreadContext; +import org.apache.logging.log4j.message.StringMapMessage; +import org.apache.logging.log4j.message.StructuredDataMessage; +import org.assertj.core.api.AssertAccess; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; + +public abstract class AbstractLog4j2Test { + + protected static final Logger logger = LogManager.getLogger("abc"); + + protected abstract InstrumentationExtension testing(); + + protected static Stream provideParameters() { + return Stream.of( + Arguments.of(false, false), + Arguments.of(false, true), + Arguments.of(true, false), + Arguments.of(true, true)); + } + + protected static List threadAttributesAssertions() { + return asList( + equalTo(THREAD_NAME, Thread.currentThread().getName()), + equalTo(THREAD_ID, Thread.currentThread().getId())); + } + + @ParameterizedTest + @MethodSource("provideParameters") + 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 void test( + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException, + boolean withParent, + String expectedLoggerName, + Severity expectedSeverity, + String expectedSeverityText) + throws InterruptedException { + + Instant start = Instant.now(); + + // when + if (withParent) { + testing() + .runWithSpan( + "parent", () -> performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException)); + } else { + performLogging(oneArgLoggerMethod, twoArgLoggerMethod, logException); + } + + // then + if (withParent) { + testing().waitForTraces(1); + } + + if (expectedSeverity != null) { + testing() + .waitAndAssertLogRecords( + logRecord -> { + logRecord + .hasBody("xyz: 123") + .hasInstrumentationScope( + InstrumentationScopeInfo.builder(expectedLoggerName).build()) + .hasSeverity(expectedSeverity) + .hasSeverityText(expectedSeverityText) + .hasSpanContext( + withParent + ? testing().spans().get(0).getSpanContext() + : SpanContext.getInvalid()); + + List attributeAsserts = + addCodeLocationAttributes("performLogging"); + attributeAsserts.addAll(threadAttributesAssertions()); + + if (logException) { + attributeAsserts.addAll( + asList( + equalTo(EXCEPTION_TYPE, IllegalStateException.class.getName()), + equalTo(EXCEPTION_MESSAGE, "hello"), + satisfies( + EXCEPTION_STACKTRACE, + v -> v.contains(AbstractLog4j2Test.class.getName())))); + } + logRecord.hasAttributesSatisfyingExactly(attributeAsserts); + + LogRecordData logRecordData = AssertAccess.getActual(logRecord); + assertThat(logRecordData.getTimestampEpochNanos()) + .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) + .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); + }); + } else { + Thread.sleep(500); // sleep a bit just to make sure no log is captured + assertThat(testing().logRecords()).isEmpty(); + } + } + + @Test + void testContextData() { + ThreadContext.put("key1", "val1"); + ThreadContext.put("key2", "val2"); + ThreadContext.put("event.name", "MyEventName"); + try { + logger.info("xyz: {}", 123); + } finally { + ThreadContext.clearMap(); + } + + List assertions = addCodeLocationAttributes("testContextData"); + assertions.addAll(threadAttributesAssertions()); + assertions.add(equalTo(stringKey("key1"), "val1")); + assertions.add(equalTo(stringKey("key2"), "val2")); + + testing() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("xyz: 123") + .hasEventName("MyEventName") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly(assertions)); + } + + @Test + void testStringMapMessage() { + StringMapMessage message = new StringMapMessage(); + message.put("key1", "val1"); + message.put("key2", "val2"); + logger.info(message); + + List assertions = addCodeLocationAttributes("testStringMapMessage"); + assertions.addAll(threadAttributesAssertions()); + assertions.add(equalTo(stringKey("log4j.map_message.key1"), "val1")); + assertions.add(equalTo(stringKey("log4j.map_message.key2"), "val2")); + + testing() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody((Value) null) + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly(assertions)); + } + + @Test + void testStringMapMessageWithSpecialAttribute() { + StringMapMessage message = new StringMapMessage(); + message.put("key1", "val1"); + message.put("message", "val2"); + logger.info(message); + + List assertions = + addCodeLocationAttributes("testStringMapMessageWithSpecialAttribute"); + assertions.addAll(threadAttributesAssertions()); + assertions.add(equalTo(stringKey("log4j.map_message.key1"), "val1")); + + testing() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("val2") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly(assertions)); + } + + @Test + void testStructuredDataMapMessage() { + StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type"); + message.put("key1", "val1"); + message.put("key2", "val2"); + logger.info(message); + + List assertions = addCodeLocationAttributes("testStructuredDataMapMessage"); + assertions.addAll(threadAttributesAssertions()); + assertions.add(equalTo(stringKey("log4j.map_message.key1"), "val1")); + assertions.add(equalTo(stringKey("log4j.map_message.key2"), "val2")); + + testing() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("a message") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly(assertions)); + } + + @Test + void testMarker() { + String markerName = "aMarker"; + Marker marker = MarkerManager.getMarker(markerName); + + logger.info(marker, "Message"); + + List assertions = addCodeLocationAttributes("testMarker"); + assertions.addAll(threadAttributesAssertions()); + assertions.add(equalTo(stringKey("log4j.marker"), markerName)); + + testing() + .waitAndAssertLogRecords(logRecord -> logRecord.hasAttributesSatisfyingExactly(assertions)); + } + + protected 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); + } + } + + protected List addCodeLocationAttributes(String methodName) { + List result = new ArrayList<>(); + result.addAll(codeFunctionAssertions(AbstractLog4j2Test.class, methodName)); + result.addAll(codeFileAndLineAssertions("AbstractLog4j2Test.java")); + return result; + } + + @FunctionalInterface + public interface OneArgLoggerMethod { + void call(Logger logger, String msg, Object arg); + } + + @FunctionalInterface + public interface TwoArgLoggerMethod { + void call(Logger logger, String msg, Object arg1, Object arg2); + } +} diff --git a/settings.gradle.kts b/settings.gradle.kts index 3b6bf858fb56..c06a1c40b2d9 100644 --- a/settings.gradle.kts +++ b/settings.gradle.kts @@ -393,6 +393,7 @@ include(":instrumentation:liberty:liberty-dispatcher-20.0:javaagent") include(":instrumentation:log4j:log4j-appender-1.2:javaagent") include(":instrumentation:log4j:log4j-appender-2.17:javaagent") include(":instrumentation:log4j:log4j-appender-2.17:library") +include(":instrumentation:log4j:log4j-appender-2.17:testing") include(":instrumentation:log4j:log4j-context-data:log4j-context-data-2.7:javaagent") include(":instrumentation:log4j:log4j-context-data:log4j-context-data-2.17:javaagent") include(":instrumentation:log4j:log4j-context-data:log4j-context-data-2.17:library-autoconfigure") From 98f6d9273957a6f01559b2f61213a673d63e2b3d Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Wed, 8 Oct 2025 16:24:10 -0700 Subject: [PATCH 2/2] private --- .../log4j/appender/v2_17/AbstractLog4j2Test.java | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java b/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java index 4a744aa401b0..2dd8d3826e57 100644 --- a/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java +++ b/instrumentation/log4j/log4j-appender-2.17/testing/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractLog4j2Test.java @@ -45,11 +45,11 @@ public abstract class AbstractLog4j2Test { - protected static final Logger logger = LogManager.getLogger("abc"); + private static final Logger logger = LogManager.getLogger("abc"); protected abstract InstrumentationExtension testing(); - protected static Stream provideParameters() { + private static Stream provideParameters() { return Stream.of( Arguments.of(false, false), Arguments.of(false, true), @@ -57,7 +57,7 @@ protected static Stream provideParameters() { Arguments.of(true, true)); } - protected static List threadAttributesAssertions() { + private static List threadAttributesAssertions() { return asList( equalTo(THREAD_NAME, Thread.currentThread().getName()), equalTo(THREAD_ID, Thread.currentThread().getId())); @@ -255,7 +255,7 @@ void testMarker() { .waitAndAssertLogRecords(logRecord -> logRecord.hasAttributesSatisfyingExactly(assertions)); } - protected static void performLogging( + private static void performLogging( OneArgLoggerMethod oneArgLoggerMethod, TwoArgLoggerMethod twoArgLoggerMethod, boolean logException) {