Skip to content

Commit 15e611e

Browse files
lauritlaurit
authored
Log4j2: add option to fill code attributes (#12592)
1 parent e91bb38 commit 15e611e

File tree

15 files changed

+300
-110
lines changed

15 files changed

+300
-110
lines changed

‎instrumentation/log4j/log4j-appender-2.17/javaagent/README.md

+9-6
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,11 @@
11
# Settings for the Log4j Appender instrumentation
22

3-
| System property | Type | Default | Description |
4-
|-----------------------------------------------------------------------------------| ------- | ------- |-----------------------------------------------------------------------------------------------------------------------|
5-
| `otel.instrumentation.log4j-appender.experimental-log-attributes` | Boolean | `false` | Enable the capture of experimental log attributes `thread.name` and `thread.id`. |
6-
| `otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes` | Boolean | `false` | Enable the capture of `MapMessage` attributes. |
7-
| `otel.instrumentation.log4j-appender.experimental.capture-marker-attribute` | Boolean | `false` | Enable the capture of Log4j markers as attributes. |
8-
| `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. |
3+
| System property | Type | Default | Description |
4+
|-----------------------------------------------------------------------------------|---------|---------|-----------------------------------------------------------------------------------------------------------------------------------------------|
5+
| `otel.instrumentation.log4j-appender.experimental-log-attributes` | Boolean | `false` | Enable the capture of experimental log attributes `thread.name` and `thread.id`. |
6+
| `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. |
7+
| `otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes` | Boolean | `false` | Enable the capture of `MapMessage` attributes. |
8+
| `otel.instrumentation.log4j-appender.experimental.capture-marker-attribute` | Boolean | `false` | Enable the capture of Log4j markers as attributes. |
9+
| `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. |
10+
11+
[source code attributes]: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/attributes.md#source-code-attributes

‎instrumentation/log4j/log4j-appender-2.17/javaagent/build.gradle.kts

+3-2
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ muzzle {
1414
val testLatestDeps = findProperty("testLatestDeps") as Boolean
1515

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

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

@@ -56,9 +56,10 @@ tasks {
5656

5757
tasks.withType<Test>().configureEach {
5858
// TODO run tests both with and without experimental log attributes
59+
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
60+
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-code-attributes=true")
5961
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-map-message-attributes=true")
6062
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-mdc-attributes=*")
61-
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental-log-attributes=true")
6263
jvmArgs("-Dotel.instrumentation.log4j-appender.experimental.capture-marker-attribute=true")
6364
}
6465

‎instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jAppenderInstrumentation.java

+5-2
Original file line numberDiff line numberDiff line change
@@ -73,14 +73,16 @@ public static void methodEnter(
7373
@Advice.This Logger logger,
7474
@Advice.Argument(0) Level level,
7575
@Advice.Argument(1) Marker marker,
76+
@Advice.Argument(2) String loggerClassName,
77+
@Advice.Argument(3) StackTraceElement location,
7678
@Advice.Argument(4) Message message,
7779
@Advice.Argument(5) Throwable t,
7880
@Advice.Local("otelCallDepth") CallDepth callDepth) {
7981
// need to track call depth across all loggers in order to avoid double capture when one
8082
// logging framework delegates to another
8183
callDepth = CallDepth.forClass(LoggerProvider.class);
8284
if (callDepth.getAndIncrement() == 0) {
83-
Log4jHelper.capture(logger, level, marker, message, t);
85+
Log4jHelper.capture(logger, loggerClassName, location, level, marker, message, t);
8486
}
8587
}
8688

@@ -96,6 +98,7 @@ public static class LogMessageAdvice {
9698
@Advice.OnMethodEnter(suppress = Throwable.class)
9799
public static void methodEnter(
98100
@Advice.This Logger logger,
101+
@Advice.Argument(0) String loggerClassName,
99102
@Advice.Argument(1) Level level,
100103
@Advice.Argument(2) Marker marker,
101104
@Advice.Argument(3) Message message,
@@ -105,7 +108,7 @@ public static void methodEnter(
105108
// logging framework delegates to another
106109
callDepth = CallDepth.forClass(LoggerProvider.class);
107110
if (callDepth.getAndIncrement() == 0) {
108-
Log4jHelper.capture(logger, level, marker, message, t);
111+
Log4jHelper.capture(logger, loggerClassName, null, level, marker, message, t);
109112
}
110113
}
111114

‎instrumentation/log4j/log4j-appender-2.17/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/log4j/appender/v2_17/Log4jHelper.java

+58-2
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,9 @@
1414
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataAccessor;
1515
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.LogEventMapper;
1616
import io.opentelemetry.javaagent.bootstrap.internal.AgentInstrumentationConfig;
17+
import java.lang.invoke.MethodHandle;
18+
import java.lang.invoke.MethodHandles;
19+
import java.lang.invoke.MethodType;
1720
import java.time.Instant;
1821
import java.util.List;
1922
import java.util.Map;
@@ -28,14 +31,17 @@
2831
public final class Log4jHelper {
2932

3033
private static final LogEventMapper<Map<String, String>> mapper;
31-
3234
private static final boolean captureExperimentalAttributes;
35+
private static final MethodHandle stackTraceMethodHandle = getStackTraceMethodHandle();
3336

3437
static {
3538
InstrumentationConfig config = AgentInstrumentationConfig.get();
3639

3740
captureExperimentalAttributes =
3841
config.getBoolean("otel.instrumentation.log4j-appender.experimental-log-attributes", false);
42+
boolean captureCodeAttributes =
43+
config.getBoolean(
44+
"otel.instrumentation.log4j-appender.experimental.capture-code-attributes", false);
3945
boolean captureMapMessageAttributes =
4046
config.getBoolean(
4147
"otel.instrumentation.log4j-appender.experimental.capture-map-message-attributes",
@@ -51,13 +57,20 @@ public final class Log4jHelper {
5157
new LogEventMapper<>(
5258
ContextDataAccessorImpl.INSTANCE,
5359
captureExperimentalAttributes,
60+
captureCodeAttributes,
5461
captureMapMessageAttributes,
5562
captureMarkerAttribute,
5663
captureContextDataAttributes);
5764
}
5865

5966
public static void capture(
60-
Logger logger, Level level, Marker marker, Message message, Throwable throwable) {
67+
Logger logger,
68+
String loggerClassName,
69+
StackTraceElement location,
70+
Level level,
71+
Marker marker,
72+
Message message,
73+
Throwable throwable) {
6174
String instrumentationName = logger.getName();
6275
if (instrumentationName == null || instrumentationName.isEmpty()) {
6376
instrumentationName = "ROOT";
@@ -86,11 +99,54 @@ public static void capture(
8699
contextData,
87100
threadName,
88101
threadId,
102+
() -> location != null ? location : getLocation(loggerClassName),
89103
Context.current());
90104
builder.setTimestamp(Instant.now());
91105
builder.emit();
92106
}
93107

108+
private static StackTraceElement getLocation(String loggerClassName) {
109+
if (stackTraceMethodHandle == null) {
110+
return null;
111+
}
112+
113+
try {
114+
return (StackTraceElement) stackTraceMethodHandle.invoke(loggerClassName);
115+
} catch (Throwable exception) {
116+
return null;
117+
}
118+
}
119+
120+
private static MethodHandle getStackTraceMethodHandle() {
121+
Class<?> stackTraceClass = null;
122+
try {
123+
// since 2.9.0
124+
stackTraceClass = Class.forName("org.apache.logging.log4j.util.StackLocatorUtil");
125+
} catch (ClassNotFoundException exception) {
126+
// ignore
127+
}
128+
if (stackTraceClass == null) {
129+
try {
130+
// before 2.9.0
131+
stackTraceClass = Class.forName("org.apache.logging.log4j.core.impl.Log4jLogEvent");
132+
} catch (ClassNotFoundException exception) {
133+
// ignore
134+
}
135+
}
136+
if (stackTraceClass == null) {
137+
return null;
138+
}
139+
try {
140+
return MethodHandles.lookup()
141+
.findStatic(
142+
stackTraceClass,
143+
"calcLocation",
144+
MethodType.methodType(StackTraceElement.class, String.class));
145+
} catch (Exception exception) {
146+
return null;
147+
}
148+
}
149+
94150
private enum ContextDataAccessorImpl implements ContextDataAccessor<Map<String, String>> {
95151
INSTANCE;
96152

‎instrumentation/log4j/log4j-appender-2.17/javaagent/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/Log4j2Test.java

+43-20
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,12 @@
1111
import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_MESSAGE;
1212
import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_STACKTRACE;
1313
import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_TYPE;
14+
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_FILEPATH;
15+
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_FUNCTION;
16+
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_LINENO;
17+
import static io.opentelemetry.semconv.incubating.CodeIncubatingAttributes.CODE_NAMESPACE;
18+
import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_ID;
19+
import static io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes.THREAD_NAME;
1420
import static java.util.concurrent.TimeUnit.MILLISECONDS;
1521

1622
import io.opentelemetry.api.common.AttributeKey;
@@ -22,7 +28,6 @@
2228
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
2329
import io.opentelemetry.sdk.logs.data.LogRecordData;
2430
import io.opentelemetry.sdk.testing.assertj.AttributeAssertion;
25-
import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes;
2631
import java.time.Instant;
2732
import java.util.ArrayList;
2833
import java.util.Arrays;
@@ -35,6 +40,7 @@
3540
import org.apache.logging.log4j.ThreadContext;
3641
import org.apache.logging.log4j.message.StringMapMessage;
3742
import org.apache.logging.log4j.message.StructuredDataMessage;
43+
import org.assertj.core.api.AbstractLongAssert;
3844
import org.assertj.core.api.AssertAccess;
3945
import org.junit.jupiter.api.Test;
4046
import org.junit.jupiter.api.extension.RegisterExtension;
@@ -112,11 +118,12 @@ private static void test(
112118
List<AttributeAssertion> attributeAsserts =
113119
new ArrayList<>(
114120
Arrays.asList(
115-
equalTo(
116-
ThreadIncubatingAttributes.THREAD_NAME,
117-
Thread.currentThread().getName()),
118-
equalTo(
119-
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
121+
equalTo(THREAD_NAME, Thread.currentThread().getName()),
122+
equalTo(THREAD_ID, Thread.currentThread().getId()),
123+
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
124+
equalTo(CODE_FUNCTION, "performLogging"),
125+
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
126+
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
120127
if (logException) {
121128
attributeAsserts.addAll(
122129
Arrays.asList(
@@ -158,9 +165,12 @@ void testContextData() {
158165
.hasAttributesSatisfyingExactly(
159166
equalTo(AttributeKey.stringKey("key1"), "val1"),
160167
equalTo(AttributeKey.stringKey("key2"), "val2"),
161-
equalTo(
162-
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
163-
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
168+
equalTo(THREAD_NAME, Thread.currentThread().getName()),
169+
equalTo(THREAD_ID, Thread.currentThread().getId()),
170+
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
171+
equalTo(CODE_FUNCTION, "testContextData"),
172+
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
173+
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
164174
}
165175

166176
@Test
@@ -180,9 +190,12 @@ void testStringMapMessage() {
180190
.hasAttributesSatisfyingExactly(
181191
equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"),
182192
equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2"),
183-
equalTo(
184-
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
185-
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
193+
equalTo(THREAD_NAME, Thread.currentThread().getName()),
194+
equalTo(THREAD_ID, Thread.currentThread().getId()),
195+
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
196+
equalTo(CODE_FUNCTION, "testStringMapMessage"),
197+
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
198+
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
186199
}
187200

188201
@Test
@@ -201,9 +214,12 @@ void testStringMapMessageWithSpecialAttribute() {
201214
.hasSeverityText("INFO")
202215
.hasAttributesSatisfyingExactly(
203216
equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"),
204-
equalTo(
205-
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
206-
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
217+
equalTo(THREAD_NAME, Thread.currentThread().getName()),
218+
equalTo(THREAD_ID, Thread.currentThread().getId()),
219+
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
220+
equalTo(CODE_FUNCTION, "testStringMapMessageWithSpecialAttribute"),
221+
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
222+
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
207223
}
208224

209225
@Test
@@ -223,9 +239,12 @@ void testStructuredDataMapMessage() {
223239
.hasAttributesSatisfyingExactly(
224240
equalTo(AttributeKey.stringKey("log4j.map_message.key1"), "val1"),
225241
equalTo(AttributeKey.stringKey("log4j.map_message.key2"), "val2"),
226-
equalTo(
227-
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
228-
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
242+
equalTo(THREAD_NAME, Thread.currentThread().getName()),
243+
equalTo(THREAD_ID, Thread.currentThread().getId()),
244+
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
245+
equalTo(CODE_FUNCTION, "testStructuredDataMapMessage"),
246+
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
247+
equalTo(CODE_FILEPATH, "Log4j2Test.java")));
229248
}
230249

231250
@Test
@@ -238,8 +257,12 @@ public void testMarker() {
238257
testing.waitAndAssertLogRecords(
239258
logRecord ->
240259
logRecord.hasAttributesSatisfyingExactly(
241-
equalTo(ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
242-
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
260+
equalTo(THREAD_NAME, Thread.currentThread().getName()),
261+
equalTo(THREAD_ID, Thread.currentThread().getId()),
262+
equalTo(CODE_NAMESPACE, Log4j2Test.class.getName()),
263+
equalTo(CODE_FUNCTION, "testMarker"),
264+
satisfies(CODE_LINENO, AbstractLongAssert::isPositive),
265+
equalTo(CODE_FILEPATH, "Log4j2Test.java"),
243266
equalTo(AttributeKey.stringKey("log4j.marker"), markerName)));
244267
}
245268

0 commit comments

Comments
 (0)