Skip to content

Commit b6ba7d0

Browse files
Add native tracing fields to LogEvent to eliminate async MDC overhead (#4171)
* Add tracing fields to RingBufferLogEvent and related classes * Add W3C trace context support with pattern converters for trace ID, span ID, and trace flags * Enhance TraceContextProviderService for exception safety and simplify trace ID retrieval * Add tests for tracing fields serialization and pattern converters * Refactor tracing metadata documentation and improve code comments for clarity * Add native W3C tracing fields to LogEvent and introduce TraceContextProvider SPI * Add benchmark for ContextDataProvider tracing approach * Enhance TraceContextProviderService to handle SecurityManager restrictions gracefully
1 parent a52ad57 commit b6ba7d0

24 files changed

Lines changed: 1376 additions & 26 deletions
Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
/*
2+
* Licensed to the Apache Software Foundation (ASF) under one or more
3+
* contributor license agreements. See the NOTICE file distributed with
4+
* this work for additional information regarding copyright ownership.
5+
* The ASF licenses this file to you under the Apache License, Version 2.0
6+
* (the "License"); you may not use this file except in compliance with
7+
* the License. You may obtain a copy of the License at
8+
*
9+
* http://www.apache.org/licenses/LICENSE-2.0
10+
*
11+
* Unless required by applicable law or agreed to in writing, software
12+
* distributed under the License is distributed on an "AS IS" BASIS,
13+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14+
* See the License for the specific language governing permissions and
15+
* limitations under the License.
16+
*/
17+
package org.apache.logging.log4j.spi;
18+
19+
/**
20+
* Service Provider Interface (SPI) for retrieving distributed tracing metadata (such as W3C Trace Context)
21+
* from the active execution context.
22+
* <p>
23+
* Implementing this SPI allows tracing frameworks (e.g., OpenTelemetry, Micrometer, Zipkin) to pass native
24+
* trace identifiers directly to Log4j events. This completely bypasses the {@link org.apache.logging.log4j.ThreadContext}
25+
* map, eliminating map-cloning and garbage collection overhead during asynchronous logging.
26+
* </p>
27+
* <p>
28+
* Log4j locates implementations of this interface using the standard Java {@link java.util.ServiceLoader} mechanism.
29+
* To register a custom provider, create a plain-text file named
30+
* {@code org.apache.logging.log4j.spi.TraceContextProvider} in the {@code META-INF/services/} directory
31+
* containing the fully qualified class name of the implementation.
32+
* </p>
33+
*
34+
* @since 2.27.0
35+
*/
36+
public interface TraceContextProvider {
37+
38+
/**
39+
* Returns the standard trace ID from the active context, or {@code null}.
40+
*/
41+
String getTraceId();
42+
43+
/**
44+
* Returns the standard span ID from the active context, or {@code null}.
45+
*/
46+
String getSpanId();
47+
48+
/**
49+
* Returns the standard trace flags from the active context, or {@code null}.
50+
*/
51+
String getTraceFlags();
52+
}

log4j-api/src/main/java/org/apache/logging/log4j/spi/package-info.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@
1919
* API classes.
2020
*/
2121
@Export
22-
@Version("2.25.0")
22+
@Version("2.26.0")
2323
package org.apache.logging.log4j.spi;
2424

2525
import org.osgi.annotation.bundle.Export;

log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,10 +16,12 @@
1616
*/
1717
package org.apache.logging.log4j.core.async;
1818

19+
import static org.apache.logging.log4j.core.util.ClockFactory.getClock;
1920
import static org.assertj.core.api.Assertions.as;
2021
import static org.assertj.core.api.Assertions.assertThat;
2122
import static org.assertj.core.api.Assertions.assertThatCode;
2223
import static org.assertj.core.api.Assertions.fail;
24+
import static org.junit.jupiter.api.Assertions.assertNull;
2325
import static org.mockito.Mockito.mock;
2426
import static org.mockito.Mockito.verify;
2527
import static org.mockito.Mockito.verifyNoMoreInteractions;
@@ -31,6 +33,7 @@
3133
import org.apache.logging.log4j.ThreadContext;
3234
import org.apache.logging.log4j.ThreadContext.ContextStack;
3335
import org.apache.logging.log4j.core.LogEvent;
36+
import org.apache.logging.log4j.core.impl.ContextDataFactory;
3437
import org.apache.logging.log4j.core.impl.ThrowableProxy;
3538
import org.apache.logging.log4j.core.time.internal.FixedPreciseClock;
3639
import org.apache.logging.log4j.core.util.Clock;
@@ -468,4 +471,46 @@ void testGettersAndClear() {
468471
// Verify interaction exhaustion
469472
verifyNoMoreInteractions(asyncLogger, message, throwable, contextData, contextStack);
470473
}
474+
475+
@Test
476+
void testRingBufferLogEventTracingFieldsAndClear() {
477+
final RingBufferLogEvent event = new RingBufferLogEvent();
478+
479+
// Check initial state
480+
assertThat(event.getTraceId()).isNull();
481+
assertThat(event.getSpanId()).isNull();
482+
assertThat(event.getTraceFlags()).isNull();
483+
484+
// Initialize with trace fields inside 18-parameter setValues
485+
event.setValues(
486+
null,
487+
"TestLogger",
488+
null,
489+
"FQCN",
490+
Level.INFO,
491+
new SimpleMessage("msg"),
492+
null,
493+
ContextDataFactory.createContextData(),
494+
ThreadContext.EMPTY_STACK,
495+
123L,
496+
"thread-name",
497+
5,
498+
null,
499+
getClock(),
500+
new DummyNanoClock(),
501+
"trace-id-ringbuffer",
502+
"span-id-ringbuffer",
503+
"01");
504+
505+
// Assert values are retrievable
506+
assertThat(event.getTraceId()).isEqualTo("trace-id-ringbuffer");
507+
assertThat(event.getSpanId()).isEqualTo("span-id-ringbuffer");
508+
assertThat(event.getTraceFlags()).isEqualTo("01");
509+
510+
// Verify clearing wipes tracing state to avoid leakage on slot reuse
511+
event.clear();
512+
assertNull(event.getTraceId());
513+
assertNull(event.getSpanId());
514+
assertNull(event.getTraceFlags());
515+
}
471516
}

