From c57abb1394dd541d1059cec76533bb1d43a52fb1 Mon Sep 17 00:00:00 2001 From: Lauri Tulmin Date: Wed, 4 Sep 2024 14:19:53 +0300 Subject: [PATCH] Make log record asserts similar to trace asserts --- .../appender/v1_1/JbossLogmanagerTest.java | 104 +++++----- .../log4j/appender/v1_2/Log4j1Test.java | 103 +++++----- .../log4j/appender/v2_17/Log4j2Test.java | 186 ++++++++++-------- .../appender/v2_17/Slf4jToLog4jTest.java | 105 +++++----- .../AbstractOpenTelemetryAppenderTest.java | 163 ++++++++------- .../LogReplayOpenTelemetryAppenderTest.java | 71 ++++--- .../v2_17/OpenTelemetryAppenderTest.java | 42 ++-- .../logback/appender/v1_0/LogbackTest.java | 135 +++++++------ .../library/build.gradle.kts | 1 + .../logback/appender/v1_0/Slf4j2Test.java | 124 +++++------- .../AbstractOpenTelemetryAppenderTest.java | 152 +++++++------- .../LogReplayOpenTelemetryAppenderTest.java | 36 ++-- .../v1_0/OpenTelemetryAppenderTest.java | 58 +++--- .../junit/InstrumentationExtension.java | 26 +++ 14 files changed, 690 insertions(+), 616 deletions(-) diff --git a/instrumentation/jboss-logmanager/jboss-logmanager-appender-1.1/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/jbosslogmanager/appender/v1_1/JbossLogmanagerTest.java b/instrumentation/jboss-logmanager/jboss-logmanager-appender-1.1/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/jbosslogmanager/appender/v1_1/JbossLogmanagerTest.java index eaa67c0d6ba7..acef12077658 100644 --- a/instrumentation/jboss-logmanager/jboss-logmanager-appender-1.1/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/jbosslogmanager/appender/v1_1/JbossLogmanagerTest.java +++ b/instrumentation/jboss-logmanager/jboss-logmanager-appender-1.1/javaagent/src/test/java/io/opentelemetry/javaagent/instrumentation/jbosslogmanager/appender/v1_1/JbossLogmanagerTest.java @@ -9,18 +9,23 @@ import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; import static java.util.concurrent.TimeUnit.MILLISECONDS; -import static org.assertj.core.api.Assertions.assertThat; import io.opentelemetry.api.common.AttributeKey; 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 io.opentelemetry.semconv.ExceptionAttributes; import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes; import java.time.Instant; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; import java.util.stream.Stream; +import org.assertj.core.api.AssertAccess; import org.jboss.logmanager.Level; import org.jboss.logmanager.LogContext; import org.jboss.logmanager.Logger; @@ -127,40 +132,45 @@ private static void test( } if (expectedSeverity != null) { - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody(withParam ? "xyz: 123" : "xyz") - .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build()) - .hasSeverity(expectedSeverity) - .hasSeverityText(expectedSeverityText); - - assertThat(log.getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); - - if (logException) { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(ExceptionAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), - satisfies( - ExceptionAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(JbossLogmanagerTest.class.getName()))); - } else { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); - } - - if (withParent) { - assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); - } else { - assertThat(log.getSpanContext().isValid()).isFalse(); - } - + testing.waitAndAssertLogRecords( + logRecord -> { + logRecord + .hasBody(withParam ? "xyz: 123" : "xyz") + .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( + ThreadIncubatingAttributes.THREAD_NAME, + Thread.currentThread().getName()), + equalTo( + ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); + if (logException) { + attributeAsserts.addAll( + Arrays.asList( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + ExceptionAttributes.EXCEPTION_STACKTRACE, + v -> v.contains(JbossLogmanagerTest.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(); @@ -199,17 +209,19 @@ void testMdc() { MDC.remove("key2"); } - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("xyz") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(AttributeKey.stringKey("key1"), "val1"), - equalTo(AttributeKey.stringKey("key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("xyz") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("key1"), "val1"), + equalTo(AttributeKey.stringKey("key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } @FunctionalInterface diff --git a/instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v1_2/Log4j1Test.java b/instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v1_2/Log4j1Test.java index 7019e8844418..a5b36a9e5ad9 100644 --- a/instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v1_2/Log4j1Test.java +++ b/instrumentation/log4j/log4j-appender-1.2/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v1_2/Log4j1Test.java @@ -12,18 +12,24 @@ import io.opentelemetry.api.common.AttributeKey; 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 io.opentelemetry.semconv.ExceptionAttributes; import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes; import java.lang.reflect.Field; import java.time.Instant; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; import java.util.stream.Stream; import org.apache.log4j.Logger; import org.apache.log4j.MDC; import org.apache.log4j.helpers.Loader; +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; @@ -98,40 +104,45 @@ private static void test( } if (expectedSeverity != null) { - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("xyz") - .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build()) - .hasSeverity(expectedSeverity) - .hasSeverityText(expectedSeverityText); - - assertThat(log.getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); - - if (logException) { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(ExceptionAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), - satisfies( - ExceptionAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(Log4j1Test.class.getName()))); - } else { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); - } - - if (withParent) { - assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); - } else { - assertThat(log.getSpanContext().isValid()).isFalse(); - } - + testing.waitAndAssertLogRecords( + logRecord -> { + logRecord + .hasBody("xyz") + .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( + ThreadIncubatingAttributes.THREAD_NAME, + Thread.currentThread().getName()), + equalTo( + ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); + if (logException) { + attributeAsserts.addAll( + Arrays.asList( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + ExceptionAttributes.EXCEPTION_STACKTRACE, + v -> v.contains(Log4j1Test.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(); @@ -149,17 +160,19 @@ void testMdc() { MDC.remove("key2"); } - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("xyz") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(AttributeKey.stringKey("key1"), "val1"), - equalTo(AttributeKey.stringKey("key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("xyz") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("key1"), "val1"), + equalTo(AttributeKey.stringKey("key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } private static void performLogging( 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 2db99177c409..50c0a2999c9e 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 @@ -12,13 +12,18 @@ import io.opentelemetry.api.common.AttributeKey; 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 io.opentelemetry.semconv.ExceptionAttributes; import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes; 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; @@ -27,6 +32,7 @@ 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; @@ -87,40 +93,45 @@ private static void test( } if (expectedSeverity != null) { - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("xyz: 123") - .hasInstrumentationScope(InstrumentationScopeInfo.builder(expectedLoggerName).build()) - .hasSeverity(expectedSeverity) - .hasSeverityText(expectedSeverityText); - - assertThat(log.getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); - - if (logException) { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(ExceptionAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), - satisfies( - ExceptionAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(Log4j2Test.class.getName()))); - } else { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); - } - - if (withParent) { - assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); - } else { - assertThat(log.getSpanContext().isValid()).isFalse(); - } - + 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( + ThreadIncubatingAttributes.THREAD_NAME, + Thread.currentThread().getName()), + equalTo( + ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); + if (logException) { + attributeAsserts.addAll( + Arrays.asList( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + ExceptionAttributes.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(); @@ -137,17 +148,19 @@ void testContextData() { ThreadContext.clearMap(); } - 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("key1"), "val1"), - equalTo(AttributeKey.stringKey("key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("key1"), "val1"), + equalTo(AttributeKey.stringKey("key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } @Test @@ -157,17 +170,19 @@ void testStringMapMessage() { message.put("key2", "val2"); logger.info(message); - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"), - equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"), + equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } @Test @@ -177,16 +192,18 @@ void testStringMapMessageWithSpecialAttribute() { message.put("message", "val2"); logger.info(message); - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("val2") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("val2") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } @Test @@ -196,33 +213,34 @@ void testStructuredDataMapMessage() { message.put("key2", "val2"); logger.info(message); - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasBody("a message") - .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"), - equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("a message") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"), + equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } @Test public void testMarker() { - String markerName = "aMarker"; Marker marker = MarkerManager.getMarker(markerName); logger.info(marker, "Message"); - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(AttributeKey.stringKey("log4j.marker"), markerName)); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord.hasAttributesSatisfyingExactly( + equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(AttributeKey.stringKey("log4j.marker"), markerName))); } private static void performLogging( diff --git a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java index 6a3ffafa8853..0a842bbd16cc 100644 --- a/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java +++ b/instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Slf4jToLog4jTest.java @@ -11,12 +11,16 @@ import io.opentelemetry.api.common.AttributeKey; 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 io.opentelemetry.semconv.ExceptionAttributes; import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; import java.util.stream.Stream; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.RegisterExtension; @@ -81,35 +85,40 @@ private static void test( } 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(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(ExceptionAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), - satisfies( - ExceptionAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(Slf4jToLog4jTest.class.getName()))); - } else { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); - } - - if (withParent) { - assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); - } else { - assertThat(log.getSpanContext().isValid()).isFalse(); - } - + 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( + ThreadIncubatingAttributes.THREAD_NAME, + Thread.currentThread().getName()), + equalTo( + ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); + if (logException) { + attributeAsserts.addAll( + Arrays.asList( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + ExceptionAttributes.EXCEPTION_STACKTRACE, + v -> v.contains(Slf4jToLog4jTest.class.getName())))); + } + logRecord.hasAttributesSatisfyingExactly(attributeAsserts); + }); } else { Thread.sleep(500); // sleep a bit just to make sure no log is captured assertThat(testing.logRecords()).isEmpty(); @@ -126,17 +135,19 @@ void testMdc() { 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("key1"), "val1"), - equalTo(AttributeKey.stringKey("key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("key1"), "val1"), + equalTo(AttributeKey.stringKey("key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()))); } @Test @@ -147,12 +158,12 @@ public void testMarker() { logger.info(marker, "Message"); - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(AttributeKey.stringKey("log4j.marker"), markerName)); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord.hasAttributesSatisfyingExactly( + equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(AttributeKey.stringKey("log4j.marker"), markerName))); } private static void performLogging( 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 17f07014b0f4..c548e99cfc61 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 @@ -11,20 +11,15 @@ import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies; import static java.util.concurrent.TimeUnit.MILLISECONDS; -import io.opentelemetry.api.OpenTelemetry; import io.opentelemetry.api.common.Attributes; import io.opentelemetry.api.logs.Severity; import io.opentelemetry.api.trace.SpanContext; -import io.opentelemetry.sdk.OpenTelemetrySdk; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; import io.opentelemetry.sdk.common.InstrumentationScopeInfo; -import io.opentelemetry.sdk.logs.SdkLoggerProvider; import io.opentelemetry.sdk.logs.data.LogRecordData; -import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor; import io.opentelemetry.sdk.resources.Resource; -import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter; import io.opentelemetry.semconv.ExceptionAttributes; import java.time.Instant; -import java.util.List; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.Marker; @@ -34,6 +29,7 @@ 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; @@ -42,30 +38,18 @@ abstract class AbstractOpenTelemetryAppenderTest { static final Logger logger = LogManager.getLogger("TestLogger"); - static InMemoryLogRecordExporter logRecordExporter; static Resource resource; static InstrumentationScopeInfo instrumentationScopeInfo; - static OpenTelemetry openTelemetry; void executeAfterLogsExecution() {} @BeforeAll static void setupAll() { - logRecordExporter = InMemoryLogRecordExporter.create(); resource = Resource.getDefault(); instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger"); - - SdkLoggerProvider loggerProvider = - SdkLoggerProvider.builder() - .setResource(resource) - .addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter)) - .build(); - - openTelemetry = OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build(); } static void generalBeforeEachSetup() { - logRecordExporter.reset(); ThreadContext.clearAll(); } @@ -75,12 +59,14 @@ static void cleanupAll() { OpenTelemetryAppender.install(null); } + protected abstract InstrumentationExtension getTesting(); + @Test void initializeWithBuilder() { OpenTelemetryAppender appender = OpenTelemetryAppender.builder() .setName("OpenTelemetryAppender") - .setOpenTelemetry(openTelemetry) + .setOpenTelemetry(getTesting().getOpenTelemetry()) .build(); appender.start(); @@ -91,9 +77,7 @@ void initializeWithBuilder() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList) - .satisfiesExactly(logRecordData -> assertThat(logDataList.get(0)).hasBody("log message 1")); + getTesting().waitAndAssertLogRecords(logRecord -> logRecord.hasBody("log message 1")); } @Test @@ -102,13 +86,14 @@ void logNoSpan() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasAttributes(Attributes.empty()); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasAttributes(Attributes.empty())); } @Test @@ -117,9 +102,8 @@ void logWithSpanInvalid() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0).getSpanContext()).isEqualTo(SpanContext.getInvalid()); + getTesting() + .waitAndAssertLogRecords(logRecord -> logRecord.hasSpanContext(SpanContext.getInvalid())); } @Test @@ -129,22 +113,29 @@ void logWithExtras() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasSeverity(Severity.INFO) - .hasSeverityText("INFO") - .hasAttributesSatisfyingExactly( - equalTo(ExceptionAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "Error!"), - satisfies(ExceptionAttributes.EXCEPTION_STACKTRACE, v -> v.contains("logWithExtras"))); - - assertThat(logDataList.get(0).getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(MILLISECONDS.toNanos(Instant.now().toEpochMilli())); + getTesting() + .waitAndAssertLogRecords( + logRecord -> { + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "Error!"), + satisfies( + ExceptionAttributes.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 @@ -159,14 +150,15 @@ void logContextData() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasAttributesSatisfyingExactly( - equalTo(stringKey("key1"), "val1"), equalTo(stringKey("key2"), "val2")); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasAttributesSatisfyingExactly( + equalTo(stringKey("key1"), "val1"), equalTo(stringKey("key2"), "val2"))); } @Test @@ -178,14 +170,15 @@ void logStringMapMessage() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasAttributesSatisfyingExactly( - equalTo(stringKey("log4j.map_message.key1"), "val1"), - equalTo(stringKey("log4j.map_message.key2"), "val2")); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasAttributesSatisfyingExactly( + equalTo(stringKey("log4j.map_message.key1"), "val1"), + equalTo(stringKey("log4j.map_message.key2"), "val2"))); } @Test @@ -197,13 +190,15 @@ void logStringMapMessageWithSpecialAttribute() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("val2") - .hasAttributesSatisfyingExactly(equalTo(stringKey("log4j.map_message.key1"), "val1")); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("val2") + .hasAttributesSatisfyingExactly( + equalTo(stringKey("log4j.map_message.key1"), "val1"))); } @Test @@ -215,9 +210,10 @@ void testCaptureMarkerAttribute() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - LogRecordData logData = logDataList.get(0); - assertThat(logData.getAttributes().get(stringKey("log4j.marker"))).isEqualTo(markerName); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord.hasAttributesSatisfying(equalTo(stringKey("log4j.marker"), markerName))); } @Test @@ -229,14 +225,15 @@ void logStructuredDataMessage() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("a message") - .hasAttributesSatisfyingExactly( - equalTo(stringKey("log4j.map_message.key1"), "val1"), - equalTo(stringKey("log4j.map_message.key2"), "val2")); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("a message") + .hasAttributesSatisfyingExactly( + equalTo(stringKey("log4j.map_message.key1"), "val1"), + equalTo(stringKey("log4j.map_message.key2"), "val2"))); } } diff --git a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogReplayOpenTelemetryAppenderTest.java b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogReplayOpenTelemetryAppenderTest.java index 5b854d1fdc8d..c5de31180fab 100644 --- a/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogReplayOpenTelemetryAppenderTest.java +++ b/instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogReplayOpenTelemetryAppenderTest.java @@ -6,19 +6,23 @@ package io.opentelemetry.instrumentation.log4j.appender.v2_17; import static io.opentelemetry.api.common.AttributeKey.stringKey; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; -import io.opentelemetry.sdk.logs.data.LogRecordData; -import java.util.List; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; import org.apache.logging.log4j.message.StringMapMessage; import org.apache.logging.log4j.message.StructuredDataMessage; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; class LogReplayOpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest { + @RegisterExtension + private static final LibraryInstrumentationExtension testing = + LibraryInstrumentationExtension.create(); + @BeforeEach void setup() { generalBeforeEachSetup(); @@ -29,9 +33,14 @@ void resetOpenTelemetry() { OpenTelemetryAppender.install(null); } + @Override + protected InstrumentationExtension getTesting() { + return testing; + } + @Override void executeAfterLogsExecution() { - OpenTelemetryAppender.install(openTelemetry); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); } @Test @@ -40,14 +49,14 @@ void twoLogs() { logger.info( "log message 2"); // Won't be instrumented because cache size is 1 (see log4j2.xml file) - OpenTelemetryAppender.install(openTelemetry); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1"); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1")); } @Test @@ -64,16 +73,16 @@ void twoLogsStringMapMessage() { logger.info(message2); // Won't be instrumented because cache size is 1 (see log4j2.xml file) - OpenTelemetryAppender.install(openTelemetry); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasAttributesSatisfyingExactly( - equalTo(stringKey("log4j.map_message.key1"), "val1"), - equalTo(stringKey("log4j.map_message.key2"), "val2")); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasAttributesSatisfyingExactly( + equalTo(stringKey("log4j.map_message.key1"), "val1"), + equalTo(stringKey("log4j.map_message.key2"), "val2"))); } @Test @@ -89,16 +98,16 @@ void twoLogsStructuredDataMessage() { message.put("key2-2", "val2-2"); logger.info(message2); // Won't be instrumented because cache size is 1 (see log4j2.xml file) - OpenTelemetryAppender.install(openTelemetry); - - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0)) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("a message") - .hasAttributesSatisfyingExactly( - equalTo(stringKey("log4j.map_message.key1"), "val1"), - equalTo(stringKey("log4j.map_message.key2"), "val2")); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); + + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("a message") + .hasAttributesSatisfyingExactly( + equalTo(stringKey("log4j.map_message.key1"), "val1"), + equalTo(stringKey("log4j.map_message.key2"), "val2"))); } } 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 bcc8a1290e56..e675f56c0fdc 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,22 +5,28 @@ package io.opentelemetry.instrumentation.log4j.appender.v2_17; -import static org.assertj.core.api.Assertions.assertThat; - import io.opentelemetry.api.trace.Span; -import io.opentelemetry.context.Scope; -import io.opentelemetry.sdk.logs.data.LogRecordData; -import io.opentelemetry.sdk.trace.SdkTracerProvider; -import java.util.List; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; class OpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest { + @RegisterExtension + private static final LibraryInstrumentationExtension testing = + LibraryInstrumentationExtension.create(); + @BeforeEach void setup() { generalBeforeEachSetup(); - OpenTelemetryAppender.install(openTelemetry); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); + } + + @Override + protected InstrumentationExtension getTesting() { + return testing; } @Test @@ -28,22 +34,16 @@ void logWithSpan() { // Does not work for log replay but it is not likely to occ // 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 = runWithSpan("span1", () -> logger.info("log message")); + Span span1 = + testing.runWithSpan( + "span1", + () -> { + logger.info("log message"); + return Span.current(); + }); executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - assertThat(logDataList.get(0).getSpanContext()).isEqualTo(span1.getSpanContext()); - } - - private static Span runWithSpan(String spanName, Runnable runnable) { - Span span = SdkTracerProvider.builder().build().get("tracer").spanBuilder(spanName).startSpan(); - try (Scope ignored = span.makeCurrent()) { - runnable.run(); - } finally { - span.end(); - } - return span; + testing.waitAndAssertLogRecords(logRecord -> logRecord.hasSpanContext(span1.getSpanContext())); } } 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 a1236c9ace55..985915317f9d 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 @@ -11,14 +11,18 @@ import io.opentelemetry.api.common.AttributeKey; 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 io.opentelemetry.semconv.ExceptionAttributes; import io.opentelemetry.semconv.incubating.CodeIncubatingAttributes; import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes; +import java.util.ArrayList; import java.util.Arrays; +import java.util.Collections; +import java.util.List; import java.util.stream.Stream; import org.assertj.core.api.AbstractLongAssert; import org.junit.jupiter.api.Test; @@ -135,43 +139,46 @@ private static void test( } 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(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), - equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "performLogging"), - satisfies(CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), - equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java"), - equalTo(ExceptionAttributes.EXCEPTION_TYPE, IllegalStateException.class.getName()), - equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), - satisfies( - ExceptionAttributes.EXCEPTION_STACKTRACE, - v -> v.contains(LogbackTest.class.getName()))); - } else { - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), - equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "performLogging"), - satisfies(CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), - equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java")); - } - - if (withParent) { - assertThat(log).hasSpanContext(testing.spans().get(0).getSpanContext()); - } else { - assertThat(log.getSpanContext().isValid()).isFalse(); - } + 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( + ThreadIncubatingAttributes.THREAD_NAME, + Thread.currentThread().getName()), + equalTo( + ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo( + CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), + equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "performLogging"), + satisfies( + CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), + equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java"))); + if (logException) { + attributeAsserts.addAll( + Arrays.asList( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "hello"), + satisfies( + ExceptionAttributes.EXCEPTION_STACKTRACE, + v -> v.contains(LogbackTest.class.getName())))); + } + logRecord.hasAttributesSatisfyingExactly(attributeAsserts); + }); } else { Thread.sleep(500); // sleep a bit just to make sure no log is captured assertThat(testing.logRecords()).isEmpty(); @@ -188,21 +195,23 @@ void testMdc() { 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("key1"), "val1"), - equalTo(AttributeKey.stringKey("key2"), "val2"), - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), - equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "testMdc"), - satisfies(CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), - equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java")); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasBody("xyz: 123") + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo(AttributeKey.stringKey("key1"), "val1"), + equalTo(AttributeKey.stringKey("key2"), "val2"), + equalTo( + ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo(CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), + equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "testMdc"), + satisfies(CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), + equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java"))); } @Test @@ -213,16 +222,18 @@ public void testMarker() { abcLogger.info(marker, "Message"); - LogRecordData log = testing.waitForLogRecords(1).get(0); - assertThat(log) - .hasAttributesSatisfyingExactly( - equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), - equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), - equalTo(AttributeKey.stringArrayKey("logback.marker"), Arrays.asList(markerName)), - equalTo(CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), - equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "testMarker"), - satisfies(CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), - equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java")); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord.hasAttributesSatisfyingExactly( + equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()), + equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()), + equalTo( + AttributeKey.stringArrayKey("logback.marker"), + Collections.singletonList(markerName)), + equalTo(CodeIncubatingAttributes.CODE_NAMESPACE, LogbackTest.class.getName()), + equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "testMarker"), + satisfies(CodeIncubatingAttributes.CODE_LINENO, AbstractLongAssert::isPositive), + equalTo(CodeIncubatingAttributes.CODE_FILEPATH, "LogbackTest.java"))); } private static void performLogging( diff --git a/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts b/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts index 0d96dd79d229..87a21f3aa5ea 100644 --- a/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts +++ b/instrumentation/logback/logback-appender-1.0/library/build.gradle.kts @@ -70,6 +70,7 @@ testing { dependencies { implementation(project(":instrumentation:logback:logback-appender-1.0:library")) implementation("io.opentelemetry:opentelemetry-sdk-testing") + implementation(project(":testing-common")) if (latestDepTest) { implementation("ch.qos.logback:logback-classic:+") diff --git a/instrumentation/logback/logback-appender-1.0/library/src/slf4j2ApiTest/java/io/opentelemetry/instrumentation/logback/appender/v1_0/Slf4j2Test.java b/instrumentation/logback/logback-appender-1.0/library/src/slf4j2ApiTest/java/io/opentelemetry/instrumentation/logback/appender/v1_0/Slf4j2Test.java index af17aeaedd84..ddccdeb5a84a 100644 --- a/instrumentation/logback/logback-appender-1.0/library/src/slf4j2ApiTest/java/io/opentelemetry/instrumentation/logback/appender/v1_0/Slf4j2Test.java +++ b/instrumentation/logback/logback-appender-1.0/library/src/slf4j2ApiTest/java/io/opentelemetry/instrumentation/logback/appender/v1_0/Slf4j2Test.java @@ -5,22 +5,16 @@ package io.opentelemetry.instrumentation.logback.appender.v1_0; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo; import io.opentelemetry.api.common.AttributeKey; -import io.opentelemetry.sdk.OpenTelemetrySdk; +import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; import io.opentelemetry.sdk.common.InstrumentationScopeInfo; -import io.opentelemetry.sdk.logs.SdkLoggerProvider; -import io.opentelemetry.sdk.logs.data.LogRecordData; -import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor; import io.opentelemetry.sdk.resources.Resource; -import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter; import java.util.Arrays; -import java.util.List; import org.junit.jupiter.api.BeforeAll; -import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.slf4j.MarkerFactory; @@ -28,30 +22,19 @@ public class Slf4j2Test { private static final Logger logger = LoggerFactory.getLogger("TestLogger"); - private static InMemoryLogRecordExporter logRecordExporter; + @RegisterExtension + private static final LibraryInstrumentationExtension testing = + LibraryInstrumentationExtension.create(); + private static Resource resource; private static InstrumentationScopeInfo instrumentationScopeInfo; @BeforeAll static void setupAll() { - logRecordExporter = InMemoryLogRecordExporter.create(); resource = Resource.getDefault(); instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger"); - SdkLoggerProvider loggerProvider = - SdkLoggerProvider.builder() - .setResource(resource) - .addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter)) - .build(); - OpenTelemetrySdk openTelemetrySdk = - OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build(); - - OpenTelemetryAppender.install(openTelemetrySdk); - } - - @BeforeEach - void setup() { - logRecordExporter.reset(); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); } @Test @@ -69,24 +52,22 @@ void keyValue() { .addKeyValue("double key", 6.0) .log(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - assertThat(logData.getResource()).isEqualTo(resource); - assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo); - assertThat(logData.getBody().asString()).isEqualTo("log message 1"); - assertThat(logData.getAttributes().size()) - .isEqualTo(12); // 4 code attributes + 8 key value pairs - assertThat(logData) - .hasAttributesSatisfying( - equalTo(AttributeKey.stringKey("string key"), "string value"), - equalTo(AttributeKey.booleanKey("boolean key"), true), - equalTo(AttributeKey.longKey("byte key"), 1), - equalTo(AttributeKey.longKey("short key"), 2), - equalTo(AttributeKey.longKey("int key"), 3), - equalTo(AttributeKey.longKey("long key"), 4), - equalTo(AttributeKey.doubleKey("float key"), 5.0), - equalTo(AttributeKey.doubleKey("double key"), 6.0)); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasTotalAttributeCount(12) // 4 code attributes + 8 key value pairs + .hasAttributesSatisfying( + equalTo(AttributeKey.stringKey("string key"), "string value"), + equalTo(AttributeKey.booleanKey("boolean key"), true), + equalTo(AttributeKey.longKey("byte key"), 1), + equalTo(AttributeKey.longKey("short key"), 2), + equalTo(AttributeKey.longKey("int key"), 3), + equalTo(AttributeKey.longKey("long key"), 4), + equalTo(AttributeKey.doubleKey("float key"), 5.0), + equalTo(AttributeKey.doubleKey("double key"), 6.0))); } @Test @@ -100,17 +81,17 @@ void multipleMarkers() { .addMarker(MarkerFactory.getMarker(markerName2)) .log(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - assertThat(logData.getResource()).isEqualTo(resource); - assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo); - assertThat(logData.getBody().asString()).isEqualTo("log message 1"); - assertThat(logData.getAttributes().size()).isEqualTo(5); // 4 code attributes + 1 marker - assertThat(logData.getAttributes()) - .hasEntrySatisfying( - AttributeKey.stringArrayKey("logback.marker"), - value -> assertThat(value).isEqualTo(Arrays.asList(markerName1, markerName2))); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasTotalAttributeCount(5) // 4 code attributes + 1 marker + .hasAttributesSatisfying( + equalTo( + AttributeKey.stringArrayKey("logback.marker"), + Arrays.asList(markerName1, markerName2)))); } @Test @@ -124,31 +105,24 @@ void arguments() { .addArgument(Long.MAX_VALUE) .log(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - - assertThat(logData.getResource()).isEqualTo(resource); - assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo); - assertThat(logData.getBody().asString()) - .isEqualTo( - "log message 'world' and 3.141592653589793, bool true, long 9223372036854775807"); - assertThat(logData.getAttributes().size()).isEqualTo(6); - assertThat(logData.getAttributes()) - .hasEntrySatisfying( - AttributeKey.stringArrayKey("log.body.parameters"), - value -> - assertThat(value) - .isEqualTo( + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody( + "log message 'world' and 3.141592653589793, bool true, long 9223372036854775807") + .hasTotalAttributeCount(6) + .hasAttributesSatisfying( + equalTo( + AttributeKey.stringArrayKey("log.body.parameters"), Arrays.asList( "'world'", String.valueOf(Math.PI), String.valueOf(true), - String.valueOf(Long.MAX_VALUE)))); - assertThat(logData) - .hasAttributesSatisfying( - equalTo( - AttributeKey.stringKey("log.body.template"), - "log message {} and {}, bool {}, long {}")); + String.valueOf(Long.MAX_VALUE))), + equalTo( + AttributeKey.stringKey("log.body.template"), + "log message {} and {}, bool {}, long {}"))); } } diff --git a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/AbstractOpenTelemetryAppenderTest.java b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/AbstractOpenTelemetryAppenderTest.java index 7595d9ddd22d..bd73cdc9dd4c 100644 --- a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/AbstractOpenTelemetryAppenderTest.java +++ b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/AbstractOpenTelemetryAppenderTest.java @@ -6,27 +6,26 @@ package io.opentelemetry.instrumentation.logback.appender.v1_0; 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 ch.qos.logback.classic.LoggerContext; import ch.qos.logback.core.ContextBase; import io.opentelemetry.api.common.AttributeKey; import io.opentelemetry.api.logs.Severity; -import io.opentelemetry.sdk.OpenTelemetrySdk; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; import io.opentelemetry.sdk.common.InstrumentationScopeInfo; -import io.opentelemetry.sdk.logs.SdkLoggerProvider; import io.opentelemetry.sdk.logs.data.LogRecordData; -import io.opentelemetry.sdk.logs.export.SimpleLogRecordProcessor; import io.opentelemetry.sdk.resources.Resource; -import io.opentelemetry.sdk.testing.exporter.InMemoryLogRecordExporter; import io.opentelemetry.semconv.ExceptionAttributes; import io.opentelemetry.semconv.incubating.CodeIncubatingAttributes; import java.lang.reflect.Field; import java.lang.reflect.Method; import java.time.Instant; -import java.util.Arrays; -import java.util.List; +import java.util.Collections; import java.util.Map; import java.util.concurrent.TimeUnit; +import org.assertj.core.api.AssertAccess; import org.junit.jupiter.api.BeforeAll; import org.junit.jupiter.api.Test; import org.slf4j.Logger; @@ -39,25 +38,15 @@ abstract class AbstractOpenTelemetryAppenderTest { static final Logger logger = LoggerFactory.getLogger("TestLogger"); - static InMemoryLogRecordExporter logRecordExporter; static Resource resource; static InstrumentationScopeInfo instrumentationScopeInfo; - static OpenTelemetrySdk openTelemetrySdk; - void executeAfterLogsExecution() {} @BeforeAll static void setupAll() { - logRecordExporter = InMemoryLogRecordExporter.create(); resource = Resource.getDefault(); instrumentationScopeInfo = InstrumentationScopeInfo.create("TestLogger"); - SdkLoggerProvider loggerProvider = - SdkLoggerProvider.builder() - .setResource(resource) - .addLogRecordProcessor(SimpleLogRecordProcessor.create(logRecordExporter)) - .build(); - openTelemetrySdk = OpenTelemetrySdk.builder().setLoggerProvider(loggerProvider).build(); // by default LoggerContext contains HOSTNAME property we clear it to start with empty context resetLoggerContext(); } @@ -83,9 +72,7 @@ static void resetLoggerContext() { } } - static void generalBeforeEachSetup() { - logRecordExporter.reset(); - } + protected abstract InstrumentationExtension getTesting(); @Test void logNoSpan() { @@ -93,15 +80,14 @@ void logNoSpan() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - - assertThat(logData) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasTotalAttributeCount(4); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasTotalAttributeCount(4)); } @Test @@ -114,41 +100,42 @@ void logWithExtras() { executeAfterLogsExecution(); Instant now = Instant.now(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - assertThat(logData.getResource()).isEqualTo(resource); - assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo); - assertThat(logData.getBody().asString()).isEqualTo("log message 1"); - assertThat(logData.getTimestampEpochNanos()) - .isGreaterThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(start.toEpochMilli())) - .isLessThanOrEqualTo(TimeUnit.SECONDS.toNanos(now.getEpochSecond()) + now.getNano()); - assertThat(logData.getSeverity()).isEqualTo(Severity.INFO); - assertThat(logData.getSeverityText()).isEqualTo("INFO"); - assertThat(logData.getAttributes().size()) - .isEqualTo(3 + 4 + 1); // 3 exception attributes, 4 code attributes, 1 marker attribute - assertThat(logData.getAttributes().get(ExceptionAttributes.EXCEPTION_TYPE)) - .isEqualTo(IllegalStateException.class.getName()); - assertThat(logData.getAttributes().get(ExceptionAttributes.EXCEPTION_MESSAGE)) - .isEqualTo("Error!"); - assertThat(logData.getAttributes().get(ExceptionAttributes.EXCEPTION_STACKTRACE)) - .contains("logWithExtras"); - - String file = logData.getAttributes().get(CodeIncubatingAttributes.CODE_FILEPATH); - assertThat(file).isEqualTo(AbstractOpenTelemetryAppenderTest.class.getSimpleName() + ".java"); - - String codeClass = logData.getAttributes().get(CodeIncubatingAttributes.CODE_NAMESPACE); - assertThat(codeClass).isEqualTo(AbstractOpenTelemetryAppenderTest.class.getName()); - - String method = logData.getAttributes().get(CodeIncubatingAttributes.CODE_FUNCTION); - assertThat(method).isEqualTo("logWithExtras"); - - Long lineNumber = logData.getAttributes().get(CodeIncubatingAttributes.CODE_LINENO); - assertThat(lineNumber).isGreaterThan(1); - - List logMarker = - logData.getAttributes().get(AttributeKey.stringArrayKey("logback.marker")); - assertThat(logMarker).isEqualTo(Arrays.asList(markerName)); + getTesting() + .waitAndAssertLogRecords( + logRecord -> { + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + .hasAttributesSatisfyingExactly( + equalTo( + ExceptionAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()), + equalTo(ExceptionAttributes.EXCEPTION_MESSAGE, "Error!"), + satisfies( + ExceptionAttributes.EXCEPTION_STACKTRACE, + stackTrace -> stackTrace.contains("logWithExtras")), + equalTo( + CodeIncubatingAttributes.CODE_FILEPATH, + AbstractOpenTelemetryAppenderTest.class.getSimpleName() + ".java"), + equalTo( + CodeIncubatingAttributes.CODE_NAMESPACE, + AbstractOpenTelemetryAppenderTest.class.getName()), + equalTo(CodeIncubatingAttributes.CODE_FUNCTION, "logWithExtras"), + satisfies( + CodeIncubatingAttributes.CODE_LINENO, lineNo -> lineNo.isGreaterThan(1)), + equalTo( + AttributeKey.stringArrayKey("logback.marker"), + Collections.singletonList(markerName))); + + LogRecordData logRecordData = AssertAccess.getActual(logRecord); + assertThat(logRecordData.getTimestampEpochNanos()) + .isGreaterThanOrEqualTo(TimeUnit.MILLISECONDS.toNanos(start.toEpochMilli())) + .isLessThanOrEqualTo( + TimeUnit.SECONDS.toNanos(now.getEpochSecond()) + now.getNano()); + }); } @Test @@ -163,15 +150,17 @@ void logContextData() { executeAfterLogsExecution(); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - assertThat(logData.getResource()).isEqualTo(resource); - assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo); - assertThat(logData.getBody().asString()).isEqualTo("log message 1"); - assertThat(logData.getAttributes().size()).isEqualTo(2 + 4); // 4 code attributes - assertThat(logData.getAttributes().get(AttributeKey.stringKey("key1"))).isEqualTo("val1"); - assertThat(logData.getAttributes().get(AttributeKey.stringKey("key2"))).isEqualTo("val2"); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasTotalAttributeCount(2 + 4) // 4 code attributes + .hasAttributesSatisfying( + equalTo(AttributeKey.stringKey("key1"), "val1"), + equalTo(AttributeKey.stringKey("key2"), "val2"))); } @Test @@ -185,14 +174,15 @@ void logLoggerContext() { resetLoggerContext(); } - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - assertThat(logData.getResource()).isEqualTo(resource); - assertThat(logData.getInstrumentationScopeInfo()).isEqualTo(instrumentationScopeInfo); - assertThat(logData.getBody().asString()).isEqualTo("log message 1"); - assertThat(logData.getAttributes().size()).isEqualTo(1 + 4); // 4 code attributes - assertThat(logData.getAttributes().get(AttributeKey.stringKey("test-property"))) - .isEqualTo("test-value"); + getTesting() + .waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasTotalAttributeCount(1 + 4) // 4 code attributes + .hasAttributesSatisfying( + equalTo(AttributeKey.stringKey("test-property"), "test-value"))); } } diff --git a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogReplayOpenTelemetryAppenderTest.java b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogReplayOpenTelemetryAppenderTest.java index 778fcef42839..0d5dab96f219 100644 --- a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogReplayOpenTelemetryAppenderTest.java +++ b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogReplayOpenTelemetryAppenderTest.java @@ -5,27 +5,34 @@ package io.opentelemetry.instrumentation.logback.appender.v1_0; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; - import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.util.ContextInitializer; import ch.qos.logback.core.spi.ContextAware; -import io.opentelemetry.sdk.logs.data.LogRecordData; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; import java.net.URL; -import java.util.List; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; import org.slf4j.LoggerFactory; class LogReplayOpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest { + @RegisterExtension + private static final LibraryInstrumentationExtension testing = + LibraryInstrumentationExtension.create(); + @BeforeEach void setup() throws Exception { - generalBeforeEachSetup(); // to make sure we start fresh with a new OpenTelemetryAppender for each test reloadLoggerConfiguration(); } + @Override + protected InstrumentationExtension getTesting() { + return testing; + } + private static void reloadLoggerConfiguration() throws Exception { LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory(); loggerContext.reset(); @@ -49,7 +56,7 @@ private static void reloadLoggerConfiguration() throws Exception { @Override void executeAfterLogsExecution() { - OpenTelemetryAppender.install(openTelemetrySdk); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); } @Test @@ -59,15 +66,14 @@ void twoLogs() { "log message 2"); // Won't be instrumented because cache size is 1 (see logback-test.xml // file) - OpenTelemetryAppender.install(openTelemetrySdk); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(1); - LogRecordData logData = logDataList.get(0); - assertThat(logData) - .hasResource(resource) - .hasInstrumentationScope(instrumentationScopeInfo) - .hasBody("log message 1") - .hasTotalAttributeCount(4); + testing.waitAndAssertLogRecords( + logRecord -> + logRecord + .hasResource(resource) + .hasInstrumentationScope(instrumentationScopeInfo) + .hasBody("log message 1") + .hasTotalAttributeCount(4)); } } diff --git a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppenderTest.java b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppenderTest.java index 0b85ea22d4bc..6ed54d67537f 100644 --- a/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppenderTest.java +++ b/instrumentation/logback/logback-appender-1.0/library/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/OpenTelemetryAppenderTest.java @@ -5,23 +5,28 @@ package io.opentelemetry.instrumentation.logback.appender.v1_0; -import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; - import io.opentelemetry.api.trace.Span; import io.opentelemetry.api.trace.SpanContext; -import io.opentelemetry.context.Scope; -import io.opentelemetry.sdk.logs.data.LogRecordData; -import io.opentelemetry.sdk.trace.SdkTracerProvider; -import java.util.List; +import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension; +import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; class OpenTelemetryAppenderTest extends AbstractOpenTelemetryAppenderTest { + @RegisterExtension + private static final LibraryInstrumentationExtension testing = + LibraryInstrumentationExtension.create(); + @BeforeEach void setup() { - generalBeforeEachSetup(); - OpenTelemetryAppender.install(openTelemetrySdk); + OpenTelemetryAppender.install(testing.getOpenTelemetry()); + } + + @Override + protected InstrumentationExtension getTesting() { + return testing; } @Test @@ -29,28 +34,29 @@ void logWithSpan() { // Does not work for log replay but it is not likely to occ // 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 = runWithSpan("span1", () -> logger.info("log message 1")); + Span span1 = + testing.runWithSpan( + "span1", + () -> { + logger.info("log message 1"); + return Span.current(); + }); logger.info("log message 2"); executeAfterLogsExecution(); - Span span2 = runWithSpan("span2", () -> logger.info("log message 3")); - - List logDataList = logRecordExporter.getFinishedLogRecordItems(); - assertThat(logDataList).hasSize(3); - assertThat(logDataList.get(0)).hasSpanContext(span1.getSpanContext()); - assertThat(logDataList.get(1)).hasSpanContext(SpanContext.getInvalid()); - assertThat(logDataList.get(2)).hasSpanContext(span2.getSpanContext()); - } - - private static Span runWithSpan(String spanName, Runnable runnable) { - Span span = SdkTracerProvider.builder().build().get("tracer").spanBuilder(spanName).startSpan(); - try (Scope ignored = span.makeCurrent()) { - runnable.run(); - } finally { - span.end(); - } - return span; + Span span2 = + testing.runWithSpan( + "span2", + () -> { + logger.info("log message 3"); + return Span.current(); + }); + + testing.waitAndAssertLogRecords( + logRecord -> logRecord.hasSpanContext(span1.getSpanContext()), + logRecord -> logRecord.hasSpanContext(SpanContext.getInvalid()), + logRecord -> logRecord.hasSpanContext(span2.getSpanContext())); } } diff --git a/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java b/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java index 0426436e91d8..d66c9c86552d 100644 --- a/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java +++ b/testing-common/src/main/java/io/opentelemetry/instrumentation/testing/junit/InstrumentationExtension.java @@ -5,6 +5,7 @@ package io.opentelemetry.instrumentation.testing.junit; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; import static org.assertj.core.api.Assertions.assertThat; import static org.awaitility.Awaitility.await; @@ -18,11 +19,15 @@ import io.opentelemetry.sdk.OpenTelemetrySdk; import io.opentelemetry.sdk.logs.data.LogRecordData; import io.opentelemetry.sdk.metrics.data.MetricData; +import io.opentelemetry.sdk.testing.assertj.LogRecordDataAssert; import io.opentelemetry.sdk.testing.assertj.MetricAssert; import io.opentelemetry.sdk.testing.assertj.TraceAssert; import io.opentelemetry.sdk.trace.data.SpanData; import java.time.Duration; +import java.util.ArrayList; +import java.util.Arrays; import java.util.Comparator; +import java.util.Iterator; import java.util.List; import java.util.function.Consumer; import org.assertj.core.api.ListAssert; @@ -160,6 +165,27 @@ public final void waitAndAssertTraces(Iterable> testRunner.waitAndAssertTraces(assertions); } + private void doWaitAndAssertLogRecords(List> assertions) { + List logRecordDataList = waitForLogRecords(assertions.size()); + Iterator> assertionIterator = assertions.iterator(); + for (LogRecordData logRecordData : logRecordDataList) { + assertionIterator.next().accept(assertThat(logRecordData)); + } + } + + public final void waitAndAssertLogRecords( + Iterable> assertions) { + List> assertionsList = new ArrayList<>(); + assertions.forEach(assertionsList::add); + doWaitAndAssertLogRecords(assertionsList); + } + + @SafeVarargs + @SuppressWarnings("varargs") + public final void waitAndAssertLogRecords(Consumer... assertions) { + doWaitAndAssertLogRecords(Arrays.asList(assertions)); + } + /** * Runs the provided {@code callback} inside the scope of an INTERNAL span with name {@code * spanName}.