diff --git a/hadoop-hdds/common/src/main/java/org/apache/hadoop/hdds/tracing/TracingUtil.java b/hadoop-hdds/common/src/main/java/org/apache/hadoop/hdds/tracing/TracingUtil.java index 810555ca3e45..b845c828996b 100644 --- a/hadoop-hdds/common/src/main/java/org/apache/hadoop/hdds/tracing/TracingUtil.java +++ b/hadoop-hdds/common/src/main/java/org/apache/hadoop/hdds/tracing/TracingUtil.java @@ -22,11 +22,13 @@ import io.opentelemetry.api.common.AttributeKey; import io.opentelemetry.api.common.Attributes; import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.SpanContext; import io.opentelemetry.api.trace.SpanKind; import io.opentelemetry.api.trace.StatusCode; import io.opentelemetry.api.trace.Tracer; import io.opentelemetry.api.trace.propagation.W3CTraceContextPropagator; import io.opentelemetry.context.Context; +import io.opentelemetry.context.ContextStorage; import io.opentelemetry.context.Scope; import io.opentelemetry.context.propagation.ContextPropagators; import io.opentelemetry.context.propagation.TextMapGetter; @@ -48,6 +50,7 @@ import org.apache.ratis.util.function.CheckedSupplier; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import org.slf4j.MDC; /** * Utility class to collect all the tracing helper methods. @@ -62,11 +65,29 @@ public final class TracingUtil { private static Tracer tracer = OpenTelemetry.noop().getTracer("noop"); private static volatile SdkTracerProvider sdkTracerProvider; private static BatchSpanProcessor batchSpanProcessor; + private static boolean mdcContextStorageInstalled; public static final String GLOBAL_TRACER_NAME = "ozone"; private TracingUtil() { } + /** + * Adds the current trace and span IDs to the logging MDC. + * Only for Ozone services and CLIs, not the client library, so applications keep their own MDC. + * Must be called before OpenTelemetry {@link Context} is first used in the JVM. + */ + public static synchronized void installMdcContextStorage() { + if (mdcContextStorageInstalled) { + return; + } + mdcContextStorageInstalled = true; + ContextStorage.addWrapper(MdcContextStorage::new); + if (!(ContextStorage.get() instanceof MdcContextStorage)) { + LOG.warn("OpenTelemetry context is already initialized, {} and {} will not be added to the logging MDC", + MdcContextStorage.MDC_TRACE_ID, MdcContextStorage.MDC_SPAN_ID); + } + } + /** * Initialize the tracing with the given service name. */ @@ -128,6 +149,7 @@ public static synchronized void flushTracing() { /** * This function initializes tracing, runs the command in a span, and exports spans before returning for CLI spans. + * Only for Ozone CLIs: it also installs the MDC context storage, see {@link #installMdcContextStorage()}. */ public static R execute( String serviceName, @@ -143,6 +165,7 @@ public static R execute( SpanKind spanKind, ConfigurationSource conf, CheckedSupplier supplier) throws E { + installMdcContextStorage(); initTracing(serviceName, conf); try { return executeInNewSpan(spanName, spanKind, supplier); @@ -648,4 +671,56 @@ public static TraceCloseable createActivatedSpanFromW3cHttpHeaders( span.end(); }; } + + /** + * {@link ContextStorage} that keeps the logging MDC in sync with the current span. + * Installed through {@link #installMdcContextStorage()} by Ozone services and CLIs only, + * so applications using the Ozone client keep their own MDC and context storage. + * Every {@code makeCurrent()} / {@code Context.wrap(...)} goes through {@link #attach(Context)}, + * so trace and span IDs are available to log patterns without changes at the call sites. + * The MDC is always derived from the current context (never saved and restored), + * so values inherited by child threads through the MDC are overwritten on the next attach or close. + */ + static final class MdcContextStorage implements ContextStorage { + static final String MDC_TRACE_ID = "trace_id"; + static final String MDC_SPAN_ID = "span_id"; + + private final ContextStorage delegate; + + MdcContextStorage(ContextStorage delegate) { + this.delegate = delegate; + } + + @Override + public Scope attach(Context toAttach) { + Scope scope = delegate.attach(toAttach); + updateMdc(delegate.current()); + return () -> { + scope.close(); + updateMdc(delegate.current()); + }; + } + + @Override + public Context current() { + return delegate.current(); + } + + @Override + public Context root() { + return delegate.root(); + } + + private static void updateMdc(Context context) { + SpanContext spanContext = context == null ? SpanContext.getInvalid() + : Span.fromContext(context).getSpanContext(); + if (spanContext.isValid()) { + MDC.put(MDC_TRACE_ID, spanContext.getTraceId()); + MDC.put(MDC_SPAN_ID, spanContext.getSpanId()); + } else { + MDC.remove(MDC_TRACE_ID); + MDC.remove(MDC_SPAN_ID); + } + } + } } diff --git a/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestMdcContextStorageInstall.java b/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestMdcContextStorageInstall.java new file mode 100644 index 000000000000..3dace96c5387 --- /dev/null +++ b/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestMdcContextStorageInstall.java @@ -0,0 +1,161 @@ +/* + * 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.hadoop.hdds.tracing; + +import static org.apache.hadoop.hdds.tracing.TracingUtil.MdcContextStorage.MDC_SPAN_ID; +import static org.apache.hadoop.hdds.tracing.TracingUtil.MdcContextStorage.MDC_TRACE_ID; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertInstanceOf; +import static org.junit.jupiter.api.Assertions.assertNotEquals; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertTrue; + +import io.opentelemetry.api.GlobalOpenTelemetry; +import io.opentelemetry.api.trace.Span; +import io.opentelemetry.api.trace.SpanContext; +import io.opentelemetry.context.Context; +import io.opentelemetry.context.ContextStorage; +import io.opentelemetry.context.Scope; +import io.opentelemetry.sdk.OpenTelemetrySdk; +import io.opentelemetry.sdk.trace.SdkTracerProvider; +import io.opentelemetry.sdk.trace.export.SimpleSpanProcessor; +import io.opentelemetry.sdk.trace.export.SpanExporter; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import org.apache.hadoop.hdds.conf.InMemoryConfigurationForTesting; +import org.apache.hadoop.hdds.conf.MutableConfigurationSource; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; + +/** + * Tests {@link TracingUtil#installMdcContextStorage()}. + * When running together with other test classes, use fork mode per class. + */ +public class TestMdcContextStorageInstall { + + @BeforeAll + public static void install() { + TracingUtil.installMdcContextStorage(); + assertInstanceOf(TracingUtil.MdcContextStorage.class, ContextStorage.get(), "use fork mode per class"); + } + + @BeforeEach + public void setUp() { + TracingUtil.shutdownTracing(); + GlobalOpenTelemetry.resetForTest(); + MDC.clear(); + } + + @AfterEach + public void tearDown() { + TracingUtil.shutdownTracing(); + GlobalOpenTelemetry.resetForTest(); + MDC.clear(); + } + + private static void initTracing(boolean enabled) { + SdkTracerProvider provider = SdkTracerProvider.builder() + .addSpanProcessor(SimpleSpanProcessor.create(SpanExporter.noop())).build(); + OpenTelemetrySdk sdk = OpenTelemetrySdk.builder().setTracerProvider(provider).build(); + GlobalOpenTelemetry.set(sdk); + MutableConfigurationSource conf = new InMemoryConfigurationForTesting(); + conf.setBoolean("ozone.tracing.enabled", enabled); + TracingUtil.initTracing("mdc-install", conf); + } + + private static void assertMdcMatchesCurrentSpan() { + SpanContext current = Span.current().getSpanContext(); + assertTrue(current.isValid()); + assertEquals(current.getTraceId(), MDC.get(MDC_TRACE_ID)); + assertEquals(current.getSpanId(), MDC.get(MDC_SPAN_ID)); + } + + private static void assertMdcEmpty() { + assertNull(MDC.get(MDC_TRACE_ID)); + assertNull(MDC.get(MDC_SPAN_ID)); + } + + @Test + public void testActivatedSpanSetsMdc() { + initTracing(true); + try (TracingUtil.TraceCloseable ignored = TracingUtil.createActivatedSpan("outer")) { + assertMdcMatchesCurrentSpan(); + String traceId = MDC.get(MDC_TRACE_ID); + String outerSpanId = MDC.get(MDC_SPAN_ID); + try (TracingUtil.TraceCloseable ignoredInner = TracingUtil.createActivatedSpan("inner")) { + assertMdcMatchesCurrentSpan(); + assertEquals(traceId, MDC.get(MDC_TRACE_ID)); + assertNotEquals(outerSpanId, MDC.get(MDC_SPAN_ID)); + } + assertEquals(traceId, MDC.get(MDC_TRACE_ID)); + assertEquals(outerSpanId, MDC.get(MDC_SPAN_ID)); + } + assertMdcEmpty(); + } + + @Test + public void testImportedParentSpanSetsMdc() { + initTracing(true); + String carrier; + String parentTraceId; + try (TracingUtil.TraceCloseable ignored = TracingUtil.createActivatedSpan("client")) { + carrier = TracingUtil.exportCurrentSpan(); + parentTraceId = Span.current().getSpanContext().getTraceId(); + } + assertMdcEmpty(); + + Span server = TracingUtil.importAndCreateSpan("server", carrier); + try (Scope ignored = server.makeCurrent()) { + assertMdcMatchesCurrentSpan(); + assertEquals(parentTraceId, MDC.get(MDC_TRACE_ID)); + } finally { + server.end(); + } + assertMdcEmpty(); + } + + @Test + public void testContextWrapPropagatesMdcToOtherThread() throws Exception { + initTracing(true); + ExecutorService executor = Executors.newSingleThreadExecutor(); + try { + try (TracingUtil.TraceCloseable ignored = TracingUtil.createActivatedSpan("span")) { + String[] inTask = executor.submit(Context.current().wrap( + () -> new String[]{MDC.get(MDC_TRACE_ID), MDC.get(MDC_SPAN_ID)})).get(); + assertEquals(MDC.get(MDC_TRACE_ID), inTask[0]); + assertEquals(MDC.get(MDC_SPAN_ID), inTask[1]); + } + assertNull(executor.submit(() -> MDC.get(MDC_TRACE_ID)).get()); + assertNull(executor.submit(() -> MDC.get(MDC_SPAN_ID)).get()); + } finally { + executor.shutdownNow(); + } + } + + @Test + public void testTracingDisabledLeavesMdcEmpty() { + initTracing(false); + try (TracingUtil.TraceCloseable ignored = TracingUtil.createActivatedSpan("span")) { + assertMdcEmpty(); + } + assertMdcEmpty(); + } +} diff --git a/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestTracingUtil.java b/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestTracingUtil.java index 49bb7a451783..5b3e805700a0 100644 --- a/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestTracingUtil.java +++ b/hadoop-hdds/common/src/test/java/org/apache/hadoop/hdds/tracing/TestTracingUtil.java @@ -17,12 +17,16 @@ package org.apache.hadoop.hdds.tracing; +import static org.apache.hadoop.hdds.tracing.TracingUtil.MdcContextStorage.MDC_SPAN_ID; +import static org.apache.hadoop.hdds.tracing.TracingUtil.MdcContextStorage.MDC_TRACE_ID; import static org.apache.hadoop.hdds.tracing.TracingUtil.createProxy; import static org.apache.hadoop.hdds.tracing.TracingUtil.exportCurrentSpan; import static org.junit.jupiter.api.Assertions.assertEquals; import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertNotEquals; import static org.junit.jupiter.api.Assertions.assertNotNull; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; import static org.junit.jupiter.api.Assertions.assertThrows; import static org.junit.jupiter.api.Assertions.assertTrue; import static org.junit.jupiter.api.Assertions.fail; @@ -30,19 +34,44 @@ import io.opentelemetry.api.trace.Span; import io.opentelemetry.api.trace.SpanContext; import io.opentelemetry.api.trace.SpanKind; +import io.opentelemetry.api.trace.TraceFlags; +import io.opentelemetry.api.trace.TraceState; +import io.opentelemetry.context.Context; +import io.opentelemetry.context.ContextStorage; import io.opentelemetry.context.Scope; import io.opentelemetry.sdk.trace.ReadableSpan; import java.io.IOException; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; import org.apache.hadoop.hdds.conf.InMemoryConfigurationForTesting; import org.apache.hadoop.hdds.conf.MutableConfigurationSource; import org.apache.hadoop.hdds.tracing.TestTraceAllMethod.Service; import org.apache.hadoop.hdds.tracing.TestTraceAllMethod.ServiceImpl; +import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.Test; +import org.slf4j.MDC; /** * Test for {@link TracingUtil}. */ public class TestTracingUtil { + private static final String TRACE_ID = "0af7651916cd43dd8448eb211c80319c"; + private static final String PARENT_SPAN_ID = "b7ad6b7169203331"; + private static final String CHILD_SPAN_ID = "00f067aa0ba902b7"; + + @AfterEach + public void clearMdc() { + MDC.clear(); + } + + private static Context spanContext(String spanId) { + return Context.root().with(Span.wrap( + SpanContext.create(TRACE_ID, spanId, TraceFlags.getSampled(), TraceState.getDefault()))); + } + + private static TracingUtil.MdcContextStorage mdcContextStorage() { + return new TracingUtil.MdcContextStorage(ContextStorage.defaultStorage()); + } private static MutableConfigurationSource tracingEnabled() { MutableConfigurationSource config = new InMemoryConfigurationForTesting(); @@ -227,4 +256,82 @@ public void testImportAndCreateSpanUsesExplicitKind() { server.end(); } } + + @Test + public void testMdcNotChangedWithoutInstall() { + assertFalse(ContextStorage.get() instanceof TracingUtil.MdcContextStorage); + TracingUtil.initTracing("mdc-not-installed", tracingEnabled().getObject(TracingConfig.class)); + MDC.put(MDC_TRACE_ID, "app-trace"); + try (TracingUtil.TraceCloseable ignored = TracingUtil.createActivatedSpan("span")) { + assertTrue(Span.current().getSpanContext().isValid()); + assertEquals("app-trace", MDC.get(MDC_TRACE_ID)); + assertNull(MDC.get(MDC_SPAN_ID)); + } + try (Scope ignored = Span.getInvalid().makeCurrent()) { + assertEquals("app-trace", MDC.get(MDC_TRACE_ID)); + } + assertEquals("app-trace", MDC.get(MDC_TRACE_ID)); + } + + @Test + public void testInstallAfterContextInitializedHasNoEffect() { + ContextStorage storage = ContextStorage.get(); + Context.current(); + TracingUtil.installMdcContextStorage(); + assertSame(storage, ContextStorage.get()); + try (Scope ignored = spanContext(PARENT_SPAN_ID).makeCurrent()) { + assertNull(MDC.get(MDC_TRACE_ID)); + } + } + + @Test + public void testMdcContextStorageSetsAndRestoresMdc() { + TracingUtil.MdcContextStorage storage = mdcContextStorage(); + try (Scope ignored = storage.attach(spanContext(PARENT_SPAN_ID))) { + assertEquals(TRACE_ID, MDC.get(MDC_TRACE_ID)); + assertEquals(PARENT_SPAN_ID, MDC.get(MDC_SPAN_ID)); + try (Scope ignoredInner = storage.attach(spanContext(CHILD_SPAN_ID))) { + assertEquals(CHILD_SPAN_ID, MDC.get(MDC_SPAN_ID)); + } + assertEquals(PARENT_SPAN_ID, MDC.get(MDC_SPAN_ID)); + try (Scope ignoredInner = storage.attach(Context.root().with(Span.getInvalid()))) { + assertNull(MDC.get(MDC_TRACE_ID)); + assertNull(MDC.get(MDC_SPAN_ID)); + } + assertEquals(TRACE_ID, MDC.get(MDC_TRACE_ID)); + assertEquals(PARENT_SPAN_ID, MDC.get(MDC_SPAN_ID)); + } + assertNull(MDC.get(MDC_TRACE_ID)); + assertNull(MDC.get(MDC_SPAN_ID)); + } + + @Test + public void testMdcContextStorageClearsStaleMdc() { + MDC.put(MDC_TRACE_ID, "stale-trace"); + MDC.put(MDC_SPAN_ID, "stale-span"); + try (Scope ignored = mdcContextStorage().attach(spanContext(PARENT_SPAN_ID))) { + assertEquals(PARENT_SPAN_ID, MDC.get(MDC_SPAN_ID)); + } + assertNull(MDC.get(MDC_TRACE_ID)); + assertNull(MDC.get(MDC_SPAN_ID)); + } + + @Test + public void testMdcContextStorageOnOtherThread() throws Exception { + TracingUtil.MdcContextStorage storage = mdcContextStorage(); + ExecutorService executor = Executors.newSingleThreadExecutor(); + try { + String[] inSpan = executor.submit(() -> { + try (Scope ignored = storage.attach(spanContext(PARENT_SPAN_ID))) { + return new String[] {MDC.get(MDC_TRACE_ID), MDC.get(MDC_SPAN_ID)}; + } + }).get(); + assertEquals(TRACE_ID, inSpan[0]); + assertEquals(PARENT_SPAN_ID, inSpan[1]); + assertNull(executor.submit(() -> MDC.get(MDC_TRACE_ID)).get()); + assertNull(executor.submit(() -> MDC.get(MDC_SPAN_ID)).get()); + } finally { + executor.shutdownNow(); + } + } } diff --git a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/HddsDatanodeService.java b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/HddsDatanodeService.java index 493c341d4028..47840ab85bf3 100644 --- a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/HddsDatanodeService.java +++ b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/HddsDatanodeService.java @@ -78,6 +78,7 @@ import org.apache.hadoop.hdds.server.http.HttpConfig; import org.apache.hadoop.hdds.server.http.RatisDropwizardExports; import org.apache.hadoop.hdds.tracing.TracingConfig; +import org.apache.hadoop.hdds.tracing.TracingUtil; import org.apache.hadoop.hdds.utils.HddsServerUtil; import org.apache.hadoop.hdds.utils.HddsVersionInfo; import org.apache.hadoop.hdds.utils.IOUtils; @@ -189,6 +190,7 @@ public static void main(String[] args) { @Override public Void call() throws Exception { + TracingUtil.installMdcContextStorage(); OzoneConfiguration configuration = getOzoneConf(); if (printBanner) { HddsServerUtil.startupShutdownMessage(HddsVersionInfo.HDDS_VERSION_INFO, diff --git a/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/server/StorageContainerManagerStarter.java b/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/server/StorageContainerManagerStarter.java index 737c7a024c0e..f4138756a98d 100644 --- a/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/server/StorageContainerManagerStarter.java +++ b/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/server/StorageContainerManagerStarter.java @@ -24,6 +24,7 @@ import org.apache.hadoop.hdds.cli.GenericCli; import org.apache.hadoop.hdds.cli.HddsVersionProvider; import org.apache.hadoop.hdds.conf.OzoneConfiguration; +import org.apache.hadoop.hdds.tracing.TracingUtil; import org.apache.hadoop.hdds.utils.HddsServerUtil; import org.apache.hadoop.hdds.utils.HddsVersionInfo; import org.apache.hadoop.ozone.common.StorageInfo; @@ -145,6 +146,7 @@ private void startScm() throws Exception { * is set and print the startup banner message. */ private void commonInit() { + TracingUtil.installMdcContextStorage(); conf = getOzoneConf(); String[] originalArgs = getCmd().getParseResult().originalArgs() diff --git a/hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/OzoneManagerStarter.java b/hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/OzoneManagerStarter.java index f24c584c9af6..85420cfe9314 100644 --- a/hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/OzoneManagerStarter.java +++ b/hadoop-ozone/ozone-manager/src/main/java/org/apache/hadoop/ozone/om/OzoneManagerStarter.java @@ -24,6 +24,7 @@ import org.apache.hadoop.hdds.cli.GenericCli; import org.apache.hadoop.hdds.cli.HddsVersionProvider; import org.apache.hadoop.hdds.conf.OzoneConfiguration; +import org.apache.hadoop.hdds.tracing.TracingUtil; import org.apache.hadoop.hdds.utils.HddsServerUtil; import org.apache.hadoop.ozone.util.OzoneNetUtils; import org.apache.hadoop.ozone.util.OzoneVersionInfo; @@ -168,6 +169,7 @@ public void bootstrapOM(@CommandLine.Option(names = {"--force"}, * is set and print the startup banner message. */ private void commonInit() { + TracingUtil.installMdcContextStorage(); conf = getOzoneConf(); String[] originalArgs = getCmd().getParseResult().originalArgs() diff --git a/hadoop-ozone/s3gateway/src/main/java/org/apache/hadoop/ozone/s3/Gateway.java b/hadoop-ozone/s3gateway/src/main/java/org/apache/hadoop/ozone/s3/Gateway.java index 0b738d01eb87..6b8ef8f22afc 100644 --- a/hadoop-ozone/s3gateway/src/main/java/org/apache/hadoop/ozone/s3/Gateway.java +++ b/hadoop-ozone/s3gateway/src/main/java/org/apache/hadoop/ozone/s3/Gateway.java @@ -88,6 +88,7 @@ static void redirectJulToSlf4j() { public Void call() throws Exception { OzoneConfiguration ozoneConfiguration = getOzoneConf(); OzoneConfigurationHolder.setConfiguration(ozoneConfiguration); + TracingUtil.installMdcContextStorage(); TracingUtil.initTracing("S3gateway", OzoneConfigurationHolder.configuration()); UserGroupInformation.setConfiguration(OzoneConfigurationHolder.configuration()); loginS3GUser(OzoneConfigurationHolder.configuration());