From 3020b69730bbeab23bde6b815c932701075b7c4e Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Tue, 13 Sep 2022 21:31:43 -0700 Subject: [PATCH 1/3] Convert logback test to Java --- .../javaagent/build.gradle.kts | 1 + .../src/test/groovy/LogbackTest.groovy | 139 ---------- .../src/test/groovy/LogbackTest.java | 241 ++++++++++++++++++ .../junit/InstrumentationExtension.java | 6 + 4 files changed, 248 insertions(+), 139 deletions(-) delete mode 100644 instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy create mode 100644 instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts b/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts index 493bf9a34c12..0f6b34623c90 100644 --- a/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts +++ b/instrumentation/logback/logback-appender-1.0/javaagent/build.gradle.kts @@ -47,6 +47,7 @@ dependencies { implementation(project(":instrumentation:logback:logback-appender-1.0:library")) + testImplementation("io.opentelemetry:opentelemetry-sdk-logs-testing") testImplementation("org.awaitility:awaitility") } diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy deleted file mode 100644 index 8e7af56cb922..000000000000 --- a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.groovy +++ /dev/null @@ -1,139 +0,0 @@ -/* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ - -import io.opentelemetry.api.common.AttributeKey -import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification -import io.opentelemetry.sdk.logs.data.Severity -import io.opentelemetry.semconv.trace.attributes.SemanticAttributes -import org.slf4j.Logger -import org.slf4j.LoggerFactory -import org.slf4j.MDC -import spock.lang.Unroll - -import static org.assertj.core.api.Assertions.assertThat -import static org.awaitility.Awaitility.await - -class LogbackTest extends AgentInstrumentationSpecification { - - private static final Logger abcLogger = LoggerFactory.getLogger("abc") - private static final Logger defLogger = LoggerFactory.getLogger("def") - - @Unroll - def "test logger=#loggerName method=#testMethod with exception=#exception and parent=#parent"() { - when: - if (parent) { - runWithSpan("parent") { - if (exception) { - logger."$testMethod"("xyz: {}", 123, new IllegalStateException("hello")) - } else { - logger."$testMethod"("xyz: {}", 123) - } - } - } else { - if (exception) { - logger."$testMethod"("xyz: {}", 123, new IllegalStateException("hello")) - } else { - logger."$testMethod"("xyz: {}", 123) - } - } - - then: - if (parent) { - waitForTraces(1) - } - - String jvmVersion = System.getProperty("java.vm.specification.version") - int codeAttributes = 3 - boolean jvmVersionGreaterThanOrEqualTo18 = !jvmVersion.startsWith("1.8") && Integer.parseInt(jvmVersion) >= 18 - if (jvmVersionGreaterThanOrEqualTo18) { - codeAttributes = 4 // Java 18 specificity on line number (lineNumber > 0 check) - } - - if (severity != null) { - await() - .untilAsserted( - () -> { - assertThat(logs).hasSize(1) - }) - def log = logs.get(0) - assertThat(log.getBody().asString()).isEqualTo("xyz: 123") - assertThat(log.getInstrumentationScopeInfo().getName()).isEqualTo(loggerName) - assertThat(log.getSeverity()).isEqualTo(severity) - assertThat(log.getSeverityText()).isEqualTo(severityText) - if (exception) { - assertThat(log.getAttributes().size()).isEqualTo(5 + codeAttributes) - assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isEqualTo(IllegalStateException.getName()) - assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isEqualTo("hello") - assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).contains(LogbackTest.name) - } else { - assertThat(log.getAttributes().size()).isEqualTo(2 + codeAttributes) - assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_TYPE)).isNull() - assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_MESSAGE)).isNull() - assertThat(log.getAttributes().get(SemanticAttributes.EXCEPTION_STACKTRACE)).isNull() - } - assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName()) - assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId()) - if (parent) { - assertThat(log.getSpanContext()).isEqualTo(traces.get(0).get(0).getSpanContext()) - } else { - assertThat(log.getSpanContext().isValid()).isFalse() - } - } else { - Thread.sleep(500) // sleep a bit just to make sure no span is captured - logs.size() == 0 - } - - where: - [args, exception, parent] << [ - [ - [abcLogger, "abc", "debug", null, null], - [abcLogger, "abc", "info", Severity.INFO, "INFO"], - [abcLogger, "abc", "warn", Severity.WARN, "WARN"], - [abcLogger, "abc", "error", Severity.ERROR, "ERROR"], - [defLogger, "def", "debug", null, null], - [defLogger, "def", "info", null, null], - [defLogger, "def", "warn", Severity.WARN, "WARN"], - [defLogger, "def", "error", Severity.ERROR, "ERROR"] - ], - [true, false], - [true, false] - ].combinations() - - logger = args[0] - loggerName = args[1] - testMethod = args[2] - severity = args[3] - severityText = args[4] - } - - def "test mdc"() { - when: - MDC.put("key1", "val1") - MDC.put("key2", "val2") - try { - abcLogger.info("xyz: {}", 123) - } finally { - MDC.clear() - } - - then: - - await() - .untilAsserted( - () -> { - assertThat(logs).hasSize(1) - }) - def log = logs.get(0) - assertThat(log.getBody().asString()).isEqualTo("xyz: 123") - assertThat(log.getInstrumentationScopeInfo().getName()).isEqualTo("abc") - assertThat(log.getSeverity()).isEqualTo(Severity.INFO) - assertThat(log.getSeverityText()).isEqualTo("INFO") - assertThat(log.getAttributes().size()).isEqualTo(3 + 3) // 3 code attributes - assertThat(log.getAttributes().get(AttributeKey.stringKey("logback.mdc.key1"))).isEqualTo("val1") - assertThat(log.getAttributes().get(AttributeKey.stringKey("logback.mdc.key2"))).isEqualTo("val2") - assertThat(log.getAttributes().get(SemanticAttributes.THREAD_NAME)).isEqualTo(Thread.currentThread().getName()) - assertThat(log.getAttributes().get(SemanticAttributes.THREAD_ID)).isEqualTo(Thread.currentThread().getId()) - } -} diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java new file mode 100644 index 000000000000..5f04f6a85c54 --- /dev/null +++ b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java @@ -0,0 +1,241 @@ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat; +import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; +import static org.awaitility.Awaitility.await; + +import io.opentelemetry.api.common.AttributeKey; +import io.opentelemetry.instrumentation.test.AgentInstrumentationSpecification; +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.LogData; +import io.opentelemetry.sdk.logs.data.Severity; +import io.opentelemetry.semconv.trace.attributes.SemanticAttributes; +import java.util.stream.Stream; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.extension.RegisterExtension; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +class LogbackTest extends AgentInstrumentationSpecification { + + @RegisterExtension + static final InstrumentationExtension testing = AgentInstrumentationExtension.create(); + + private static final Logger abcLogger = LoggerFactory.getLogger("abc"); + private static final Logger defLogger = LoggerFactory.getLogger("def"); + + private static Stream provideParameters() { + return Stream.of( + Arguments.of(false, false), + Arguments.of(false, true), + Arguments.of(true, false), + Arguments.of(true, true)); + } + + @ParameterizedTest + @MethodSource("provideParameters") + public void test(boolean logException, boolean withParent) throws InterruptedException { + test(abcLogger, Logger::debug, Logger::debug, logException, withParent, null, null, null); + testing.clearData(); + test( + abcLogger, + Logger::info, + Logger::info, + logException, + withParent, + "abc", + Severity.INFO, + "INFO"); + testing.clearData(); + test( + abcLogger, + Logger::warn, + Logger::warn, + logException, + withParent, + "abc", + Severity.WARN, + "WARN"); + testing.clearData(); + test( + abcLogger, + Logger::error, + Logger::error, + logException, + withParent, + "abc", + Severity.ERROR, + "ERROR"); + testing.clearData(); + test(defLogger, Logger::debug, Logger::debug, logException, withParent, null, null, null); + testing.clearData(); + test(defLogger, Logger::info, Logger::info, logException, withParent, null, null, null); + testing.clearData(); + test( + defLogger, + Logger::warn, + Logger::warn, + logException, + withParent, + "def", + Severity.WARN, + "WARN"); + testing.clearData(); + test( + defLogger, + Logger::error, + Logger::error, + logException, + withParent, + "def", + Severity.ERROR, + "ERROR"); + testing.clearData(); + } + + private static void test( + Logger logger, + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException, + boolean withParent, + String expectedLoggerName, + Severity expectedSeverity, + String expectedSeverityText) + throws InterruptedException { + + // when + if (withParent) { + testing.runWithSpan( + "parent", + () -> { + performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException); + }); + } else { + performLogging(logger, oneArgLoggerMethod, twoArgLoggerMethod, logException); + } + + // then + if (withParent) { + testing.waitForTraces(1); + } + + if (expectedSeverity != null) { + await().untilAsserted(() -> assertThat(testing.logs().size()).isEqualTo(1)); + + LogData log = testing.logs().get(0); + assertThat(log) + .hasBody("xyz: 123") + // TODO (trask) why is version "" instead of null? + .hasInstrumentationScope( + InstrumentationScopeInfo.builder(expectedLoggerName).setVersion("").build()) + .hasSeverity(expectedSeverity) + .hasSeverityText(expectedSeverityText); + if (logException) { + assertThat(log) + .hasAttributesSatisfying( + attributes -> + assertThat(attributes) + .hasSize(9) + .containsEntry( + SemanticAttributes.EXCEPTION_TYPE, + IllegalStateException.class.getName()) + .containsEntry(SemanticAttributes.EXCEPTION_MESSAGE, "hello") + .hasEntrySatisfying( + SemanticAttributes.EXCEPTION_STACKTRACE, + value -> assertThat(value).contains(LogbackTest.class.getName()))); + } else { + assertThat(log.getAttributes()).hasSize(6); + } + + assertThat(log) + .hasAttributesSatisfying( + attributes -> + assertThat(attributes) + .containsEntry( + SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()) + .containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()) + .containsEntry(SemanticAttributes.CODE_NAMESPACE, "LogbackTest") + .containsEntry(SemanticAttributes.CODE_FUNCTION, "performLogging") + .hasEntrySatisfying( + SemanticAttributes.CODE_LINENO, value -> assertThat(value).isPositive()) + .containsEntry(SemanticAttributes.CODE_FILEPATH, "LogbackTest.java")); + + if (withParent) { + assertThat(log.getSpanContext()).isEqualTo(testing.spans().get(0).getSpanContext()); + } else { + assertThat(log.getSpanContext().isValid()).isFalse(); + } + + } else { + Thread.sleep(500); // sleep a bit just to make sure no log is captured + assertThat(testing.logs()).isEmpty(); + } + } + + @Test + void testMdc() { + MDC.put("key1", "val1"); + MDC.put("key2", "val2"); + try { + abcLogger.info("xyz: {}", 123); + } finally { + MDC.clear(); + } + + await().untilAsserted(() -> assertThat(testing.logs().size()).isEqualTo(1)); + + LogData log = getLogs().get(0); + assertThat(log) + .hasBody("xyz: 123") + // TODO (trask) why is version "" instead of null? + .hasInstrumentationScope(InstrumentationScopeInfo.builder("abc").setVersion("").build()) + .hasSeverity(Severity.INFO) + .hasSeverityText("INFO") + // TODO (trask) convert to hasAttributesSatisfyingExactly once that's available for logs + .hasAttributesSatisfying( + attributes -> + assertThat(attributes) + .hasSize(8) + .containsEntry(AttributeKey.stringKey("logback.mdc.key1"), "val1") + .containsEntry(AttributeKey.stringKey("logback.mdc.key2"), "val2") + .containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()) + .containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()) + .containsEntry(SemanticAttributes.CODE_NAMESPACE, "LogbackTest") + .containsEntry(SemanticAttributes.CODE_FUNCTION, "testMdc") + .hasEntrySatisfying( + SemanticAttributes.CODE_LINENO, value -> assertThat(value).isPositive()) + .containsEntry(SemanticAttributes.CODE_FILEPATH, "LogbackTest.java")); + } + + private static void performLogging( + Logger logger, + OneArgLoggerMethod oneArgLoggerMethod, + TwoArgLoggerMethod twoArgLoggerMethod, + boolean logException) { + if (logException) { + twoArgLoggerMethod.call(logger, "xyz: {}", 123, new IllegalStateException("hello")); + } else { + oneArgLoggerMethod.call(logger, "xyz: {}", 123); + } + } + + @FunctionalInterface + interface OneArgLoggerMethod { + void call(Logger logger, String msg, Object arg); + } + + @FunctionalInterface + interface TwoArgLoggerMethod { + void call(Logger logger, String msg, Object arg1, Object arg2); + } +} diff --git a/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 e790da8f6c5b..22572836c9d3 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 @@ -16,6 +16,7 @@ import io.opentelemetry.instrumentation.testing.util.ThrowingRunnable; import io.opentelemetry.instrumentation.testing.util.ThrowingSupplier; import io.opentelemetry.sdk.OpenTelemetrySdk; +import io.opentelemetry.sdk.logs.data.LogData; import io.opentelemetry.sdk.metrics.data.MetricData; import io.opentelemetry.sdk.testing.assertj.TraceAssert; import io.opentelemetry.sdk.trace.data.SpanData; @@ -74,6 +75,11 @@ public List metrics() { return testRunner.getExportedMetrics(); } + /** Return a list of all captured logs. */ + public List logs() { + return testRunner.getExportedLogs(); + } + /** * Waits for the assertion applied to all metrics of the given instrumentation and metric name to * pass. From ddb6d0694b008f71f1b67a649c5fe0af0fb11a4c Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Wed, 14 Sep 2022 08:53:33 -0700 Subject: [PATCH 2/3] Move test to the right place --- .../logback/appender/v1_0}/LogbackTest.java | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) rename instrumentation/logback/logback-appender-1.0/javaagent/src/test/{groovy => java/io/opentelemetry/instrumentation/logback/appender/v1_0}/LogbackTest.java (96%) diff --git a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java similarity index 96% rename from instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java rename to instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java index 5f04f6a85c54..2c88f7798ee4 100644 --- a/instrumentation/logback/logback-appender-1.0/javaagent/src/test/groovy/LogbackTest.java +++ b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java @@ -1,7 +1,7 @@ -/* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ +package io.opentelemetry.instrumentation.logback.appender.v1_0; /* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat; import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat; @@ -164,7 +164,7 @@ private static void test( .containsEntry( SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()) .containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()) - .containsEntry(SemanticAttributes.CODE_NAMESPACE, "LogbackTest") + .containsEntry(SemanticAttributes.CODE_NAMESPACE, LogbackTest.class.getName()) .containsEntry(SemanticAttributes.CODE_FUNCTION, "performLogging") .hasEntrySatisfying( SemanticAttributes.CODE_LINENO, value -> assertThat(value).isPositive()) @@ -210,7 +210,7 @@ void testMdc() { .containsEntry(AttributeKey.stringKey("logback.mdc.key2"), "val2") .containsEntry(SemanticAttributes.THREAD_NAME, Thread.currentThread().getName()) .containsEntry(SemanticAttributes.THREAD_ID, Thread.currentThread().getId()) - .containsEntry(SemanticAttributes.CODE_NAMESPACE, "LogbackTest") + .containsEntry(SemanticAttributes.CODE_NAMESPACE, LogbackTest.class.getName()) .containsEntry(SemanticAttributes.CODE_FUNCTION, "testMdc") .hasEntrySatisfying( SemanticAttributes.CODE_LINENO, value -> assertThat(value).isPositive()) From 2ec1a4085a6b7aa9d3d20d86f1b71e5b07327c3c Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Wed, 14 Sep 2022 09:17:20 -0700 Subject: [PATCH 3/3] spotless --- .../logback/appender/v1_0/LogbackTest.java | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) 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 2c88f7798ee4..3c0fa46f8023 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 @@ -1,7 +1,9 @@ -package io.opentelemetry.instrumentation.logback.appender.v1_0; /* - * Copyright The OpenTelemetry Authors - * SPDX-License-Identifier: Apache-2.0 - */ +/* + * Copyright The OpenTelemetry Authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package io.opentelemetry.instrumentation.logback.appender.v1_0; import static io.opentelemetry.sdk.testing.assertj.LogAssertions.assertThat; import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.assertThat;