Skip to content

Commit e8c5c06

Browse files
lauritlaurit
authored
Fix capturing context in log4j library instrumentation with async logger (#12176)
1 parent c2713e1 commit e8c5c06

File tree

14 files changed

+174
-42
lines changed

14 files changed

+174
-42
lines changed

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ dependencies {
3737
}
3838

3939
// this is needed for the async logging test
40-
testImplementation("com.lmax:disruptor:3.4.2")
40+
testLibrary("com.lmax:disruptor:3.4.2")
4141
}
4242

4343
tasks.withType<Test>().configureEach {

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

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99

1010
import io.opentelemetry.api.GlobalOpenTelemetry;
1111
import io.opentelemetry.api.logs.LogRecordBuilder;
12+
import io.opentelemetry.context.Context;
1213
import io.opentelemetry.instrumentation.api.incubator.config.internal.InstrumentationConfig;
1314
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataAccessor;
1415
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.LogEventMapper;
@@ -77,7 +78,15 @@ public static void capture(
7778
threadId = currentThread.getId();
7879
}
7980
mapper.mapLogEvent(
80-
builder, message, level, marker, throwable, contextData, threadName, threadId);
81+
builder,
82+
message,
83+
level,
84+
marker,
85+
throwable,
86+
contextData,
87+
threadName,
88+
threadId,
89+
Context.current());
8190
builder.setTimestamp(Instant.now());
8291
builder.emit();
8392
}
@@ -87,12 +96,12 @@ private enum ContextDataAccessorImpl implements ContextDataAccessor<Map<String,
8796

