Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log4j2: add option to fill code attributes #12592

Merged
merged 6 commits into from
Nov 14, 2024
+300 −110
Merged

Log4j2: add option to fill code attributes #12592

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
6cff4f5
Log4j2: add option to fill code attributes
laurit Nov 8, 2024
d67cae2
use reflection
laurit Nov 8, 2024
44c25eb
spotless
laurit Nov 8, 2024
a880293
fix async test
laurit Nov 8, 2024
3eca7a1
address review comment
laurit Nov 8, 2024
99f1f82
fix latest dep test
laurit Nov 10, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 9 additions & 6 deletions instrumentation/log4j/log4j-appender-2.17/javaagent/README.md
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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");
jeanbisutti marked this conversation as resolved.
Show resolved Hide resolved
} 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
Open in desktop
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
Loading