This is an automated email from the ASF dual-hosted git repository. ramanathan1504 pushed a commit to branch fix-trace-metadata-1976 in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit e70ac38d43350ebcc63fd5374b3fa669899f32e2 Author: Ramanathan <[email protected]> AuthorDate: Thu Jul 2 15:09:13 2026 +0530 Add tracing fields to RingBufferLogEvent and related classes --- .../logging/log4j/spi/TraceContextProvider.java | 41 ++++++ .../org/apache/logging/log4j/spi/package-info.java | 2 +- .../log4j/core/async/RingBufferLogEventTest.java | 45 ++++++ .../logging/log4j/core/impl/Log4jLogEventTest.java | 149 ++++++++++++++++++++ .../log4j/core/impl/MutableLogEventTest.java | 29 ++++ .../org/apache/logging/log4j/core/LogEvent.java | 20 +++ .../log4j/core/async/RingBufferLogEvent.java | 71 +++++++++- .../core/async/RingBufferLogEventTranslator.java | 54 +++++++- .../logging/log4j/core/async/package-info.java | 2 +- .../logging/log4j/core/impl/Log4jLogEvent.java | 153 +++++++++++++++++++-- .../logging/log4j/core/impl/MutableLogEvent.java | 47 ++++++- .../logging/log4j/core/impl/package-info.java | 2 +- .../apache/logging/log4j/core/package-info.java | 2 +- .../core/util/TraceContextProviderService.java | 72 ++++++++++ .../logging/log4j/core/util/package-info.java | 2 +- .../log4j/perf/jmh/AsyncTraceContextBenchmark.java | 133 ++++++++++++++++++ 16 files changed, 799 insertions(+), 25 deletions(-) diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/spi/TraceContextProvider.java b/log4j-api/src/main/java/org/apache/logging/log4j/spi/TraceContextProvider.java new file mode 100644 index 0000000000..3c1ef5b8c1 --- /dev/null +++ b/log4j-api/src/main/java/org/apache/logging/log4j/spi/TraceContextProvider.java @@ -0,0 +1,41 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.spi; + +/** + * Service Provider Interface (SPI) for retrieving standard W3C tracing metadata from the active context. + * Placed in the API module to allow third-party providers to compile against it with minimal dependencies. + * + * @since 2.27.0 + */ +public interface TraceContextProvider { + + /** + * Returns the standard trace ID from the active context, or {@code null}. + */ + String getTraceId(); + + /** + * Returns the standard span ID from the active context, or {@code null}. + */ + String getSpanId(); + + /** + * Returns the standard trace flags from the active context, or {@code null}. + */ + String getTraceFlags(); +} diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/spi/package-info.java b/log4j-api/src/main/java/org/apache/logging/log4j/spi/package-info.java index 3b6b5c2585..0956aad003 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/spi/package-info.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/spi/package-info.java @@ -19,7 +19,7 @@ * API classes. */ @Export -@Version("2.25.0") +@Version("2.26.0") package org.apache.logging.log4j.spi; import org.osgi.annotation.bundle.Export; diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java index 5377040565..26044686fe 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java @@ -16,10 +16,12 @@ */ package org.apache.logging.log4j.core.async; +import static org.apache.logging.log4j.core.util.ClockFactory.getClock; import static org.assertj.core.api.Assertions.as; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatCode; import static org.assertj.core.api.Assertions.fail; +import static org.junit.jupiter.api.Assertions.assertNull; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.verify; import static org.mockito.Mockito.verifyNoMoreInteractions; @@ -31,6 +33,7 @@ import org.apache.logging.log4j.MarkerManager; import org.apache.logging.log4j.ThreadContext; import org.apache.logging.log4j.ThreadContext.ContextStack; import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.impl.ContextDataFactory; import org.apache.logging.log4j.core.impl.ThrowableProxy; import org.apache.logging.log4j.core.time.internal.FixedPreciseClock; import org.apache.logging.log4j.core.util.Clock; @@ -468,4 +471,46 @@ class RingBufferLogEventTest { // Verify interaction exhaustion verifyNoMoreInteractions(asyncLogger, message, throwable, contextData, contextStack); } + + @Test + void testRingBufferLogEventTracingFieldsAndClear() { + final RingBufferLogEvent event = new RingBufferLogEvent(); + + // 1. Check initial state + assertThat(event.getTraceId()).isNull(); + assertThat(event.getSpanId()).isNull(); + assertThat(event.getTraceFlags()).isNull(); + + // 2. Initialize with trace fields inside 18-parameter setValues + event.setValues( + null, + "TestLogger", + null, + "FQCN", + Level.INFO, + new SimpleMessage("msg"), + null, + ContextDataFactory.createContextData(), + ThreadContext.EMPTY_STACK, + 123L, + "thread-name", + 5, + null, + getClock(), + new DummyNanoClock(), + "trace-id-ringbuffer", + "span-id-ringbuffer", + "01"); + + // 3. Assert values are retrievable + assertThat(event.getTraceId()).isEqualTo("trace-id-ringbuffer"); + assertThat(event.getSpanId()).isEqualTo("span-id-ringbuffer"); + assertThat(event.getTraceFlags()).isEqualTo("01"); + + // 4. Verify clearing wipes tracing state to avoid leakage on slot reuse + event.clear(); + assertNull(event.getTraceId()); + assertNull(event.getSpanId()); + assertNull(event.getTraceFlags()); + } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/Log4jLogEventTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/Log4jLogEventTest.java index bc90e594d2..ce7cf8d769 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/Log4jLogEventTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/Log4jLogEventTest.java @@ -18,6 +18,7 @@ package org.apache.logging.log4j.core.impl; import static org.apache.logging.log4j.test.junit.SerialUtil.deserialize; import static org.apache.logging.log4j.test.junit.SerialUtil.serialize; +import static org.assertj.core.api.Assertions.assertThat; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertInstanceOf; @@ -29,6 +30,7 @@ import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; import java.lang.reflect.Field; +import java.util.Map; import org.apache.logging.log4j.Level; import org.apache.logging.log4j.Marker; import org.apache.logging.log4j.MarkerManager; @@ -36,6 +38,8 @@ import org.apache.logging.log4j.ThreadContext; import org.apache.logging.log4j.ThreadContext.ContextStack; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.config.plugins.convert.Base64Converter; +import org.apache.logging.log4j.core.time.Instant; +import org.apache.logging.log4j.core.time.MutableInstant; import org.apache.logging.log4j.core.util.Clock; import org.apache.logging.log4j.core.util.ClockFactory; import org.apache.logging.log4j.core.util.ClockFactoryTest; @@ -45,6 +49,7 @@ import org.apache.logging.log4j.message.ObjectMessage; import org.apache.logging.log4j.message.ReusableMessage; import org.apache.logging.log4j.message.ReusableObjectMessage; import org.apache.logging.log4j.message.SimpleMessage; +import org.apache.logging.log4j.util.ReadOnlyStringMap; import org.apache.logging.log4j.util.SortedArrayStringMap; import org.apache.logging.log4j.util.StringMap; import org.apache.logging.log4j.util.Strings; @@ -541,4 +546,148 @@ public class Log4jLogEventTest { // Throws an NPE in 2.6.2 assertNotNull(new Log4jLogEvent().toString()); } + + @Test + public void testCustomLegacyLogEventDefaultBehavior() { + // Create an anonymous/stub class implementing LogEvent without implementing getTraceId/getSpanId/getTraceFlags + final LogEvent legacyEvent = new LogEvent() { + private static final long serialVersionUID = 1L; + + @Override + public LogEvent toImmutable() { + return this; + } + + @Override + @Deprecated + public Map<String, String> getContextMap() { + return java.util.Collections.emptyMap(); + } + + @Override + public ReadOnlyStringMap getContextData() { + return ContextDataFactory.emptyFrozenContextData(); + } + + @Override + public ThreadContext.ContextStack getContextStack() { + return ThreadContext.EMPTY_STACK; + } + + @Override + public String getLoggerFqcn() { + return null; + } + + @Override + public Level getLevel() { + return Level.INFO; + } + + @Override + public String getLoggerName() { + return "LegacyLogger"; + } + + @Override + public Marker getMarker() { + return null; + } + + @Override + public Message getMessage() { + return new SimpleMessage("Legacy msg"); + } + + @Override + public long getTimeMillis() { + return 0; + } + + @Override + public Instant getInstant() { + return new MutableInstant(); + } + + @Override + public StackTraceElement getSource() { + return null; + } + + @Override + public String getThreadName() { + return "main"; + } + + @Override + public long getThreadId() { + return 1; + } + + @Override + public int getThreadPriority() { + return 5; + } + + @Override + public Throwable getThrown() { + return null; + } + + @Override + @Deprecated + public ThrowableProxy getThrownProxy() { + return null; + } + + @Override + public boolean isEndOfBatch() { + return false; + } + + @Override + public boolean isIncludeLocation() { + return false; + } + + @Override + public void setEndOfBatch(boolean endOfBatch) {} + + @Override + public void setIncludeLocation(boolean locationRequired) {} + + @Override + public long getNanoTime() { + return 0; + } + }; + + // Assert Java 8 default method fallbacks return null without throwing abstract method exceptions + assertNull(legacyEvent.getTraceId()); + assertNull(legacyEvent.getSpanId()); + assertNull(legacyEvent.getTraceFlags()); + } + + @Test + void testTracingFieldsInBuilderAndCopy() { + final Log4jLogEvent originalEvent = Log4jLogEvent.newBuilder() + .setLoggerName("TestLogger") + .setLevel(Level.DEBUG) + .setMessage(new org.apache.logging.log4j.message.SimpleMessage("Test message")) + .setTraceId("4bf92f3577b34da6a3ce929d0e0e4736") + .setSpanId("00f067aa0ba902b7") + .setTraceFlags("01") + .build(); + + // 1. Verify getters on original + assertThat(originalEvent.getTraceId()).isEqualTo("4bf92f3577b34da6a3ce929d0e0e4736"); + assertThat(originalEvent.getSpanId()).isEqualTo("00f067aa0ba902b7"); + assertThat(originalEvent.getTraceFlags()).isEqualTo("01"); + + // 2. Verify Builder Copy Constructor + final Log4jLogEvent copiedEvent = new Log4jLogEvent.Builder(originalEvent).build(); + assertThat(copiedEvent.getTraceId()).isEqualTo("4bf92f3577b34da6a3ce929d0e0e4736"); + assertThat(copiedEvent.getSpanId()).isEqualTo("00f067aa0ba902b7"); + assertThat(copiedEvent.getTraceFlags()).isEqualTo("01"); + } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/MutableLogEventTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/MutableLogEventTest.java index 092c2133e2..87c032fa71 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/MutableLogEventTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/impl/MutableLogEventTest.java @@ -366,4 +366,33 @@ class MutableLogEventTest { final Log4jLogEvent immutable = mutable.toImmutable(); assertThat(immutable.getSource()).isEqualTo(source); } + + @Test + void testMutableLogEventTracingFieldsPropagationAndClear() { + final Log4jLogEvent sourceEvent = Log4jLogEvent.newBuilder() + .setLoggerName("SourceLogger") + .setTraceId("trace-xyz-123") + .setSpanId("span-abc-456") + .setTraceFlags("01") + .build(); + + final MutableLogEvent mutableEvent = new MutableLogEvent(); + + // 1. Initially empty + assertThat(mutableEvent.getTraceId()).isNull(); + assertThat(mutableEvent.getSpanId()).isNull(); + assertThat(mutableEvent.getTraceFlags()).isNull(); + + // 2. Verify propagation via initFrom + mutableEvent.initFrom(sourceEvent); + assertThat(mutableEvent.getTraceId()).isEqualTo("trace-xyz-123"); + assertThat(mutableEvent.getSpanId()).isEqualTo("span-abc-456"); + assertThat(mutableEvent.getTraceFlags()).isEqualTo("01"); + + // 3. Verify clearing removes tracking state to prevent leakage on pool reuse + mutableEvent.clear(); + assertThat(mutableEvent.getTraceId()).isNull(); + assertThat(mutableEvent.getSpanId()).isNull(); + assertThat(mutableEvent.getTraceFlags()).isNull(); + } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/LogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/LogEvent.java index 63daa9d3bb..50d947ed34 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/LogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/LogEvent.java @@ -241,4 +241,24 @@ public interface LogEvent extends Serializable { * @since Log4J 2.4 */ long getNanoTime(); + /** + * Returns the standard Trace ID. + */ + default String getTraceId() { + return null; + } + + /** + * Returns the standard Span ID. + */ + default String getSpanId() { + return null; + } + + /** + * Returns the standard Trace Flags. + */ + default String getTraceFlags() { + return null; + } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java index 2afb007387..8a46be100e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java @@ -91,6 +91,9 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen private String fqcn; private StackTraceElement location; private ContextStack contextStack; + private String traceId; + private String spanId; + private String traceFlags; private transient AsyncLogger asyncLogger; @@ -109,7 +112,10 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen final int threadPriority, final StackTraceElement aLocation, final Clock clock, - final NanoClock nanoClock) { + final NanoClock nanoClock, + final String traceId, + final String spanId, + final String traceFlags) { this.threadPriority = threadPriority; this.threadId = threadId; this.level = aLevel; @@ -125,9 +131,50 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen this.contextData = mutableContextData; this.contextStack = aContextStack; this.asyncLogger = anAsyncLogger; + this.traceId = traceId; + this.spanId = spanId; + this.traceFlags = traceFlags; this.populated = true; } + public void setValues( + final AsyncLogger anAsyncLogger, + final String aLoggerName, + final Marker aMarker, + final String theFqcn, + final Level aLevel, + final Message msg, + final Throwable aThrowable, + final StringMap mutableContextData, + final ContextStack aContextStack, + final long threadId, + final String threadName, + final int threadPriority, + final StackTraceElement aLocation, + final Clock clock, + final NanoClock nanoClock) { + setValues( + anAsyncLogger, + aLoggerName, + aMarker, + theFqcn, + aLevel, + msg, + aThrowable, + mutableContextData, + aContextStack, + threadId, + threadName, + threadPriority, + aLocation, + clock, + nanoClock, + null, // traceId default + null, // spanId default + null // traceFlags default + ); + } + private void initTime(final Clock clock) { if (message instanceof TimestampMessage) { instant.initFromEpochMilli(((TimestampMessage) message).getTimestamp(), 0); @@ -399,6 +446,21 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen return nanoTime; } + @Override + public String getTraceId() { + return traceId; + } + + @Override + public String getSpanId() { + return spanId; + } + + @Override + public String getTraceFlags() { + return traceFlags; + } + /** * Release references held by ring buffer to allow objects to be garbage-collected. */ @@ -415,6 +477,9 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen this.location = null; this.contextStack = null; this.asyncLogger = null; + this.traceId = null; + this.spanId = null; + this.traceFlags = null; } private void clearMessage() { @@ -499,6 +564,8 @@ public class RingBufferLogEvent implements LogEvent, ReusableMessage, CharSequen .setThreadPriority(threadPriority) // .setThrown(getThrown()) // may deserialize from thrownProxy .setInstant(instant) // - ; + .setTraceId(traceId) + .setSpanId(spanId) + .setTraceFlags(traceFlags); } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java index f6fee9fcf5..b694c9e013 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java @@ -24,7 +24,9 @@ import org.apache.logging.log4j.core.ContextDataInjector; import org.apache.logging.log4j.core.impl.ContextDataInjectorFactory; import org.apache.logging.log4j.core.util.Clock; import org.apache.logging.log4j.core.util.NanoClock; +import org.apache.logging.log4j.core.util.TraceContextProviderService; import org.apache.logging.log4j.message.Message; +import org.apache.logging.log4j.spi.TraceContextProvider; import org.apache.logging.log4j.util.ReadOnlyStringMap; import org.apache.logging.log4j.util.StringMap; @@ -51,6 +53,9 @@ public class RingBufferLogEventTranslator implements EventTranslator<RingBufferL private StackTraceElement location; private Clock clock; private NanoClock nanoClock; + private String traceId; + private String spanId; + private String traceFlags; // Due to the usage pattern of this class, these are effectively final private long threadId = Thread.currentThread().getId(); @@ -79,7 +84,10 @@ public class RingBufferLogEventTranslator implements EventTranslator<RingBufferL threadPriority, location, clock, - nanoClock); + nanoClock, + traceId, + spanId, + traceFlags); } finally { clear(); // clear the translator } @@ -100,7 +108,10 @@ public class RingBufferLogEventTranslator implements EventTranslator<RingBufferL null, // contextStack null, // location null, // clock - null // nanoClock + null, // nanoClock + null, // traceId + null, // spanId + null // traceFlags ); } @@ -115,7 +126,10 @@ public class RingBufferLogEventTranslator implements EventTranslator<RingBufferL final ContextStack aContextStack, final StackTraceElement aLocation, final Clock aClock, - final NanoClock aNanoClock) { + final NanoClock aNanoClock, + final String traceId, + final String spanId, + final String traceFlags) { this.asyncLogger = anAsyncLogger; this.loggerName = aLoggerName; this.marker = aMarker; @@ -127,8 +141,42 @@ public class RingBufferLogEventTranslator implements EventTranslator<RingBufferL this.location = aLocation; this.clock = aClock; this.nanoClock = aNanoClock; + this.traceId = traceId; + this.spanId = spanId; + this.traceFlags = traceFlags; } + public void setBasicValues( + final AsyncLogger anAsyncLogger, + final String aLoggerName, + final Marker aMarker, + final String theFqcn, + final Level aLevel, + final Message msg, + final Throwable aThrowable, + final ContextStack aContextStack, + final StackTraceElement aLocation, + final Clock aClock, + final NanoClock aNanoClock) { + + final TraceContextProvider provider = TraceContextProviderService.getActiveProvider(); + + setBasicValues( + anAsyncLogger, + aLoggerName, + aMarker, + theFqcn, + aLevel, + msg, + aThrowable, + aContextStack, + aLocation, + aClock, + aNanoClock, + provider.getTraceId(), + provider.getSpanId(), + provider.getTraceFlags()); + } /** * @deprecated since 2.25.0. {@link RingBufferLogEventTranslator} instances should only be used on the thread that * created it. diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/package-info.java index 24e9b7643f..e8e8a9189d 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/package-info.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/package-info.java @@ -18,7 +18,7 @@ * Provides Asynchronous Logger classes and interfaces for low-latency logging. */ @Export -@Version("2.26.0") +@Version("2.27.0") package org.apache.logging.log4j.core.async; import org.osgi.annotation.bundle.Export; diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java index 471b1cd5be..b7b99bd60e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/Log4jLogEvent.java @@ -38,11 +38,13 @@ import org.apache.logging.log4j.core.util.Clock; import org.apache.logging.log4j.core.util.ClockFactory; import org.apache.logging.log4j.core.util.DummyNanoClock; import org.apache.logging.log4j.core.util.NanoClock; +import org.apache.logging.log4j.core.util.TraceContextProviderService; import org.apache.logging.log4j.message.LoggerNameAwareMessage; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.ReusableMessage; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.message.TimestampMessage; +import org.apache.logging.log4j.spi.TraceContextProvider; import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.ReadOnlyStringMap; import org.apache.logging.log4j.util.StackLocatorUtil; @@ -94,6 +96,10 @@ public class Log4jLogEvent implements LogEvent { // 5. Deprecated fields, only used for serialization private ThrowableProxy thrownProxy; + // 6. Tracing fields + private final String traceId; + private final String spanId; + private final String traceFlags; /** LogEvent Builder helper class. */ public static class Builder implements org.apache.logging.log4j.core.util.Builder<LogEvent> { @@ -123,9 +129,28 @@ public class Log4jLogEvent implements LogEvent { private StringMap contextData; private ThreadContext.ContextStack contextStack; + private String traceId = Strings.EMPTY; + private String spanId = Strings.EMPTY; + private String traceFlags = Strings.EMPTY; + public Builder() { this.contextData = createContextData((List<Property>) null); this.contextStack = ThreadContext.getImmutableStack(); + + final TraceContextProvider provider = TraceContextProviderService.getActiveProvider(); + + final String tId = provider.getTraceId(); + if (tId != null) { + this.traceId = tId; + } + final String sId = provider.getSpanId(); + if (sId != null) { + this.spanId = sId; + } + final String flags = provider.getTraceFlags(); + if (flags != null) { + this.traceFlags = flags; + } } /** @@ -159,6 +184,10 @@ public class Log4jLogEvent implements LogEvent { // but since we are copying the event, we want to call it. this.source = other.getSource(); + this.traceId = other.getTraceId(); + this.spanId = other.getSpanId(); + this.traceFlags = other.getTraceFlags(); + Message message = other.getMessage(); this.message = message instanceof ReusableMessage ? ((ReusableMessage) message).memento() @@ -175,6 +204,21 @@ public class Log4jLogEvent implements LogEvent { this.contextStack = other.getContextStack(); } + public Builder setTraceId(String traceId) { + this.traceId = traceId; + return this; + } + + public Builder setSpanId(String spanId) { + this.spanId = spanId; + return this; + } + + public Builder setTraceFlags(String traceFlags) { + this.traceFlags = traceFlags; + return this; + } + public Builder setLevel(final Level level) { this.level = level; return this; @@ -303,7 +347,10 @@ public class Log4jLogEvent implements LogEvent { source, instant.getEpochMillisecond(), instant.getNanoOfMillisecond(), - nanoTime); + nanoTime, + traceId, + spanId, + traceFlags); result.setIncludeLocation(includeLocation); result.setEndOfBatch(endOfBatch); return result; @@ -339,7 +386,10 @@ public class Log4jLogEvent implements LogEvent { 0, null, CLOCK, - nanoClock.nanoTime()); + nanoClock.nanoTime(), + Strings.EMPTY, + Strings.EMPTY, + Strings.EMPTY); } /** @@ -363,7 +413,10 @@ public class Log4jLogEvent implements LogEvent { null, timestamp, 0, - nanoClock.nanoTime()); + nanoClock.nanoTime(), + Strings.EMPTY, + Strings.EMPTY, + Strings.EMPTY); } /** @@ -420,7 +473,10 @@ public class Log4jLogEvent implements LogEvent { 0, // thread priority null, // StackTraceElement source CLOCK, // - nanoClock.nanoTime()); + nanoClock.nanoTime(), + Strings.EMPTY, + Strings.EMPTY, + Strings.EMPTY); } /** @@ -457,7 +513,10 @@ public class Log4jLogEvent implements LogEvent { 0, // thread priority source, // StackTraceElement source CLOCK, // - nanoClock.nanoTime()); + nanoClock.nanoTime(), + Strings.EMPTY, + Strings.EMPTY, + Strings.EMPTY); } /** @@ -503,7 +562,10 @@ public class Log4jLogEvent implements LogEvent { location, timestampMillis, 0, - nanoClock.nanoTime()); + nanoClock.nanoTime(), + Strings.EMPTY, + Strings.EMPTY, + Strings.EMPTY); } /** @@ -552,7 +614,10 @@ public class Log4jLogEvent implements LogEvent { location, timestamp, 0, - nanoClock.nanoTime()); + nanoClock.nanoTime(), + Strings.EMPTY, + Strings.EMPTY, + Strings.EMPTY); return result; } @@ -590,7 +655,10 @@ public class Log4jLogEvent implements LogEvent { final StackTraceElement source, final long timestampMillis, final int nanoOfMillisecond, - final long nanoTime) { + final long nanoTime, + final String traceId, + final String spanId, + final String traceFlags) { this( loggerName, marker, @@ -604,7 +672,10 @@ public class Log4jLogEvent implements LogEvent { threadName, threadPriority, source, - nanoTime); + nanoTime, + traceId, + spanId, + traceFlags); final long millis = message instanceof TimestampMessage ? ((TimestampMessage) message).getTimestamp() : timestampMillis; instant.initFromEpochMilli(millis, nanoOfMillisecond); @@ -624,7 +695,10 @@ public class Log4jLogEvent implements LogEvent { final int threadPriority, final StackTraceElement source, final Clock clock, - final long nanoTime) { + final long nanoTime, + final String traceId, + final String spanId, + final String traceFlags) { this( loggerName, marker, @@ -638,7 +712,10 @@ public class Log4jLogEvent implements LogEvent { threadName, threadPriority, source, - nanoTime); + nanoTime, + traceId, + spanId, + traceFlags); if (message instanceof TimestampMessage) { instant.initFromEpochMilli(((TimestampMessage) message).getTimestamp(), 0); } else { @@ -659,7 +736,10 @@ public class Log4jLogEvent implements LogEvent { final String threadName, final int threadPriority, final StackTraceElement source, - final long nanoTime) { + final long nanoTime, + final String traceId, + final String spanId, + final String traceFlags) { this.loggerName = loggerName; this.marker = marker; this.loggerFqcn = loggerFQCN; @@ -676,6 +756,9 @@ public class Log4jLogEvent implements LogEvent { ((LoggerNameAwareMessage) message).setLoggerName(loggerName); } this.nanoTime = nanoTime; + this.traceId = traceId; + this.spanId = spanId; + this.traceFlags = traceFlags; } private static StringMap createContextData(final Map<String, String> contextMap) { @@ -985,7 +1068,10 @@ public class Log4jLogEvent implements LogEvent { proxy.source, proxy.timeMillis, proxy.nanoOfMillisecond, - proxy.nanoTime); + proxy.nanoTime, + proxy.traceId, + proxy.spanId, + proxy.traceFlags); result.setEndOfBatch(proxy.isEndOfBatch); result.setIncludeLocation(proxy.isLocationRequired); return result; @@ -1093,6 +1179,15 @@ public class Log4jLogEvent implements LogEvent { if (thrown != null ? !thrown.equals(that.thrown) : that.thrown != null) { return false; } + if (traceId != null ? !traceId.equals(that.traceId) : that.traceId != null) { + return false; + } + if (spanId != null ? !spanId.equals(that.spanId) : that.spanId != null) { + return false; + } + if (traceFlags != null ? !traceFlags.equals(that.traceFlags) : that.traceFlags != null) { + return false; + } return true; } @@ -1116,10 +1211,27 @@ public class Log4jLogEvent implements LogEvent { result = 31 * result + (source != null ? source.hashCode() : 0); result = 31 * result + (includeLocation ? 1 : 0); result = 31 * result + (endOfBatch ? 1 : 0); + result = 31 * result + (traceId != null ? traceId.hashCode() : 0); + result = 31 * result + (spanId != null ? spanId.hashCode() : 0); + result = 31 * result + (traceFlags != null ? traceFlags.hashCode() : 0); // Check:ON: MagicNumber return result; } + @Override + public String getTraceId() { + return traceId; + } + + @Override + public String getSpanId() { + return spanId; + } + + @Override + public String getTraceFlags() { + return traceFlags; + } /** * Proxy pattern used to serialize the LogEvent. */ @@ -1160,6 +1272,10 @@ public class Log4jLogEvent implements LogEvent { /** @since 2.4 */ private final transient long nanoTime; + private final String traceId; + private final String spanId; + private final String traceFlags; + public LogEventProxy(final Log4jLogEvent event, final boolean includeLocation) { this.loggerFQCN = event.loggerFqcn; this.marker = event.marker; @@ -1180,6 +1296,9 @@ public class Log4jLogEvent implements LogEvent { this.isLocationRequired = includeLocation; this.isEndOfBatch = event.endOfBatch; this.nanoTime = event.nanoTime; + this.traceId = event.getTraceId(); + this.spanId = event.getSpanId(); + this.traceFlags = event.getTraceFlags(); } public LogEventProxy(final LogEvent event, final boolean includeLocation) { @@ -1210,6 +1329,9 @@ public class Log4jLogEvent implements LogEvent { this.isLocationRequired = includeLocation; this.isEndOfBatch = event.isEndOfBatch(); this.nanoTime = event.getNanoTime(); + this.traceId = event.getTraceId(); + this.spanId = event.getSpanId(); + this.traceFlags = event.getTraceFlags(); } private static Message memento(final ReusableMessage message) { @@ -1257,7 +1379,10 @@ public class Log4jLogEvent implements LogEvent { source, timeMillis, nanoOfMillisecond, - nanoTime); + nanoTime, + traceId, + spanId, + traceFlags); result.setEndOfBatch(isEndOfBatch); result.setIncludeLocation(isLocationRequired); result.thrownProxy = thrownProxy; diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java index 9a99eae624..83736894be 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/MutableLogEvent.java @@ -30,12 +30,14 @@ import org.apache.logging.log4j.core.time.MutableInstant; import org.apache.logging.log4j.core.util.Clock; import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.NanoClock; +import org.apache.logging.log4j.core.util.TraceContextProviderService; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.ParameterConsumer; import org.apache.logging.log4j.message.ParameterVisitable; import org.apache.logging.log4j.message.ReusableMessage; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.message.TimestampMessage; +import org.apache.logging.log4j.spi.TraceContextProvider; import org.apache.logging.log4j.util.ReadOnlyStringMap; import org.apache.logging.log4j.util.StackLocatorUtil; import org.apache.logging.log4j.util.StringBuilders; @@ -71,6 +73,9 @@ public class MutableLogEvent implements LogEvent, ReusableMessage, ParameterVisi StackTraceElement source; private ThreadContext.ContextStack contextStack; transient boolean reserved = false; + private String traceId; + private String spanId; + private String traceFlags; public MutableLogEvent() { // messageText and the parameter array are lazily initialized @@ -133,6 +138,10 @@ public class MutableLogEvent implements LogEvent, ReusableMessage, ParameterVisi this.endOfBatch = event.isEndOfBatch(); this.includeLocation = event.isIncludeLocation(); this.nanoTime = event.getNanoTime(); + + this.traceId = event.getTraceId(); + this.spanId = event.getSpanId(); + this.traceFlags = event.getTraceFlags(); setMessage(event.getMessage()); } @@ -157,6 +166,9 @@ public class MutableLogEvent implements LogEvent, ReusableMessage, ParameterVisi } contextStack = null; + traceId = null; + spanId = null; + traceFlags = null; // ThreadName should not be cleared: this field is set in the ReusableLogEventFactory // where this instance is kept in a ThreadLocal, so it usually does not change. // threadName = null; // no need to clear threadName @@ -359,6 +371,10 @@ public class MutableLogEvent implements LogEvent, ReusableMessage, ParameterVisi instant.initFrom(clock); } nanoTime = nanoClock.nanoTime(); + final TraceContextProvider provider = TraceContextProviderService.getActiveProvider(); + this.traceId = provider.getTraceId(); + this.spanId = provider.getSpanId(); + this.traceFlags = provider.getTraceFlags(); } @Override @@ -485,6 +501,33 @@ public class MutableLogEvent implements LogEvent, ReusableMessage, ParameterVisi this.nanoTime = nanoTime; } + @Override + public String getTraceId() { + return traceId; + } + + public void setTraceId(final String traceId) { + this.traceId = traceId; + } + + @Override + public String getSpanId() { + return spanId; + } + + public void setSpanId(final String spanId) { + this.spanId = spanId; + } + + @Override + public String getTraceFlags() { + return traceFlags; + } + + public void setTraceFlags(final String traceFlags) { + this.traceFlags = traceFlags; + } + /** * Creates a LogEventProxy that can be serialized. * @return a LogEventProxy. @@ -534,6 +577,8 @@ public class MutableLogEvent implements LogEvent, ReusableMessage, ParameterVisi .setThreadPriority(threadPriority) // .setThrown(getThrown()) // may deserialize from thrownProxy .setInstant(instant) // - ; + .setTraceId(traceId) + .setSpanId(spanId) + .setTraceFlags(traceFlags); } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/package-info.java index 666e8325ed..2d4bdcd199 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/package-info.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/impl/package-info.java @@ -18,7 +18,7 @@ * Log4j 2 private implementation classes. */ @Export -@Version("2.24.1") +@Version("2.25.0") package org.apache.logging.log4j.core.impl; import org.osgi.annotation.bundle.Export; diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/package-info.java index c09868a666..45bc926c52 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/package-info.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/package-info.java @@ -18,7 +18,7 @@ * Implementation of Log4j 2. */ @Export -@Version("2.25.3") +@Version("2.26.0") package org.apache.logging.log4j.core; import org.osgi.annotation.bundle.Export; diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/TraceContextProviderService.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/TraceContextProviderService.java new file mode 100644 index 0000000000..3440e5e4a9 --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/TraceContextProviderService.java @@ -0,0 +1,72 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.core.util; + +import java.util.Iterator; +import java.util.ServiceLoader; +import org.apache.logging.log4j.spi.TraceContextProvider; +import org.apache.logging.log4j.status.StatusLogger; + +/** + * Service registry designed to discover and cache the active {@link TraceContextProvider}. + */ +public final class TraceContextProviderService { + + private static final TraceContextProvider ACTIVE_PROVIDER; + + static { + TraceContextProvider found = null; + try { + final ServiceLoader<TraceContextProvider> loader = + ServiceLoader.load(TraceContextProvider.class, TraceContextProviderService.class.getClassLoader()); + final Iterator<TraceContextProvider> iterator = loader.iterator(); + if (iterator.hasNext()) { + found = iterator.next(); + StatusLogger.getLogger() + .info("Using TraceContextProvider: {}", found.getClass().getName()); + } + } catch (final Throwable t) { + StatusLogger.getLogger().warn("Error loading TraceContextProvider service", t); + } + ACTIVE_PROVIDER = found != null ? found : NoOpTraceContextProvider.INSTANCE; + } + + public static TraceContextProvider getActiveProvider() { + return ACTIVE_PROVIDER; + } + + private static final class NoOpTraceContextProvider implements TraceContextProvider { + static final NoOpTraceContextProvider INSTANCE = new NoOpTraceContextProvider(); + + @Override + public String getTraceId() { + return null; + } + + @Override + public String getSpanId() { + return null; + } + + @Override + public String getTraceFlags() { + return null; + } + } + + private TraceContextProviderService() {} +} diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/package-info.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/package-info.java index e4ac85f5eb..b9efa51956 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/package-info.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/package-info.java @@ -18,7 +18,7 @@ * Log4j 2 helper classes. */ @Export -@Version("2.25.3") +@Version("2.26.0") package org.apache.logging.log4j.core.util; import org.osgi.annotation.bundle.Export; diff --git a/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/AsyncTraceContextBenchmark.java b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/AsyncTraceContextBenchmark.java new file mode 100644 index 0000000000..6483b59e0a --- /dev/null +++ b/log4j-perf-test/src/main/java/org/apache/logging/log4j/perf/jmh/AsyncTraceContextBenchmark.java @@ -0,0 +1,133 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to you under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.logging.log4j.perf.jmh; + +import java.util.concurrent.TimeUnit; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.ThreadContext; +import org.apache.logging.log4j.core.async.RingBufferLogEvent; +import org.apache.logging.log4j.core.async.RingBufferLogEventTranslator; +import org.apache.logging.log4j.core.util.ClockFactory; +import org.apache.logging.log4j.core.util.DummyNanoClock; +import org.apache.logging.log4j.message.SimpleMessage; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.BenchmarkMode; +import org.openjdk.jmh.annotations.Fork; +import org.openjdk.jmh.annotations.Measurement; +import org.openjdk.jmh.annotations.Mode; +import org.openjdk.jmh.annotations.OutputTimeUnit; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.Warmup; +import org.openjdk.jmh.runner.Runner; +import org.openjdk.jmh.runner.options.OptionsBuilder; + +@BenchmarkMode(Mode.Throughput) +@OutputTimeUnit(TimeUnit.MICROSECONDS) +@Warmup(iterations = 3, time = 1, timeUnit = TimeUnit.SECONDS) +@Measurement(iterations = 3, time = 1, timeUnit = TimeUnit.SECONDS) +@Fork(1) +@State(Scope.Benchmark) +public class AsyncTraceContextBenchmark { + + private SimpleMessage message; + + @Setup + public void setup() { + message = new SimpleMessage("Test performance message"); + } + + /** + * Reusable thread-local state to match how Disruptor events and translators + * are held per-thread in production. + */ + @State(Scope.Thread) + public static class ThreadState { + final RingBufferLogEvent event = new RingBufferLogEvent(); + final RingBufferLogEventTranslator translator = new RingBufferLogEventTranslator(); + } + + @Benchmark + public void baseline(final ThreadState state) { + state.translator.setBasicValues( + null, + "Logger", + null, + "FQCN", + Level.INFO, + message, + null, + null, + null, + ClockFactory.getClock(), + new DummyNanoClock()); + state.translator.translateTo(state.event, 0); + } + + @Benchmark + public void threadContextTracing(final ThreadState state) { + ThreadContext.put("traceId", "4bf92f3577b34da6a3ce929d0e0e4736"); + ThreadContext.put("spanId", "00f067aa0ba902b7"); + ThreadContext.put("traceFlags", "01"); + + try { + state.translator.setBasicValues( + null, + "Logger", + null, + "FQCN", + Level.INFO, + message, + null, + ThreadContext.getImmutableStack(), + null, + ClockFactory.getClock(), + new DummyNanoClock()); + state.translator.translateTo(state.event, 0); + } finally { + ThreadContext.clearMap(); + } + } + + @Benchmark + public void nativeTracing(final ThreadState state) { + state.translator.setBasicValues( + null, + "Logger", + null, + "FQCN", + Level.INFO, + message, + null, + null, + null, + ClockFactory.getClock(), + new DummyNanoClock(), + "4bf92f3577b34da6a3ce929d0e0e4736", + "00f067aa0ba902b7", + "01"); + state.translator.translateTo(state.event, 0); + } + + public static void main(final String[] args) throws Exception { + new Runner(new OptionsBuilder() + .include(AsyncTraceContextBenchmark.class.getSimpleName()) + .build()) + .run(); + } +}
