From 50ebf7b5c7305bd0733f80e52d6305322771dc6c Mon Sep 17 00:00:00 2001 From: Adrian Cole Date: Fri, 3 Apr 2020 08:50:08 +0800 Subject: [PATCH 1/2] Rewrites Slf4jScopeDecorator internally to re-use Brave's (#1595) --- .../cloud/sleuth/log/Slf4jScopeDecorator.java | 230 +++--------------- .../cloud/sleuth/log/Slf4JSpanLoggerTest.java | 60 ++--- 2 files changed, 67 insertions(+), 223 deletions(-) diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java index e1dca9a80..0522c7208 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java @@ -16,22 +16,20 @@ package org.springframework.cloud.sleuth.log; -import java.util.AbstractMap; -import java.util.ArrayList; -import java.util.Collections; -import java.util.List; +import java.util.LinkedHashSet; +import java.util.Set; +import java.util.TreeSet; -import brave.internal.HexCodec; -import brave.internal.Nullable; -import brave.propagation.CurrentTraceContext; -import brave.propagation.ExtraFieldPropagation; +import brave.baggage.BaggageField; +import brave.baggage.BaggageFields; +import brave.baggage.CorrelationScopeDecorator; +import brave.context.slf4j.MDCScopeDecorator; +import brave.propagation.CurrentTraceContext.Scope; +import brave.propagation.CurrentTraceContext.ScopeDecorator; import brave.propagation.TraceContext; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import org.slf4j.MDC; import org.springframework.cloud.sleuth.autoconfig.SleuthProperties; -import org.springframework.util.StringUtils; /** * Adds {@linkplain MDC} properties "traceId", "parentId", "spanId" and "spanExportable" @@ -43,196 +41,48 @@ import org.springframework.util.StringUtils; * @author Marcin Grzejszczak * @since 2.1.0 */ -final class Slf4jScopeDecorator implements CurrentTraceContext.ScopeDecorator { +final class Slf4jScopeDecorator implements ScopeDecorator { // Backward compatibility for all logging patterns - private static final String LEGACY_EXPORTABLE_NAME = "X-Span-Export"; + private static final ScopeDecorator LEGACY_IDS = MDCScopeDecorator.newBuilder() + .clear().addField(BaggageFields.TRACE_ID, "X-B3-TraceId") + .addField(BaggageFields.PARENT_ID, "X-B3-ParentSpanId") + .addField(BaggageFields.SPAN_ID, "X-B3-SpanId") + .addField(BaggageFields.SAMPLED, "X-Span-Export").build(); - private static final String LEGACY_PARENT_ID_NAME = "X-B3-ParentSpanId"; - - private static final String LEGACY_TRACE_ID_NAME = "X-B3-TraceId"; - - private static final String LEGACY_SPAN_ID_NAME = "X-B3-SpanId"; - - private static final Logger log = LoggerFactory.getLogger(Slf4jScopeDecorator.class); - - private final SleuthProperties sleuthProperties; - - private final SleuthSlf4jProperties sleuthSlf4jProperties; + private final ScopeDecorator delegate; Slf4jScopeDecorator(SleuthProperties sleuthProperties, SleuthSlf4jProperties sleuthSlf4jProperties) { - this.sleuthProperties = sleuthProperties; - this.sleuthSlf4jProperties = sleuthSlf4jProperties; - } - static void replace(String key, @Nullable String value) { - if (value != null) { - MDC.put(key, value); - } - else { - MDC.remove(key); + CorrelationScopeDecorator.Builder builder = MDCScopeDecorator.newBuilder().clear() + .addField(BaggageFields.TRACE_ID).addField(BaggageFields.PARENT_ID) + .addField(BaggageFields.SPAN_ID) + .addField(BaggageFields.SAMPLED, "spanExportable"); + + Set whitelist = new TreeSet<>(String.CASE_INSENSITIVE_ORDER); + whitelist.addAll(sleuthSlf4jProperties.getWhitelistedMdcKeys()); + + Set retained = new LinkedHashSet<>(); + retained.addAll(sleuthProperties.getBaggageKeys()); + retained.addAll(sleuthProperties.getLocalKeys()); + retained.addAll(sleuthProperties.getPropagationKeys()); + + for (String name : retained) { + if (whitelist.contains(name)) { + // Until we move off ExtraFieldPropagation onto BaggagePropagation, + // manually create the fields... + builder.addField(BaggageField.create(name)); + builder.addDirtyName(name); + } } + + this.delegate = builder.build(); } @Override - public CurrentTraceContext.Scope decorateScope(TraceContext currentSpan, - CurrentTraceContext.Scope scope) { - final String previousTraceId = MDC.get("traceId"); - final String previousParentId = MDC.get("parentId"); - final String previousSpanId = MDC.get("spanId"); - final String spanExportable = MDC.get("spanExportable"); - final String legacyPreviousTraceId = MDC.get(LEGACY_TRACE_ID_NAME); - final String legacyPreviousParentId = MDC.get(LEGACY_PARENT_ID_NAME); - final String legacyPreviousSpanId = MDC.get(LEGACY_SPAN_ID_NAME); - final String legacySpanExportable = MDC.get(LEGACY_EXPORTABLE_NAME); - final List> previousMdc = previousMdc(); - - if (currentSpan != null) { - String traceIdString = currentSpan.traceIdString(); - MDC.put("traceId", traceIdString); - MDC.put(LEGACY_TRACE_ID_NAME, traceIdString); - String parentId = currentSpan.parentId() != null - ? HexCodec.toLowerHex(currentSpan.parentId()) : null; - replace("parentId", parentId); - replace(LEGACY_PARENT_ID_NAME, parentId); - String spanId = HexCodec.toLowerHex(currentSpan.spanId()); - MDC.put("spanId", spanId); - MDC.put(LEGACY_SPAN_ID_NAME, spanId); - String sampled = String.valueOf(currentSpan.sampled()); - MDC.put("spanExportable", sampled); - MDC.put(LEGACY_EXPORTABLE_NAME, sampled); - log("Starting scope for span: {}", currentSpan); - if (currentSpan.parentId() != null) { - if (log.isTraceEnabled()) { - log.trace("With parent: {}", currentSpan.parentId()); - } - } - for (String key : whitelistedBaggageKeysWithValue(currentSpan)) { - MDC.put(key, ExtraFieldPropagation.get(currentSpan, key)); - } - for (String key : whitelistedPropagationKeysWithValue(currentSpan)) { - MDC.put(key, ExtraFieldPropagation.get(currentSpan, key)); - } - for (String key : whitelistedLocalKeysWithValue(currentSpan)) { - MDC.put(key, ExtraFieldPropagation.get(currentSpan, key)); - } - } - else { - MDC.remove("traceId"); - MDC.remove("parentId"); - MDC.remove("spanId"); - MDC.remove("spanExportable"); - MDC.remove(LEGACY_TRACE_ID_NAME); - MDC.remove(LEGACY_PARENT_ID_NAME); - MDC.remove(LEGACY_SPAN_ID_NAME); - MDC.remove(LEGACY_EXPORTABLE_NAME); - for (String s : whitelistedBaggageKeys()) { - MDC.remove(s); - } - for (String s : whitelistedPropagationKeys()) { - MDC.remove(s); - } - for (String s : whitelistedLocalKeys()) { - MDC.remove(s); - } - previousMdc.clear(); - } - - /** - * Thread context scope. - * - * @author Adrian Cole - */ - class ThreadContextCurrentTraceContextScope implements CurrentTraceContext.Scope { - - @Override - public void close() { - log("Closing scope for span: {}", currentSpan); - scope.close(); - replace("traceId", previousTraceId); - replace("parentId", previousParentId); - replace("spanId", previousSpanId); - replace("spanExportable", spanExportable); - replace(LEGACY_TRACE_ID_NAME, legacyPreviousTraceId); - replace(LEGACY_PARENT_ID_NAME, legacyPreviousParentId); - replace(LEGACY_SPAN_ID_NAME, legacyPreviousSpanId); - replace(LEGACY_EXPORTABLE_NAME, legacySpanExportable); - for (AbstractMap.SimpleEntry entry : previousMdc) { - replace(entry.getKey(), entry.getValue()); - } - } - - } - return new ThreadContextCurrentTraceContextScope(); - } - - private List> previousMdc() { - List> previousMdc = new ArrayList<>(); - List keys = new ArrayList<>(whitelistedBaggageKeys()); - keys.addAll(whitelistedPropagationKeys()); - keys.addAll(whitelistedLocalKeys()); - for (String key : keys) { - previousMdc.add(new AbstractMap.SimpleEntry<>(key, MDC.get(key))); - } - return previousMdc; - } - - private List whitelistedKeys(List keysToFilter) { - List keys = new ArrayList<>(); - for (String baggageKey : keysToFilter) { - if (this.sleuthSlf4jProperties.getWhitelistedMdcKeys().contains(baggageKey)) { - keys.add(baggageKey); - } - } - return keys; - } - - private List whitelistedBaggageKeys() { - return whitelistedKeys(this.sleuthProperties.getBaggageKeys()); - } - - private List whitelistedKeysWithValue(TraceContext context, - List keys) { - if (context == null) { - return Collections.EMPTY_LIST; - } - List nonEmpty = new ArrayList<>(); - for (String key : keys) { - if (StringUtils.hasText(ExtraFieldPropagation.get(context, key))) { - nonEmpty.add(key); - } - } - return nonEmpty; - } - - private List whitelistedBaggageKeysWithValue(TraceContext context) { - return whitelistedKeysWithValue(context, whitelistedBaggageKeys()); - } - - private List whitelistedPropagationKeys() { - return whitelistedKeys(this.sleuthProperties.getPropagationKeys()); - } - - private List whitelistedLocalKeys() { - return whitelistedKeys(this.sleuthProperties.getLocalKeys()); - } - - private List whitelistedPropagationKeysWithValue(TraceContext context) { - return whitelistedKeysWithValue(context, whitelistedPropagationKeys()); - } - - private List whitelistedLocalKeysWithValue(TraceContext context) { - return whitelistedKeysWithValue(context, whitelistedLocalKeys()); - } - - private void log(String text, TraceContext span) { - if (span == null) { - return; - } - if (log.isTraceEnabled()) { - log.trace(text, span); - } + public Scope decorateScope(TraceContext context, Scope scope) { + return LEGACY_IDS.decorateScope(context, delegate.decorateScope(context, scope)); } } diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java index dfe95fc77..a7fec2340 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java @@ -20,24 +20,22 @@ import brave.Span; import brave.Tracer; import brave.propagation.CurrentTraceContext.Scope; import brave.propagation.ExtraFieldPropagation; -import org.junit.After; -import org.junit.Before; -import org.junit.Test; -import org.junit.runner.RunWith; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; import org.slf4j.MDC; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.boot.SpringBootConfiguration; import org.springframework.boot.autoconfigure.EnableAutoConfiguration; import org.springframework.boot.test.context.SpringBootTest; -import org.springframework.test.context.junit4.SpringRunner; +import static brave.propagation.CurrentTraceContext.Scope.NOOP; import static org.assertj.core.api.Assertions.assertThat; /** * @author Marcin Grzejszczak */ -@RunWith(SpringRunner.class) @SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.NONE, properties = { "spring.sleuth.baggage-keys=my-baggage", "spring.sleuth.propagation-keys=my-propagation", @@ -55,8 +53,8 @@ public class Slf4JSpanLoggerTest { Span span; - @Before - @After + @BeforeEach + @AfterEach public void setup() { MDC.clear(); this.span = this.tracer.nextSpan().name("span").start(); @@ -67,13 +65,10 @@ public class Slf4JSpanLoggerTest { Scope scope = this.slf4jScopeDecorator.decorateScope(this.span.context(), () -> { }); - assertThat(MDC.get("X-B3-TraceId")) - .isEqualTo(this.span.context().traceIdString()); assertThat(MDC.get("traceId")).isEqualTo(this.span.context().traceIdString()); scope.close(); - assertThat(MDC.get("X-B3-TraceId")).isNullOrEmpty(); assertThat(MDC.get("traceId")).isNullOrEmpty(); } @@ -102,19 +97,17 @@ public class Slf4JSpanLoggerTest { ExtraFieldPropagation.set(this.span.context(), "my-baggage", "my-value"); ExtraFieldPropagation.set(this.span.context(), "my-propagation", "my-propagation-value"); - this.slf4jScopeDecorator.decorateScope(this.span.context(), () -> { - }); - assertThat(MDC.get("my-baggage")).isEqualTo("my-value"); - assertThat(MDC.get("my-propagation")).isEqualTo("my-propagation-value"); + try (Scope scope1 = this.slf4jScopeDecorator.decorateScope(this.span.context(), + NOOP)) { + assertThat(MDC.get("my-baggage")).isEqualTo("my-value"); + assertThat(MDC.get("my-propagation")).isEqualTo("my-propagation-value"); - Scope scope = this.slf4jScopeDecorator.decorateScope(null, () -> { - }); - - scope.close(); - - assertThat(MDC.get("my-baggage")).isNullOrEmpty(); - assertThat(MDC.get("my-propagation")).isNullOrEmpty(); + try (Scope scope2 = this.slf4jScopeDecorator.decorateScope(null, NOOP)) { + assertThat(MDC.get("my-baggage")).isNullOrEmpty(); + assertThat(MDC.get("my-propagation")).isNullOrEmpty(); + } + } } @Test @@ -123,35 +116,36 @@ public class Slf4JSpanLoggerTest { MDC.put("my-baggage", "my-value"); MDC.put("my-propagation", "my-propagation-value"); - this.slf4jScopeDecorator.decorateScope(this.span.context(), () -> { - }); + // the span is holding no baggage so it clears the preceding values + try (Scope scope = this.slf4jScopeDecorator.decorateScope(this.span.context(), + NOOP)) { + assertThat(MDC.get("my-baggage")).isNullOrEmpty(); + assertThat(MDC.get("my-propagation")).isNullOrEmpty(); + } assertThat(MDC.get("my-baggage")).isEqualTo("my-value"); assertThat(MDC.get("my-propagation")).isEqualTo("my-propagation-value"); - Scope scope = this.slf4jScopeDecorator.decorateScope(null, () -> { - }); + try (Scope scope = this.slf4jScopeDecorator.decorateScope(null, NOOP)) { + assertThat(MDC.get("my-baggage")).isNullOrEmpty(); + assertThat(MDC.get("my-propagation")).isNullOrEmpty(); + } - scope.close(); - - assertThat(MDC.get("my-baggage")).isNullOrEmpty(); - assertThat(MDC.get("my-propagation")).isNullOrEmpty(); + assertThat(MDC.get("my-baggage")).isEqualTo("my-value"); + assertThat(MDC.get("my-propagation")).isEqualTo("my-propagation-value"); } @Test public void should_remove_entries_from_mdc_from_null_span() throws Exception { - MDC.put("X-B3-TraceId", "A"); MDC.put("traceId", "A"); Scope scope = this.slf4jScopeDecorator.decorateScope(null, () -> { }); - assertThat(MDC.get("X-B3-TraceId")).isNullOrEmpty(); assertThat(MDC.get("traceId")).isNullOrEmpty(); scope.close(); - assertThat(MDC.get("X-B3-TraceId")).isEqualTo("A"); assertThat(MDC.get("traceId")).isEqualTo("A"); } From c20f6c6a11f30515646ad2a6b6e38e36eef683fa Mon Sep 17 00:00:00 2001 From: Adrian Cole Date: Fri, 3 Apr 2020 19:57:37 +0800 Subject: [PATCH 2/2] Moves Slf4jScopeDecorator to use CorrelationField internally (#1597) --- benchmarks/pom.xml | 2 +- pom.xml | 2 +- .../cloud/sleuth/log/Slf4jScopeDecorator.java | 36 ++++++++++++------- .../cloud/sleuth/log/Slf4JSpanLoggerTest.java | 16 +++++++-- spring-cloud-sleuth-dependencies/pom.xml | 4 +-- 5 files changed, 40 insertions(+), 20 deletions(-) diff --git a/benchmarks/pom.xml b/benchmarks/pom.xml index 10d021913..68d5ef134 100644 --- a/benchmarks/pom.xml +++ b/benchmarks/pom.xml @@ -33,7 +33,7 @@ 1.8 1.8 2.2.5.RELEASE - 5.11.0 + 5.11.1 3.14.6 diff --git a/pom.xml b/pom.xml index 7ec83ac0d..8fd836d48 100644 --- a/pom.xml +++ b/pom.xml @@ -264,7 +264,7 @@ Horsham.SR3 2.2.3.BUILD-SNAPSHOT 2.2.3.BUILD-SNAPSHOT - 5.11.0 + 5.11.1 2.1.7.RELEASE 2.2.1.RELEASE false diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java index 0522c7208..d2d0c667c 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/log/Slf4jScopeDecorator.java @@ -22,6 +22,7 @@ import java.util.TreeSet; import brave.baggage.BaggageField; import brave.baggage.BaggageFields; +import brave.baggage.CorrelationField; import brave.baggage.CorrelationScopeDecorator; import brave.context.slf4j.MDCScopeDecorator; import brave.propagation.CurrentTraceContext.Scope; @@ -45,10 +46,16 @@ final class Slf4jScopeDecorator implements ScopeDecorator { // Backward compatibility for all logging patterns private static final ScopeDecorator LEGACY_IDS = MDCScopeDecorator.newBuilder() - .clear().addField(BaggageFields.TRACE_ID, "X-B3-TraceId") - .addField(BaggageFields.PARENT_ID, "X-B3-ParentSpanId") - .addField(BaggageFields.SPAN_ID, "X-B3-SpanId") - .addField(BaggageFields.SAMPLED, "X-Span-Export").build(); + .clear() + .addField(CorrelationField.newBuilder(BaggageFields.TRACE_ID) + .name("X-B3-TraceId").build()) + .addField(CorrelationField.newBuilder(BaggageFields.PARENT_ID) + .name("X-B3-ParentSpanId").build()) + .addField(CorrelationField.newBuilder(BaggageFields.SPAN_ID) + .name("X-B3-SpanId").build()) + .addField(CorrelationField.newBuilder(BaggageFields.SAMPLED) + .name("X-Span-Export").build()) + .build(); private final ScopeDecorator delegate; @@ -56,25 +63,28 @@ final class Slf4jScopeDecorator implements ScopeDecorator { SleuthSlf4jProperties sleuthSlf4jProperties) { CorrelationScopeDecorator.Builder builder = MDCScopeDecorator.newBuilder().clear() - .addField(BaggageFields.TRACE_ID).addField(BaggageFields.PARENT_ID) - .addField(BaggageFields.SPAN_ID) - .addField(BaggageFields.SAMPLED, "spanExportable"); + .addField(CorrelationField.create(BaggageFields.TRACE_ID)) + .addField(CorrelationField.create(BaggageFields.PARENT_ID)) + .addField(CorrelationField.create(BaggageFields.SPAN_ID)) + .addField(CorrelationField.newBuilder(BaggageFields.SAMPLED) + .name("spanExportable").build()); Set whitelist = new TreeSet<>(String.CASE_INSENSITIVE_ORDER); whitelist.addAll(sleuthSlf4jProperties.getWhitelistedMdcKeys()); + // Note: we are adding all the keys as-is because correlation context doesn't + // prefix, only ExtraFieldPropagation does Set retained = new LinkedHashSet<>(); retained.addAll(sleuthProperties.getBaggageKeys()); retained.addAll(sleuthProperties.getLocalKeys()); retained.addAll(sleuthProperties.getPropagationKeys()); + retained.retainAll(whitelist); + // For backwards compatibility set all fields dirty, so that any changes made by + // MDC directly are reverted. for (String name : retained) { - if (whitelist.contains(name)) { - // Until we move off ExtraFieldPropagation onto BaggagePropagation, - // manually create the fields... - builder.addField(BaggageField.create(name)); - builder.addDirtyName(name); - } + builder.addField(CorrelationField.newBuilder(BaggageField.create(name)) + .dirty().build()); } this.delegate = builder.build(); diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java index a7fec2340..a3004ad8d 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/log/Slf4JSpanLoggerTest.java @@ -18,8 +18,10 @@ package org.springframework.cloud.sleuth.log; import brave.Span; import brave.Tracer; +import brave.baggage.CorrelationField; import brave.propagation.CurrentTraceContext.Scope; import brave.propagation.ExtraFieldPropagation; +import org.assertj.core.api.InstanceOfAssertFactories; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; @@ -37,7 +39,7 @@ import static org.assertj.core.api.Assertions.assertThat; * @author Marcin Grzejszczak */ @SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.NONE, properties = { - "spring.sleuth.baggage-keys=my-baggage", + "spring.sleuth.baggage-keys=my-baggage,my-baggage-two", "spring.sleuth.propagation-keys=my-propagation", "spring.sleuth.local-keys=my-local", "spring.sleuth.log.slf4j.whitelisted-mdc-keys=my-baggage,my-propagation,my-local" }) @@ -170,8 +172,16 @@ public class Slf4JSpanLoggerTest { } @Test - public void should_pick_previous_mdc_entries_when_their_keys_are_whitelisted() - throws Exception { + public void should_only_include_whitelist() { + assertThat(this.slf4jScopeDecorator).extracting("delegate.fields") + .asInstanceOf(InstanceOfAssertFactories.array(CorrelationField[].class)) + .extracting(CorrelationField::name).containsExactly("traceId", "parentId", + "spanId", "spanExportable", "my-baggage", "my-local", + "my-propagation"); // my-baggage-two is baggage not in the whitelist + } + + @Test + public void should_pick_previous_mdc_entries_when_their_keys_are_whitelisted() { MDC.put("my-baggage", "A1"); MDC.put("my-propagation", "B1"); diff --git a/spring-cloud-sleuth-dependencies/pom.xml b/spring-cloud-sleuth-dependencies/pom.xml index 34a970ddf..be6ff023e 100644 --- a/spring-cloud-sleuth-dependencies/pom.xml +++ b/spring-cloud-sleuth-dependencies/pom.xml @@ -31,8 +31,8 @@ spring-cloud-sleuth-dependencies Spring Cloud Sleuth Dependencies - 5.11.0 - 0.36.0 + 5.11.1 + 0.36.1 3.4.1