From 5c6d8a5d5dfb6d70a3807b32174657638476f741 Mon Sep 17 00:00:00 2001 From: Nikhil Bysani Date: Wed, 27 Jun 2018 08:55:41 -0500 Subject: [PATCH] After finish, noop set methods. Do more logging on debug levels. Signed-off-by: Nikhil Bysani --- jaeger-core/build.gradle | 2 +- .../java/io/jaegertracing/JaegerSpan.java | 36 ++++++- .../java/io/jaegertracing/JaegerTracer.java | 2 +- .../java/io/jaegertracing/JaegerSpanTest.java | 93 +++++++++++++++++++ 4 files changed, 129 insertions(+), 4 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 9692ef5dc..bfe7bcaa7 100644 --- a/jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java +++ b/jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java @@ -99,6 +99,10 @@ public Map getTags() { @Override public JaegerSpan setOperationName(String operationName) { synchronized (this) { + if (spanAlreadyFinished("set operation name")) { + return this; + } + this.operationName = operationName; } return this; @@ -132,6 +136,10 @@ public JaegerSpan setBaggageItem(String key, String value) { return this; } synchronized (this) { + if (spanAlreadyFinished("set baggage item")) { + return this; + } + context = tracer.setBaggage(this, key, value); return this; } @@ -176,10 +184,10 @@ public void finish(long finishMicros) { private void finishWithDuration(long durationMicros) { synchronized (this) { - if (finished) { - log.warn("Span has already been finished; will not be reported again."); + if (spanAlreadyFinished("finish")) { return; } + finished = true; this.durationMicroseconds = durationMicros; @@ -206,6 +214,10 @@ public synchronized JaegerSpan setTag(String key, Number value) { } private JaegerSpan setTagAsObject(String key, Object value) { + if (spanAlreadyFinished("set tag")) { + return this; + } + if (key.equals(Tags.SAMPLING_PRIORITY.getKey()) && (value instanceof Number)) { int priority = ((Number) value).intValue(); byte newFlags; @@ -233,6 +245,10 @@ public JaegerSpan log(Map fields) { @Override public JaegerSpan log(long timestampMicroseconds, Map fields) { synchronized (this) { + if (spanAlreadyFinished("log")) { + return this; + } + if (fields == null) { return this; } @@ -257,6 +273,10 @@ public JaegerSpan log(String event) { @Override public JaegerSpan log(long timestampMicroseconds, String event) { synchronized (this) { + if (spanAlreadyFinished("log")) { + return this; + } + if (event == null) { return this; } @@ -270,6 +290,18 @@ public JaegerSpan log(long timestampMicroseconds, String event) { } } + private boolean spanAlreadyFinished(String methodName) { + if (finished) { + log.warn("Span has already been finished; cannot {}.", methodName); + if (log.isDebugEnabled()) { + log.debug("Generating stack trace because we cannot {}.", methodName, new RuntimeException("Called from:")); + } + 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 258d37d47..052a11ef2 100644 --- a/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java +++ b/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java @@ -226,7 +226,7 @@ public class SpanBuilder implements Tracer.SpanBuilder { private final Map tags = new HashMap(); private boolean ignoreActiveSpan = false; - SpanBuilder(String operationName) { + private SpanBuilder(String operationName) { this.operationName = operationName; } diff --git a/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java b/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java index 2d026ba17..2d851d439 100644 --- a/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java +++ b/jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java @@ -40,11 +40,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; @@ -69,6 +75,11 @@ public void setUp() { 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")); @@ -113,6 +124,16 @@ public void testSetOperationName() { assertEquals(expected, jaegerSpan.getOperationName()); } + @Test + public void testSetOperationNameAfterrFinish() { + String unexpected = "modified.operation"; + + assertEquals("some-operation", jaegerSpan.getOperationName()); + jaegerSpan.finish(); + jaegerSpan.setOperationName(unexpected); + assertEquals("some-operation", jaegerSpan.getOperationName()); + } + @Test public void testSetStringTag() { String expected = "expected.value"; @@ -131,6 +152,16 @@ public void testSetNumberTag() { assertEquals(expected, jaegerSpan.getTags().get(key)); } + @Test + public void testSetStringTagAfterFinish() { + String value = "unexpected.value"; + String key = "tag.key"; + + jaegerSpan.finish(); + jaegerSpan.setTag(key, value); + assertEquals(null, jaegerSpan.getTags().get(key)); + } + @Test public void testWithTimestampAccurateClock() { testWithTimestamp(true); @@ -277,6 +308,28 @@ public void testLog() { assertEquals(expectedFields, actualLogData.getFields()); } + @Test + public void testLogAfterFinish() { + final long expectedTimestamp = 2222; + final String expectedLog = "some-log"; + final String expectedEvent = "expectedEvent"; + + when(clock.currentTimeMicros()).thenReturn(expectedTimestamp); + + jaegerSpan.finish(); + jaegerSpan.log(expectedEvent); + assertNull(jaegerSpan.getLogs()); + } + + @Test + public void testLogWithTimestampAfterFinish() { + Map unexpectedFields = Collections.singletonMap("foo", "bar"); + + jaegerSpan.finish(); + jaegerSpan.log(2222, unexpectedFields); + assertNull(jaegerSpan.getLogs()); + } + @Test public void testSpanDetectsSamplingPriorityGreaterThanZero() { JaegerSpan jaegerSpan = tracer.buildSpan("test-service-operation").start(); @@ -361,6 +414,14 @@ public void testImmutableBaggage() { assertFalse(baggageIter.hasNext()); } + @Test + public void testSetBaggageAfterFinish() { + jaegerSpan.finish(); + jaegerSpan.setBaggageItem("foo", "bar"); + + assertNull(jaegerSpan.getBaggageItem("foo")); + } + @Test public void testExpandExceptionLogs() { RuntimeException ex = new RuntimeException(new NullPointerException("npe")); @@ -439,6 +500,38 @@ public void testNoExpandExceptionLogs() { assertEquals(ex, logData.get(0).getFields().get(Fields.ERROR_OBJECT)); } + @Test + public void testNoLoggingingStackTracesOnDebug() { + log.setEnabledLevels(Level.WARN); + 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 testLoggingingStackTracesOnDebug() { + log.setEnabledLevels(Level.WARN, Level.DEBUG); + JaegerSpan jaegerSpan = tracer.buildSpan("foo").start(); + jaegerSpan.finish(); + jaegerSpan.finish(); + + assertEquals(2, 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()); + event = log.getLoggingEvents().get(1); + assertEquals("Generating stack trace because we cannot {}.", event.getMessage()); + assertEquals(Level.DEBUG, event.getLevel()); + assertEquals("Called from:", event.getThrowable().get().getMessage()); + } + @Test public void testSpanNotSampled() { JaegerTracer tracer = new JaegerTracer.Builder("fo")