log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/Log4jLogEventTest.java

Lines changed: 165 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818

1919
import static org.apache.logging.log4j.test.junit.SerialUtil.deserialize;
2020
import static org.apache.logging.log4j.test.junit.SerialUtil.serialize;
21+
import static org.assertj.core.api.Assertions.assertThat;
2122
import static org.junit.jupiter.api.Assertions.assertEquals;
2223
import static org.junit.jupiter.api.Assertions.assertFalse;
2324
import static org.junit.jupiter.api.Assertions.assertInstanceOf;
@@ -29,13 +30,16 @@
2930
import static org.junit.jupiter.api.Assertions.assertTrue;
3031

3132
import java.lang.reflect.Field;
33+
import java.util.Map;
3234
import org.apache.logging.log4j.Level;
3335
import org.apache.logging.log4j.Marker;
3436
import org.apache.logging.log4j.MarkerManager;
3537
import org.apache.logging.log4j.ThreadContext;
3638
import org.apache.logging.log4j.ThreadContext.ContextStack;
3739
import org.apache.logging.log4j.core.LogEvent;
3840
import org.apache.logging.log4j.core.config.plugins.convert.Base64Converter;
41+
import org.apache.logging.log4j.core.time.Instant;
42+
import org.apache.logging.log4j.core.time.MutableInstant;
3943
import org.apache.logging.log4j.core.util.Clock;
4044
import org.apache.logging.log4j.core.util.ClockFactory;
4145
import org.apache.logging.log4j.core.util.ClockFactoryTest;
@@ -45,6 +49,7 @@
4549
import org.apache.logging.log4j.message.ReusableMessage;
4650
import org.apache.logging.log4j.message.ReusableObjectMessage;
4751
import org.apache.logging.log4j.message.SimpleMessage;
52+
import org.apache.logging.log4j.util.ReadOnlyStringMap;
4853
import org.apache.logging.log4j.util.SortedArrayStringMap;
4954
import org.apache.logging.log4j.util.StringMap;
5055
import org.apache.logging.log4j.util.Strings;
@@ -541,4 +546,164 @@ void testToString() {
541546
// Throws an NPE in 2.6.2
542547
assertNotNull(new Log4jLogEvent().toString());
543548
}
549+
550+
@Test
551+
public void testCustomLegacyLogEventDefaultBehavior() {
552+
// Create an anonymous/stub class implementing LogEvent without implementing getTraceId/getSpanId/getTraceFlags
553+
final LogEvent legacyEvent = new LogEvent() {
554+
private static final long serialVersionUID = 1L;
555+
556+
@Override
557+
public LogEvent toImmutable() {
558+
return this;
559+
}
560+
561+
@Override
562+
@Deprecated
563+
public Map<String, String> getContextMap() {
564+
return java.util.Collections.emptyMap();
565+
}
566+
567+
@Override
568+
public ReadOnlyStringMap getContextData() {
569+
return ContextDataFactory.emptyFrozenContextData();
570+
}
571+
572+
@Override
573+
public ThreadContext.ContextStack getContextStack() {
574+
return ThreadContext.EMPTY_STACK;
575+
}
576+
577+
@Override
578+
public String getLoggerFqcn() {
579+
return null;
580+
}
581+
582+
@Override
583+
public Level getLevel() {
584+
return Level.INFO;
585+
}
586+
587+
@Override
588+
public String getLoggerName() {
589+
return "LegacyLogger";
590+
}
591+
592+
@Override
593+
public Marker getMarker() {
594+
return null;
595+
}
596+
597+
@Override
598+
public Message getMessage() {
599+
return new SimpleMessage("Legacy msg");
600+
}
601+
602+
@Override
603+
public long getTimeMillis() {
604+
return 0;
605+
}
606+
607+
@Override
608+
public Instant getInstant() {
609+
return new MutableInstant();
610+
}
611+
612+
@Override
613+
public StackTraceElement getSource() {
614+
return null;
615+
}
616+
617+
@Override
618+
public String getThreadName() {
619+
return "main";
620+
}
621+
622+
@Override
623+
public long getThreadId() {
624+
return 1;
625+
}
626+
627+
@Override
628+
public int getThreadPriority() {
629+
return 5;
630+
}
631+
632+
@Override
633+
public Throwable getThrown() {
634+
return null;
635+
}
636+
637+
@Override
638+
@Deprecated
639+
public ThrowableProxy getThrownProxy() {
640+
return null;
641+
}
642+
643+
@Override
644+
public boolean isEndOfBatch() {
645+
return false;
646+
}
647+
648+
@Override
649+
public boolean isIncludeLocation() {
650+
return false;
651+
}
652+
653+
@Override
654+
public void setEndOfBatch(boolean endOfBatch) {}
655+
656+
@Override
657+
public void setIncludeLocation(boolean locationRequired) {}
658+
659+
@Override
660+
public long getNanoTime() {
661+
return 0;
662+
}
663+
};
664+
665+
assertNull(legacyEvent.getTraceId());
666+
assertNull(legacyEvent.getSpanId());
667+
assertNull(legacyEvent.getTraceFlags());
668+
}
669+
670+
@Test
671+
void testTracingFieldsInBuilderAndCopy() {
672+
final Log4jLogEvent originalEvent = Log4jLogEvent.newBuilder()
673+
.setLoggerName("TestLogger")
674+
.setLevel(Level.DEBUG)
675+
.setMessage(new org.apache.logging.log4j.message.SimpleMessage("Test message"))
676+
.setTraceId("4bf92f3577b34da6a3ce929d0e0e4736")
677+
.setSpanId("00f067aa0ba902b7")
678+
.setTraceFlags("01")
679+
.build();
680+
681+
assertThat(originalEvent.getTraceId()).isEqualTo("4bf92f3577b34da6a3ce929d0e0e4736");
682+
assertThat(originalEvent.getSpanId()).isEqualTo("00f067aa0ba902b7");
683+
assertThat(originalEvent.getTraceFlags()).isEqualTo("01");
684+
685+
final Log4jLogEvent copiedEvent = new Log4jLogEvent.Builder(originalEvent).build();
686+
assertThat(copiedEvent.getTraceId()).isEqualTo("4bf92f3577b34da6a3ce929d0e0e4736");
687+
assertThat(copiedEvent.getSpanId()).isEqualTo("00f067aa0ba902b7");
688+
assertThat(copiedEvent.getTraceFlags()).isEqualTo("01");
689+
}
690+
691+
@Test
692+
void testTracingFieldsSerialization() throws Exception {
693+
final Log4jLogEvent originalEvent = Log4jLogEvent.newBuilder()
694+
.setLoggerName("SerializationLogger")
695+
.setMessage(new org.apache.logging.log4j.message.SimpleMessage("dummy message"))
696+
.setTraceId("trace-serialize-123")
697+
.setSpanId("span-serialize-456")
698+
.setTraceFlags("01")
699+
.build();
700+
701+
final byte[] serializedBytes = serialize(originalEvent);
702+
703+
final Log4jLogEvent deserializedEvent = deserialize(serializedBytes);
704+
705+
assertThat(deserializedEvent.getTraceId()).isEqualTo("trace-serialize-123");
706+
assertThat(deserializedEvent.getSpanId()).isEqualTo("span-serialize-456");
707+
assertThat(deserializedEvent.getTraceFlags()).isEqualTo("01");
708+
}
544709
}

