Skip to content
This repository has been archived by the owner on Jul 1, 2022. It is now read-only.

After finish, disallow setTag. #467

Closed
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion jaeger-core/build.gradle
Original file line number Diff line number Diff line change
Expand Up @@ -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'
}
Expand Down
36 changes: 34 additions & 2 deletions jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java
Original file line number Diff line number Diff line change
Expand Up @@ -99,6 +99,10 @@ public Map<String, Object> getTags() {
@Override
public JaegerSpan setOperationName(String operationName) {
synchronized (this) {
if (spanAlreadyFinished("set operation name")) {
return this;
}

this.operationName = operationName;
}
return this;
Expand Down Expand Up @@ -132,6 +136,10 @@ public JaegerSpan setBaggageItem(String key, String value) {
return this;
}
synchronized (this) {
if (spanAlreadyFinished("set baggage item")) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

strictly speaking setting baggage would work even after the span is finished

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems unlikely that the user would intend to do this, but do you want me to remove it?

return this;
}

context = tracer.setBaggage(this, key, value);
return this;
}
Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand Down Expand Up @@ -233,6 +245,10 @@ public JaegerSpan log(Map<String, ?> fields) {
@Override
public JaegerSpan log(long timestampMicroseconds, Map<String, ?> fields) {
synchronized (this) {
if (spanAlreadyFinished("log")) {
return this;
}

if (fields == null) {
return this;
}
Expand All @@ -257,6 +273,10 @@ public JaegerSpan log(String event) {
@Override
public JaegerSpan log(long timestampMicroseconds, String event) {
synchronized (this) {
if (spanAlreadyFinished("log")) {
return this;
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suggest to DRY it by moving this to a method spanAlreadyFinished(String funcName) and then replacing the checks with

if (spanAlreadyFinished("setTag")) {
    return this;
}


if (event == null) {
return this;
}
Expand All @@ -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
*
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -226,7 +226,7 @@ public class SpanBuilder implements Tracer.SpanBuilder {
private final Map<String, Object> tags = new HashMap<String, Object>();
private boolean ignoreActiveSpan = false;

SpanBuilder(String operationName) {
private SpanBuilder(String operationName) {
this.operationName = operationName;
}

Expand Down
93 changes: 93 additions & 0 deletions jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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"));
Expand Down Expand Up @@ -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";
Expand All @@ -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);
Expand Down Expand Up @@ -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<String, String> 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();
Expand Down Expand Up @@ -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"));
Expand Down Expand Up @@ -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")
Expand Down