Skip to content

Commit

Permalink
Log4j2: add option to fill code attributes (open-telemetry#12592)
Browse files Browse the repository at this point in the history
  • Loading branch information
@laurit
laurit authored and Alex Kats committed Nov 21, 2024
1 parent 86cdef1 commit 9492291
Show file tree
Hide file tree
Showing 15 changed files with 300 additions and 110 deletions.
15 changes: 9 additions & 6 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/README.md
View file
Original file line number Diff line number Diff line change
@@ -1,8 +1,11 @@
# Settings for the Log4j Appender instrumentation

| System property | Type | Default | Description |
|-----------------------------------------------------------------------------------| ------- | ------- |-----------------------------------------------------------------------------------------------------------------------|
| `otel.instrumentation.log4j-appender.experimental-log-attributes` | Boolean | `false` | Enable the capture of experimental log attributes `thread.name` and `thread.id`. |
| `otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes` | Boolean | `false` | Enable the capture of `MapMessage` attributes. |
| `otel.instrumentation.log4j-appender.experimental.capture-marker-attribute` | Boolean | `false` | Enable the capture of Log4j markers as attributes. |
| `otel.instrumentation.log4j-appender.experimental.capture-mdc-attributes` | String | | Comma separated list of context data attributes to capture. Use the wildcard character `*` to capture all attributes. |
| System property | Type | Default | Description |
|-----------------------------------------------------------------------------------|---------|---------|-----------------------------------------------------------------------------------------------------------------------------------------------|
| `otel.instrumentation.log4j-appender.experimental-log-attributes` | Boolean | `false` | Enable the capture of experimental log attributes `thread.name` and `thread.id`. |
| `otel.instrumentation.log4j-appender.experimental.capture-code-attributes` | Boolean | `false` | Enable the capture of [source code attributes]. Note that capturing source code attributes at logging sites might add a performance overhead. |
| `otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes` | Boolean | `false` | Enable the capture of `MapMessage` attributes. |
| `otel.instrumentation.log4j-appender.experimental.capture-marker-attribute` | Boolean | `false` | Enable the capture of Log4j markers as attributes. |
| `otel.instrumentation.log4j-appender.experimental.capture-mdc-attributes` | String | | Comma separated list of context data attributes to capture. Use the wildcard character `*` to capture all attributes. |

[source code attributes]: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/attributes.md#source-code-attributes
5 changes: 3 additions & 2 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,7 @@ muzzle {
val testLatestDeps = findProperty("testLatestDeps") as Boolean

dependencies {
library("org.apache.logging.log4j:log4j-core:2.17.0")
library("org.apache.logging.log4j:log4j-core:2.0")

compileOnly(project(":javaagent-bootstrap"))

Expand Down Expand Up @@ -56,9 +56,10 @@ tasks {

tasks.withType<Test>().configureEach {
// TODO run tests both with and without experimental log attributes
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-code-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-map-message-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-mdc-attributes=*")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-marker-attribute=true")
}

Expand Down
7 changes: 5 additions & 2 deletions ...elemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -73,14 +73,16 @@ public static void methodEnter(
@Advice.This Logger logger,
@Advice.Argument(0) Level level,
@Advice.Argument(1) Marker marker,
@Advice.Argument(2) String loggerClassName,
@Advice.Argument(3) StackTraceElement location,
@Advice.Argument(4) Message message,
@Advice.Argument(5) Throwable t,
@Advice.Local("otelCallDepth") CallDepth callDepth) {
// need to track call depth across all loggers in order to avoid double capture when one
// logging framework delegates to another
callDepth = CallDepth.forClass(LoggerProvider.class);
if (callDepth.getAndIncrement() == 0) {
Log4jHelper.capture(logger, level, marker, message, t);
Log4jHelper.capture(logger, loggerClassName, location, level, marker, message, t);
}
}

Expand All @@ -96,6 +98,7 @@ public static class LogMessageAdvice {
@Advice.OnMethodEnter(suppress = Throwable.class)
public static void methodEnter(
@Advice.This Logger logger,
@Advice.Argument(0) String loggerClassName,
@Advice.Argument(1) Level level,
@Advice.Argument(2) Marker marker,
@Advice.Argument(3) Message message,
Expand All @@ -105,7 +108,7 @@ public static void methodEnter(
// logging framework delegates to another
callDepth = CallDepth.forClass(LoggerProvider.class);
if (callDepth.getAndIncrement() == 0) {
Log4jHelper.capture(logger, level, marker, message, t);
Log4jHelper.capture(logger, loggerClassName, null, level, marker, message, t);
}
}

Expand Down
60 changes: 58 additions & 2 deletions ...ain/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jHelper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,9 @@
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataAccessor;
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.LogEventMapper;
import io.opentelemetry.javaagent.bootstrap.internal.AgentInstrumentationConfig;
import java.lang.invoke.MethodHandle;
import java.lang.invoke.MethodHandles;
import java.lang.invoke.MethodType;
import java.time.Instant;
import java.util.List;
import java.util.Map;
Expand All @@ -28,14 +31,17 @@
public final class Log4jHelper {

private static final LogEventMapper<Map<String, String>> mapper;

private static final boolean captureExperimentalAttributes;
private static final MethodHandle stackTraceMethodHandle = getStackTraceMethodHandle();

static {
InstrumentationConfig config = AgentInstrumentationConfig.get();

captureExperimentalAttributes =
config.getBoolean("otel.instrumentation.log4j-appender.experimental-log-attributes", false);
boolean captureCodeAttributes =
config.getBoolean(
"otel.instrumentation.log4j-appender.experimental.capture-code-attributes", false);
boolean captureMapMessageAttributes =
config.getBoolean(
"otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes",
Expand All @@ -51,13 +57,20 @@ public final class Log4jHelper {
new LogEventMapper<>(
ContextDataAccessorImpl.INSTANCE,
captureExperimentalAttributes,
captureCodeAttributes,
captureMapMessageAttributes,
captureMarkerAttribute,
captureContextDataAttributes);
}

public static void capture(
Logger logger, Level level, Marker marker, Message message, Throwable throwable) {
Logger logger,
String loggerClassName,
StackTraceElement location,
Level level,
Marker marker,
Message message,
Throwable throwable) {
String instrumentationName = logger.getName();
if (instrumentationName == null || instrumentationName.isEmpty()) {
instrumentationName = "ROOT";
Expand Down Expand Up @@ -86,11 +99,54 @@ public static void capture(
contextData,
threadName,
threadId,
() -> location != null ? location : getLocation(loggerClassName),
Context.current());
builder.setTimestamp(Instant.now());
builder.emit();
}

private static StackTraceElement getLocation(String loggerClassName) {
if (stackTraceMethodHandle == null) {
return null;
}

try {
return (StackTraceElement) stackTraceMethodHandle.invoke(loggerClassName);
} catch (Throwable exception) {
return null;
}
}

private static MethodHandle getStackTraceMethodHandle() {
Class<?> stackTraceClass = null;
try {
// since 2.9.0
stackTraceClass = Class.forName("org.apache.logging.log4j.util.StackLocatorUtil");
} catch (ClassNotFoundException exception) {
// ignore
}
if (stackTraceClass == null) {
try {
// before 2.9.0
stackTraceClass = Class.forName("org.apache.logging.log4j.core.impl.Log4jLogEvent");
} catch (ClassNotFoundException exception) {
// ignore
}
}
if (stackTraceClass == null) {
return null;
}
try {
return MethodHandles.lookup()
.findStatic(
stackTraceClass,
"calcLocation",
MethodType.methodType(StackTraceElement.class, String.class));
} catch (Exception exception) {
return null;
}
}

private enum ContextDataAccessorImpl implements ContextDataAccessor<Map<String, String>> {
INSTANCE;

Expand Down
63 changes: 43 additions & 20 deletions ...agent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,12 @@
import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_MESSAGE;
import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_STACKTRACE;
import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_TYPE;
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_FILEPATH;
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_FUNCTION;
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_LINENO;
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_NAMESPACE;
import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_ID;
import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_NAME;
import static java.util.concurrent.TimeUnit.MILLISECONDS;

import io.opentelemetry.api.common.AttributeKey;
Expand All @@ -22,7 +28,6 @@
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
import io.opentelemetry.sdk.logs.data.LogRecordData;
import io.opentelemetry.sdk.testing.assertj.AttributeAssertion;
import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes;
import java.time.Instant;
import java.util.ArrayList;
import java.util.Arrays;
Expand All @@ -35,6 +40,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.AbstractLongAssert;
import org.assertj.core.api.AssertAccess;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.RegisterExtension;
Expand Down Expand Up @@ -112,11 +118,12 @@ private static void test(
List<AttributeAssertion> attributeAsserts =
new ArrayList<>(
Arrays.asList(
equalTo(
ThreadIncubatingAttributes.THREAD_NAME,
Thread.currentThread().getName()),
equalTo(
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
equalTo(THREAD_NAME, Thread.currentThread().getName()),
equalTo(THREAD_ID, Thread.currentThread().getId()),
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
equalTo(CODE_FUNCTION, "performLogging"),
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
if (logException) {
attributeAsserts.addAll(
Arrays.asList(
Expand Down Expand Up @@ -158,9 +165,12 @@ void testContextData() {
.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(THREAD_NAME, Thread.currentThread().getName()),
equalTo(THREAD_ID, Thread.currentThread().getId()),
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
equalTo(CODE_FUNCTION, "testContextData"),
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
}

@Test
Expand All @@ -180,9 +190,12 @@ void testStringMapMessage() {
.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())));
equalTo(THREAD_NAME, Thread.currentThread().getName()),
equalTo(THREAD_ID, Thread.currentThread().getId()),
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
equalTo(CODE_FUNCTION, "testStringMapMessage"),
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
}

@Test
Expand All @@ -201,9 +214,12 @@ void testStringMapMessageWithSpecialAttribute() {
.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())));
equalTo(THREAD_NAME, Thread.currentThread().getName()),
equalTo(THREAD_ID, Thread.currentThread().getId()),
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
equalTo(CODE_FUNCTION, "testStringMapMessageWithSpecialAttribute"),
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
}

@Test
Expand All @@ -223,9 +239,12 @@ void testStructuredDataMapMessage() {
.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())));
equalTo(THREAD_NAME, Thread.currentThread().getName()),
equalTo(THREAD_ID, Thread.currentThread().getId()),
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
equalTo(CODE_FUNCTION, "testStructuredDataMapMessage"),
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
}

@Test
Expand All @@ -238,8 +257,12 @@ public void testMarker() {
testing.waitAndAssertLogRecords(
logRecord ->
logRecord.hasAttributesSatisfyingExactly(
equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
equalTo(THREAD_NAME, Thread.currentThread().getName()),
equalTo(THREAD_ID, Thread.currentThread().getId()),
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
equalTo(CODE_FUNCTION, "testMarker"),
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
equalTo(CODE_FILEPATH, "Log4j2Test.java"),
equalTo(AttributeKey.stringKey("log4j.marker"), markerName)));
}

Expand Down
Loading

0 comments on commit 9492291

Please sign in to comment.