log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/MutableLogEventTest.java

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -366,4 +366,33 @@ void testPreservesLocation() {
366366
final Log4jLogEvent immutable = mutable.toImmutable();
367367
assertThat(immutable.getSource()).isEqualTo(source);
368368
}
369+
370+
@Test
371+
void testMutableLogEventTracingFieldsPropagationAndClear() {
372+
final Log4jLogEvent sourceEvent = Log4jLogEvent.newBuilder()
373+
.setLoggerName("SourceLogger")
374+
.setTraceId("trace-xyz-123")
375+
.setSpanId("span-abc-456")
376+
.setTraceFlags("01")
377+
.build();
378+
379+
final MutableLogEvent mutableEvent = new MutableLogEvent();
380+
381+
// Initially empty
382+
assertThat(mutableEvent.getTraceId()).isNull();
383+
assertThat(mutableEvent.getSpanId()).isNull();
384+
assertThat(mutableEvent.getTraceFlags()).isNull();
385+
386+
// Verify propagation via initFrom
387+
mutableEvent.initFrom(sourceEvent);
388+
assertThat(mutableEvent.getTraceId()).isEqualTo("trace-xyz-123");
389+
assertThat(mutableEvent.getSpanId()).isEqualTo("span-abc-456");
390+
assertThat(mutableEvent.getTraceFlags()).isEqualTo("01");
391+
392+
// Verify clearing removes tracking state to prevent leakage on pool reuse
393+
mutableEvent.clear();
394+
assertThat(mutableEvent.getTraceId()).isNull();
395+
assertThat(mutableEvent.getSpanId()).isNull();
396+
assertThat(mutableEvent.getTraceFlags()).isNull();
397+
}
369398
}

0 commit comments

Comments
 (0)