From c683b7eab5a19c932b6c220c25d24bf2d56c9636 Mon Sep 17 00:00:00 2001 From: Nikhil Bysani Date: Wed, 27 Jun 2018 17:20:39 -0500 Subject: [PATCH] Test logging, DRY finish check. Signed-off-by: Nikhil Bysani --- jaeger-core/build.gradle | 2 +- .../java/io/jaegertracing/JaegerSpan.java | 57 +++++++------------ .../java/io/jaegertracing/JaegerTracer.java | 25 +++++--- .../java/io/jaegertracing/JaegerSpanTest.java | 48 ++++++++++++++++ 4 files changed, 86 insertions(+), 46 deletions(-) diff --git a/jaeger-core/build.gradle b/jaeger-core/build.gradle index 6751853c7..23cff2d29 100644 --- a/jaeger-core/build.gradle +++ b/jaeger-core/build.gradle @@ -13,8 +13,8 @@ dependencies { testCompile group: 'org.mockito', name: 'mockito-core', version: mockitoVersion testCompile group: 'com.tngtech.java', name: 'junit-dataprovider', version: junitDataProviderVersion testCompile group: 'org.awaitility', name: 'awaitility', version: awaitilityVersion - testCompile group: 'ch.qos.logback', name: 'logback-classic', version: logbackVersion testCompile group: 'io.micrometer', name: 'micrometer-registry-prometheus', version: micrometerVersion + testCompile group: 'uk.org.lidalia', name: 'slf4j-test', version: '1.2.0' signature 'org.codehaus.mojo.signature:java16:1.1@signature' } diff --git a/jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java b/jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java index 58dbed2db..39a2ff0e0 100644 --- a/jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java +++ b/jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java @@ -99,14 +99,10 @@ public Map getTags() { @Override public JaegerSpan setOperationName(String operationName) { synchronized (this) { - if (finished) { - if (tracer.isLoggingStackTraces()) { - log.warn("Span has already been finished; will not set name.", new RuntimeException("Called from:")); - } else { - log.warn("Span has already been finished; will not set name."); - } + if (spanAlreadyFinished("set baggage item")) { return this; } + this.operationName = operationName; } return this; @@ -140,12 +136,7 @@ public JaegerSpan setBaggageItem(String key, String value) { return this; } synchronized (this) { - if (finished) { - if (tracer.isLoggingStackTraces()) { - log.warn("Span has already been finished; will not set baggage.", new RuntimeException("Called from:")); - } else { - log.warn("Span has already been finished; will not set baggage."); - } + if (spanAlreadyFinished("set baggage item")) { return this; } @@ -193,12 +184,7 @@ public void finish(long finishMicros) { private void finishWithDuration(long durationMicros) { synchronized (this) { - if (finished) { - if (tracer.isLoggingStackTraces()) { - log.warn("Span has already been finished; will not be reported again.", new RuntimeException("Called from:")); - } else { - log.warn("Span has already been finished; will not be reported again."); - } + if (spanAlreadyFinished("finish")) { return; } @@ -228,12 +214,7 @@ public synchronized JaegerSpan setTag(String key, Number value) { } private JaegerSpan setTagAsObject(String key, Object value) { - if (finished) { - if (tracer.isLoggingStackTraces()) { - log.warn("Span has already been finished; cannot set tag.", new RuntimeException("Called from:")); - } else { - log.warn("Span has already been finished; cannot set tag."); - } + if (spanAlreadyFinished("set tag")) { return this; } @@ -264,12 +245,7 @@ public JaegerSpan log(Map fields) { @Override public JaegerSpan log(long timestampMicroseconds, Map fields) { synchronized (this) { - if (finished) { - if (tracer.isLoggingStackTraces()) { - log.warn("Span has already been finished; cannot log.", new RuntimeException("Called from:")); - } else { - log.warn("Span has already been finished; cannot log."); - } + if (spanAlreadyFinished("log")) { return this; } @@ -297,12 +273,7 @@ public JaegerSpan log(String event) { @Override public JaegerSpan log(long timestampMicroseconds, String event) { synchronized (this) { - if (finished) { - if (tracer.isLoggingStackTraces()) { - log.warn("Span has already been finished; cannot log.", new RuntimeException("Called from:")); - } else { - log.warn("Span has already been finished; cannot log."); - } + if (spanAlreadyFinished("log")) { return this; } @@ -319,6 +290,20 @@ public JaegerSpan log(long timestampMicroseconds, String event) { } } + private boolean spanAlreadyFinished(String methodName) { + if (finished) { + if (tracer.isLoggingStackTracesOnWarnings()) { + log.warn("Span has already been finished; cannot {}.", methodName, new RuntimeException("Called from:")); + } else { + log.warn("Span has already been finished; cannot {}.", methodName); + } + + return true; + } + + return false; + } + /** * Creates logs related to logged exception * diff --git a/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java b/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java index c3aab4152..02512e979 100644 --- a/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java +++ b/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java @@ -74,7 +74,7 @@ public class JaegerTracer implements Tracer, Closeable { private final ScopeManager scopeManager; private final BaggageSetter baggageSetter; private final boolean expandExceptionLogs; - private final boolean loggingStackTraces; + private final boolean loggingStackTracesOnWarnings; private JaegerTracer( String serviceName, @@ -88,7 +88,7 @@ private JaegerTracer( ScopeManager scopeManager, BaggageRestrictionManager baggageRestrictionManager, boolean expandExceptionLogs, - boolean loggingStackTraces) { + boolean loggingStackTracesOnWarnings) { this.serviceName = serviceName; this.reporter = reporter; this.sampler = sampler; @@ -99,7 +99,7 @@ private JaegerTracer( this.scopeManager = scopeManager; this.baggageSetter = new BaggageSetter(baggageRestrictionManager, metrics); this.expandExceptionLogs = expandExceptionLogs; - this.loggingStackTraces = loggingStackTraces; + this.loggingStackTracesOnWarnings = loggingStackTracesOnWarnings; this.version = loadVersion(); @@ -471,7 +471,7 @@ public static final class Builder { private ScopeManager scopeManager = new ThreadLocalScopeManager(); private BaggageRestrictionManager baggageRestrictionManager = new DefaultBaggageRestrictionManager(); private boolean expandExceptionLogs; - private boolean loggingStackTraces; + private boolean loggingStackTracesOnWarnings; public Builder(String serviceName) { this.serviceName = checkValidServiceName(serviceName); @@ -540,8 +540,14 @@ public Builder withExpandExceptionLogs() { return this; } - public Builder withLoggingStackTraces() { - this.loggingStackTraces = true; + /** + * When invalid operations are called log the stack trace in log warning. + * @return this instance of the builder + * For example, if you call finish twice and this is set, then the emitted warning + * log will include a stack trace to determine the call site. + */ + public Builder withLoggingStackTracesOnWarnings() { + this.loggingStackTracesOnWarnings = true; return this; } @@ -589,7 +595,8 @@ public JaegerTracer build() { .build(); } return new JaegerTracer(serviceName, reporter, sampler, registry, clock, metrics, tags, - zipkinSharedRpcSpan, scopeManager, baggageRestrictionManager, expandExceptionLogs, loggingStackTraces); + zipkinSharedRpcSpan, scopeManager, baggageRestrictionManager, expandExceptionLogs, + loggingStackTracesOnWarnings); } public static String checkValidServiceName(String serviceName) { @@ -637,7 +644,7 @@ boolean isExpandExceptionLogs() { return this.expandExceptionLogs; } - boolean isLoggingStackTraces() { - return this.loggingStackTraces; + boolean isLoggingStackTracesOnWarnings() { + return this.loggingStackTracesOnWarnings; } } diff --git a/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java b/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java index a1731d1bb..7e4670022 100644 --- a/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java +++ b/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java @@ -41,11 +41,17 @@ import java.util.List; import java.util.Map; import java.util.Map.Entry; +import org.junit.After; import org.junit.Before; import org.junit.Test; import org.mockito.Mockito; +import uk.org.lidalia.slf4jext.Level; +import uk.org.lidalia.slf4jtest.LoggingEvent; +import uk.org.lidalia.slf4jtest.TestLogger; +import uk.org.lidalia.slf4jtest.TestLoggerFactory; public class JaegerSpanTest { + private static final TestLogger log = TestLoggerFactory.getTestLogger(JaegerSpan.class); private Clock clock; private InMemoryReporter reporter; private JaegerTracer tracer; @@ -70,6 +76,11 @@ public void setUp() { jaegerSpan = (JaegerSpan) tracer.buildSpan("some-operation").start(); } + @After + public void clearLoggers() { + TestLoggerFactory.clear(); + } + @Test public void testSpanMetrics() { assertEquals(1, metricsFactory.getCounter("jaeger:started_spans", "sampled=y")); @@ -477,6 +488,43 @@ public void testNoExpandExceptionLogs() { assertEquals(ex, logData.get(0).getFields().get(Fields.ERROR_OBJECT)); } + @Test + public void testNoLoggingingStackTracesOnWarnings() { + JaegerTracer tracer = new JaegerTracer.Builder("fo") + .withReporter(reporter) + .withSampler(new ConstSampler(true)) + .build(); + + JaegerSpan jaegerSpan = (JaegerSpan)tracer.buildSpan("foo").start(); + jaegerSpan.finish(); + jaegerSpan.finish(); + + assertEquals(1, log.getLoggingEvents().size()); + LoggingEvent event = log.getLoggingEvents().get(0); + assertEquals("Span has already been finished; cannot {}.", event.getMessage()); + assertEquals(Level.WARN, event.getLevel()); + assertEquals(false, event.getThrowable().isPresent()); + } + + @Test + public void testLoggingingStackTracesOnWarnings() { + JaegerTracer tracer = new JaegerTracer.Builder("fo") + .withReporter(reporter) + .withSampler(new ConstSampler(true)) + .withLoggingStackTracesOnWarnings() + .build(); + + JaegerSpan jaegerSpan = (JaegerSpan)tracer.buildSpan("foo").start(); + jaegerSpan.finish(); + jaegerSpan.finish(); + + assertEquals(1, log.getLoggingEvents().size()); + LoggingEvent event = log.getLoggingEvents().get(0); + assertEquals("Span has already been finished; cannot {}.", event.getMessage()); + assertEquals(Level.WARN, event.getLevel()); + assertEquals("Called from:", event.getThrowable().get().getMessage()); + } + @Test public void testSpanNotSampled() { JaegerTracer tracer = new JaegerTracer.Builder("fo")