8897
@Override
8998
@Nullable
90-
public Object getValue(Map<String, String> contextData, String key) {
99+
public String getValue(Map<String, String> contextData, String key) {
91100
return contextData.get(key);
92101
}
93102

94103
@Override
95-
public void forEach(Map<String, String> contextData, BiConsumer<String, Object> action) {
104+
public void forEach(Map<String, String> contextData, BiConsumer<String, String> action) {
96105
contextData.forEach(action);
97106
}
98107
}

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

Lines changed: 15 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,13 +6,26 @@ dependencies {
66
library("org.apache.logging.log4j:log4j-core:2.17.0")
77
annotationProcessor("org.apache.logging.log4j:log4j-core:2.17.0")
88

9+
implementation(project(":instrumentation:log4j:log4j-context-data:log4j-context-data-2.17:library-autoconfigure"))
10+
911
testImplementation("io.opentelemetry:opentelemetry-sdk-testing")
12+
testLibrary("com.lmax:disruptor:3.3.4")
1013

1114
if (findProperty("testLatestDeps") as Boolean) {
1215
testCompileOnly("biz.aQute.bnd:biz.aQute.bnd.annotation:7.0.0")
1316
}
1417
}
1518

16-
tasks.withType<Test>().configureEach {
17-
jvmArgs("-Dotel.instrumentation.common.experimental.controller-telemetry.enabled=true")
19+
tasks {
20+
withType<Test>().configureEach {
21+
jvmArgs("-Dotel.instrumentation.common.experimental.controller-telemetry.enabled=true")
22+
}
23+
24+
val testAsyncLogger by registering(Test::class) {
25+
jvmArgs("-DLog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector")
26+
}
27+
28+
check {
29+
dependsOn(testAsyncLogger)
30+
}
1831
}

‎instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogEventToReplay.java

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
import org.apache.logging.log4j.message.StringMapMessage;
1919
import org.apache.logging.log4j.message.StructuredDataMessage;
2020
import org.apache.logging.log4j.util.ReadOnlyStringMap;
21+
import org.apache.logging.log4j.util.SortedArrayStringMap;
2122

2223
class LogEventToReplay implements LogEvent {
2324

@@ -59,7 +60,8 @@ class LogEventToReplay implements LogEvent {
5960
this.instant = logEvent.getInstant();
6061
this.thrown = logEvent.getThrown();
6162
this.marker = logEvent.getMarker();
62-
this.contextData = logEvent.getContextData();
63+
// copy context data, context data map may be reused
64+
this.contextData = new SortedArrayStringMap(logEvent.getContextData());
6365
this.threadName = logEvent.getThreadName();
6466
this.threadId = logEvent.getThreadId();
6567
}

‎instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/OpenTelemetryAppender.java

Lines changed: 32 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,8 +10,14 @@
1010
import com.google.errorprone.annotations.CanIgnoreReturnValue;
1111
import io.opentelemetry.api.OpenTelemetry;
1212
import io.opentelemetry.api.logs.LogRecordBuilder;
13+
import io.opentelemetry.api.trace.Span;
14+
import io.opentelemetry.api.trace.SpanContext;
15+
import io.opentelemetry.api.trace.TraceFlags;
16+
import io.opentelemetry.api.trace.TraceState;
17+
import io.opentelemetry.context.Context;
1318
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.ContextDataAccessor;
1419
import io.opentelemetry.instrumentation.log4j.appender.v2_17.internal.LogEventMapper;
20+
import io.opentelemetry.instrumentation.log4j.contextdata.v2_17.internal.ContextDataKeys;
1521
import java.io.Serializable;
1622
import java.util.ArrayList;
1723
import java.util.Arrays;
@@ -272,6 +278,28 @@ private void emit(OpenTelemetry openTelemetry, LogEvent event) {
272278
LogRecordBuilder builder =
273279
openTelemetry.getLogsBridge().loggerBuilder(instrumentationName).build().logRecordBuilder();
274280
ReadOnlyStringMap contextData = event.getContextData();
281+
Context context = Context.current();
282+
// when using async logger we'll be executing on a different thread than what started logging
283+
// reconstruct the context from context data
284+
if (context == Context.root()) {
285+
ContextDataAccessor<ReadOnlyStringMap> contextDataAccessor = ContextDataAccessorImpl.INSTANCE;
286+
String traceId = contextDataAccessor.getValue(contextData, ContextDataKeys.TRACE_ID_KEY);
287+
String spanId = contextDataAccessor.getValue(contextData, ContextDataKeys.SPAN_ID_KEY);
288+
String traceFlags =
289+
contextDataAccessor.getValue(contextData, ContextDataKeys.TRACE_FLAGS_KEY);
290+
if (traceId != null && spanId != null && traceFlags != null) {
291+
context =
292+
Context.root()
293+
.with(
294+
Span.wrap(
295+
SpanContext.create(
296+
traceId,
297+
spanId,
298+
TraceFlags.fromHex(traceFlags, 0),
299+
TraceState.getDefault())));
300+
}
301+
}
302+
275303
mapper.mapLogEvent(
276304
builder,
277305
event.getMessage(),
@@ -280,7 +308,8 @@ private void emit(OpenTelemetry openTelemetry, LogEvent event) {
280308
event.getThrown(),
281309
contextData,
282310
event.getThreadName(),
283-
event.getThreadId());
311+
event.getThreadId(),
312+
context);
284313

285314
Instant timestamp = event.getInstant();
286315
if (timestamp != null) {
@@ -297,12 +326,12 @@ private enum ContextDataAccessorImpl implements ContextDataAccessor<ReadOnlyStri
297326

298327
@Override
299328
@Nullable
300-
public Object getValue(ReadOnlyStringMap contextData, String key) {
329+
public String getValue(ReadOnlyStringMap contextData, String key) {
301330
return contextData.getValue(key);
302331
}
303332

304333
@Override
305-
public void forEach(ReadOnlyStringMap contextData, BiConsumer<String, Object> action) {
334+
public void forEach(ReadOnlyStringMap contextData, BiConsumer<String, String> action) {
306335
contextData.forEach(action::accept);
307336
}
308337
}

‎instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/ContextDataAccessor.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@
1515
public interface ContextDataAccessor<T> {
1616

1717
@Nullable
18-
Object getValue(T contextData, String key);
18+
String getValue(T contextData, String key);
1919

20-
void forEach(T contextData, BiConsumer<String, Object> action);
20+
void forEach(T contextData, BiConsumer<String, String> action);
2121
}

‎instrumentation/log4j/log4j-appender-2.17/library/src/main/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/internal/LogEventMapper.java

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -86,7 +86,8 @@ public void mapLogEvent(
8686
@Nullable Throwable throwable,
8787
T contextData,
8888
String threadName,
89-
long threadId) {
89+
long threadId,
90+
Context context) {
9091

9192
AttributesBuilder attributes = Attributes.builder();
9293

@@ -116,8 +117,7 @@ public void mapLogEvent(
116117
}
117118

118119
builder.setAllAttributes(attributes.build());
119-
120-
builder.setContext(Context.current());
120+
builder.setContext(context);
121121
}
122122

123123
// visible for testing
@@ -165,16 +165,16 @@ void captureContextDataAttributes(AttributesBuilder attributes, T contextData) {
165165
contextData,
166166
(key, value) -> {
167167
if (value != null) {
168-
attributes.put(getContextDataAttributeKey(key), value.toString());
168+
attributes.put(getContextDataAttributeKey(key), value);
169169
}
170170
});
171171
return;
172172
}
173173

174174
for (String key : captureContextDataAttributes) {
175-
Object value = contextDataAccessor.getValue(contextData, key);
175+
String value = contextDataAccessor.getValue(contextData, key);
176176
if (value != null) {
177-
attributes.put(getContextDataAttributeKey(key), value.toString());
177+
attributes.put(getContextDataAttributeKey(key), value);
178178
}
179179
}
180180
}

‎instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/AbstractOpenTelemetryAppenderTest.java

Lines changed: 32 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -11,14 +11,14 @@
1111
import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies;
1212
import static java.util.concurrent.TimeUnit.MILLISECONDS;
1313

14-
import io.opentelemetry.api.common.Attributes;
1514
import io.opentelemetry.api.logs.Severity;
1615
import io.opentelemetry.api.trace.SpanContext;
1716
import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension;
1817
import io.opentelemetry.sdk.common.InstrumentationScopeInfo;
1918
import io.opentelemetry.sdk.logs.data.LogRecordData;
2019
import io.opentelemetry.sdk.resources.Resource;
2120
import io.opentelemetry.semconv.ExceptionAttributes;
21+
import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes;
2222
import java.time.Instant;
2323
import org.apache.logging.log4j.LogManager;
2424
import org.apache.logging.log4j.Logger;
@@ -93,7 +93,12 @@ void logNoSpan() {
9393
.hasResource(resource)
9494
.hasInstrumentationScope(instrumentationScopeInfo)
9595
.hasBody("log message 1")
96-
.hasAttributes(Attributes.empty()));
96+
.hasAttributesSatisfyingExactly(
97+
equalTo(
98+
ThreadIncubatingAttributes.THREAD_NAME,
99+
Thread.currentThread().getName()),
100+
equalTo(
101+
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId())));
97102
}
98103

99104
@Test
@@ -123,6 +128,9 @@ void logWithExtras() {
123128
.hasSeverity(Severity.INFO)
124129
.hasSeverityText("INFO")
125130
.hasAttributesSatisfyingExactly(
131+
equalTo(
132+
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
133+
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
126134
equalTo(
127135
ExceptionAttributes.EXCEPTION_TYPE,
128136
IllegalStateException.class.getName()),
@@ -158,7 +166,13 @@ void logContextData() {
158166
.hasInstrumentationScope(instrumentationScopeInfo)
159167
.hasBody("log message 1")
160168
.hasAttributesSatisfyingExactly(
161-
equalTo(stringKey("key1"), "val1"), equalTo(stringKey("key2"), "val2")));
169+
equalTo(
170+
ThreadIncubatingAttributes.THREAD_NAME,
171+
Thread.currentThread().getName()),
172+
equalTo(
173+
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
174+
equalTo(stringKey("key1"), "val1"),
175+
equalTo(stringKey("key2"), "val2")));
162176
}
163177

164178
@Test
@@ -177,6 +191,11 @@ void logStringMapMessage() {
177191
.hasResource(resource)
178192
.hasInstrumentationScope(instrumentationScopeInfo)
179193
.hasAttributesSatisfyingExactly(
194+
equalTo(
195+
ThreadIncubatingAttributes.THREAD_NAME,
196+
Thread.currentThread().getName()),
197+
equalTo(
198+
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
180199
equalTo(stringKey("log4j.map_message.key1"), "val1"),
181200
equalTo(stringKey("log4j.map_message.key2"), "val2")));
182201
}
@@ -198,6 +217,11 @@ void logStringMapMessageWithSpecialAttribute() {
198217
.hasInstrumentationScope(instrumentationScopeInfo)
199218
.hasBody("val2")
200219
.hasAttributesSatisfyingExactly(
220+
equalTo(
221+
ThreadIncubatingAttributes.THREAD_NAME,
222+
Thread.currentThread().getName()),
223+
equalTo(
224+
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
201225
equalTo(stringKey("log4j.map_message.key1"), "val1")));
202226
}
203227

@@ -233,6 +257,11 @@ void logStructuredDataMessage() {
233257
.hasInstrumentationScope(instrumentationScopeInfo)
234258
.hasBody("a message")
235259
.hasAttributesSatisfyingExactly(
260+
equalTo(
261+
ThreadIncubatingAttributes.THREAD_NAME,
262+
Thread.currentThread().getName()),
263+
equalTo(
264+
ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
236265
equalTo(stringKey("log4j.map_message.key1"), "val1"),
237266
equalTo(stringKey("log4j.map_message.key2"), "val2")));
238267
}

‎instrumentation/log4j/log4j-appender-2.17/library/src/test/java/io/opentelemetry/instrumentation/log4j/appender/v2_17/LogReplayOpenTelemetryAppenderTest.java

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,9 +10,11 @@
1010

1111
import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension;
1212
import io.opentelemetry.instrumentation.testing.junit.LibraryInstrumentationExtension;
13+
import io.opentelemetry.semconv.incubating.ThreadIncubatingAttributes;
1314
import org.apache.logging.log4j.message.StringMapMessage;
1415
import org.apache.logging.log4j.message.StructuredDataMessage;
1516
import org.junit.jupiter.api.AfterEach;
17+
import org.junit.jupiter.api.Assumptions;
1618
import org.junit.jupiter.api.BeforeEach;
1719
import org.junit.jupiter.api.Test;
1820
import org.junit.jupiter.api.extension.RegisterExtension;
@@ -43,8 +45,16 @@ void executeAfterLogsExecution() {
4345
OpenTelemetryAppender.install(testing.getOpenTelemetry());
4446
}
4547

48+
private static boolean isAsyncLogger() {
49+
return logger.getClass().getName().contains("AsyncLogger");
50+
}
51+
4652
@Test
4753
void twoLogs() {
54+
// with async logger OpenTelemetryAppender.install may be called before second log message is
55+
// captured, so we get 2 log records instead of the expected 1
56+
Assumptions.assumeFalse(isAsyncLogger());
57+
4858
logger.info("log message 1");
4959
logger.info(
5060
"log message 2"); // Won't be instrumented because cache size is 1 (see log4j2.xml file)
@@ -61,6 +71,10 @@ void twoLogs() {
6171

6272
@Test
6373
void twoLogsStringMapMessage() {
74+
// with async logger OpenTelemetryAppender.install may be called before second log message is
75+
// captured, so we get 2 log records instead of the expected 1
76+
Assumptions.assumeFalse(isAsyncLogger());
77+
6478
StringMapMessage message = new StringMapMessage();
6579
message.put("key1", "val1");
6680
message.put("key2", "val2");
@@ -81,12 +95,19 @@ void twoLogsStringMapMessage() {
8195
.hasResource(resource)
8296
.hasInstrumentationScope(instrumentationScopeInfo)
8397
.hasAttributesSatisfyingExactly(
98+
equalTo(
99+
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
100+
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
84101
equalTo(stringKey("log4j.map_message.key1"), "val1"),
85102
equalTo(stringKey("log4j.map_message.key2"), "val2")));
86103
}
87104

88105
@Test
89106
void twoLogsStructuredDataMessage() {
107+
// with async logger OpenTelemetryAppender.install may be called before second log message is
108+
// captured, so we get 2 log records instead of the expected 1
109+
Assumptions.assumeFalse(isAsyncLogger());
110+
90111
StructuredDataMessage message = new StructuredDataMessage("an id", "a message", "a type");
91112
message.put("key1", "val1");
92113
message.put("key2", "val2");
@@ -107,6 +128,9 @@ void twoLogsStructuredDataMessage() {
107128
.hasInstrumentationScope(instrumentationScopeInfo)
108129
.hasBody("a message")
109130
.hasAttributesSatisfyingExactly(
131+
equalTo(
132+
ThreadIncubatingAttributes.THREAD_NAME, Thread.currentThread().getName()),
133+
equalTo(ThreadIncubatingAttributes.THREAD_ID, Thread.currentThread().getId()),
110134
equalTo(stringKey("log4j.map_message.key1"), "val1"),
111135
equalTo(stringKey("log4j.map_message.key2"), "val2")));
112136
}

0 commit comments

Comments
 (0)