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

Commit

Permalink
Test logging, DRY finish check.
Browse files Browse the repository at this point in the history 
Signed-off-by: Nikhil Bysani <nikhil.bysani@signifyd.com>
  • Loading branch information
Nikhil Bysani committed Jun 27, 2018
1 parent 6cdb58e commit c683b7e
Show file tree
Hide file tree
Showing 4 changed files with 86 additions and 46 deletions.
2 changes: 1 addition & 1 deletion jaeger-core/build.gradle
View file
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
57 changes: 21 additions & 36 deletions jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -99,14 +99,10 @@ public Map<String, Object> 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;
Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -264,12 +245,7 @@ public JaegerSpan log(Map<String, ?> fields) {
@Override
public JaegerSpan log(long timestampMicroseconds, Map<String, ?> 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;
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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
*
Expand Down
25 changes: 16 additions & 9 deletions jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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;
Expand All @@ -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();

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -637,7 +644,7 @@ boolean isExpandExceptionLogs() {
return this.expandExceptionLogs;
}

boolean isLoggingStackTraces() {
return this.loggingStackTraces;
boolean isLoggingStackTracesOnWarnings() {
return this.loggingStackTracesOnWarnings;
}
}
48 changes: 48 additions & 0 deletions jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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"));
Expand Down Expand Up @@ -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")
Expand Down

0 comments on commit c683b7e

Please sign in to comment.