From a979c4f63fe496c55149fa49b42e6839d7b3694d Mon Sep 17 00:00:00 2001 From: Trask Stalnaker Date: Wed, 14 Sep 2022 10:58:59 -0700 Subject: [PATCH] Convert logback test to Java (#6613) --- .../javaagent/build.gradle.kts | 1 + .../src/test/groovy/LogbackTest.groovy | 139 ---------- .../logback/appender/v1_0/LogbackTest.java | 243 ++++++++++++++++++ .../junit/InstrumentationExtension.java | 6 + 4 files changed, 250 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/java/io/opentelemetry/instrumentation/logback/appender/v1_0/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/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 new file mode 100644 index 000000000000..3c0fa46f8023 --- /dev/null +++ b/instrumentation/logback/logback-appender-1.0/javaagent/src/test/java/io/opentelemetry/instrumentation/logback/appender/v1_0/LogbackTest.java @@ -0,0 +1,243 @@ +/* + * 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; +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.class.getName()) + .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.class.getName()) + .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.