After finish, disallow setTag. #467

nikron · 2018-06-27T14:03:30Z

Which problem is this PR solving?

If you set the tag after the span finishes, this can cause a race condition in the sender as it tries to iterate over the tag map.

To fix that, you really shouldn't even be able to set a tag after the span finishes.

Short description of the changes

Check finish on setTagAsObject and return if the span is already finished.

codecov · 2018-06-27T14:12:35Z

Codecov Report

Merging #467 into master will decrease coverage by 1.54%.
The diff coverage is 100%.

@@             Coverage Diff              @@
##             master     #467      +/-   ##
============================================
- Coverage     89.76%   88.21%   -1.55%     
+ Complexity      563      501      -62     
============================================
  Files            69       63       -6     
  Lines          2061     1867     -194     
  Branches        261      247      -14     
============================================
- Hits           1850     1647     -203     
- Misses          132      142      +10     
+ Partials         79       78       -1

Impacted Files	Coverage Δ	Complexity Δ
...e/src/main/java/io/jaegertracing/JaegerTracer.java	`89.71% <100%> (ø)`	`23 <0> (?)`
...ore/src/main/java/io/jaegertracing/JaegerSpan.java	`93.75% <100%> (ø)`	`54 <8> (?)`
...xceptions/MalformedTracerStateStringException.java
...in/java/io/jaegertracing/internal/utils/Utils.java
...nal/exceptions/SamplingStrategyErrorException.java
...io/jaegertracing/internal/PropagationRegistry.java
...ng/internal/exceptions/NotFourOctetsException.java
...io/jaegertracing/internal/baggage/Restriction.java
...rtracing/internal/reporters/CompositeReporter.java
...g/tracerresolver/internal/JaegerTracerFactory.java
... and 121 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 3947cbf...5c6d8a5. Read the comment docs.

jpkrohling

Thanks for your contribution! Before we accept it, however, you'd need to sign-off your commit, as part of the "DCO" (https://github.com/probot/dco#how-it-works).

You can do that by running git commit --amend -s and force-pushing the commit (git push --force). This will get this PR updated.

jpkrohling · 2018-06-27T14:14:24Z

jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java

@@ -206,6 +206,11 @@ public synchronized JaegerSpan setTag(String key, Number value) {
  }

  private JaegerSpan setTagAsObject(String key, Object value) {
+    if (finished) {
+      log.warn("Span has already been finished; cannot set tag.", new RuntimeException("Called from:"));


Do you have a sample output for this log message? I'm not sure creating a new exception here (even if not throwing it) is what we want...

I think this is useful otherwise debugging this will be very hard in a large code base.

09:25:12.802 [Test worker] WARN io.jaegertracing.JaegerSpan - Span has already been finished; cannot set tag. java.lang.RuntimeException: Called from: at io.jaegertracing.JaegerSpan.setTagAsObject(JaegerSpan.java:210) at io.jaegertracing.JaegerSpan.setTag(JaegerSpan.java:195) at io.jaegertracing.JaegerSpanTest.testSetStringTagAfterFinish(JaegerSpanTest.java:141) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:106) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58) at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38) at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:66) at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51) at sun.reflect.GeneratedMethodAccessor34.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32) at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93) at com.sun.proxy.$Proxy1.processTestClass(Unknown Source) at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109) at sun.reflect.GeneratedMethodAccessor33.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)

I can, of course, remove the exception. For my use case, providing the stack trace will make it much easier to hunt down these errors.

Exception seems useful, but dual-finish doesn't use it currently, so if we want to have exception, I'd say it should be a tracer config switch to enable it.

If we are making this change for tags, it should also apply for all methods that write to the span, i.e. setOperation, log(), etc.

I do agree that the exception seems useful, but I'd rather have two log entries then. One at warning level, with a message like "Cannot set tag, as the span is already closed. Set log level to debug for information about the caller". Then, the second would be in debug level, wrapped in if (log.isDebugEnabled()) { logger.debug(...); }, with the stack trace.

My concerns are:

Pollute the logs with stack traces

Confuse users into thinking these stack traces are actual exceptions

Wasted resources in collecting the stack trace for every single time the span is closed, as this information is useful only once per caller.

nikron · 2018-06-27T20:37:18Z

Before I actually test the logging (because it's sort of annoying to test that...) does this look good?

yurishkuro

looks reasonable

yurishkuro · 2018-06-27T21:23:51Z

jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java

@@ -536,6 +540,11 @@ public Builder withExpandExceptionLogs() {
      return this;
    }

+    public Builder withLoggingStackTraces() {


LoggingStackTraces name might be confused with some more serious feature. I would rename to withLogStackTraceOnWarnings.

Also add javadoc explaining the option.

yurishkuro · 2018-06-27T21:26:37Z

jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java

+          log.warn("Span has already been finished; cannot log.");
+        }
+        return this;
+      }


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; }

jpkrohling

Other than the concerns I listed regarding adding the stack trace to a warn level, this does LGTM.

yurishkuro · 2018-06-28T17:48:40Z

@jpkrohling suggestion is way better & simpler than mine of doing a custom flag.

nikron · 2018-06-28T22:21:15Z

Changed it to do two lines when debug is on.

yurishkuro · 2018-06-29T05:15:33Z

jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java

@@ -99,6 +99,10 @@ public JaegerTracer getTracer() {
  @Override
  public JaegerSpan setOperationName(String operationName) {
    synchronized (this) {
+      if (spanAlreadyFinished("set baggage item")) {


set operation name

yurishkuro · 2018-06-29T05:16:26Z

jaeger-core/src/main/java/io/jaegertracing/JaegerSpan.java

@@ -132,6 +136,10 @@ public JaegerSpan setBaggageItem(String key, String value) {
      return this;
    }
    synchronized (this) {
+      if (spanAlreadyFinished("set baggage item")) {


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

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

jpkrohling

LGTM. I have a couple of very minor comments and it's up to you to fix them on this PR or not.

Thank you very much for your contribution!

jpkrohling · 2018-06-29T07:46:50Z

jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java

+
+  @Test
+  public void testLogWithTimestampAfterFinish() {
+    Map<String, String> unexpectedFields = new HashMap<String, String>() {


It's cleaner to use Collections.singletonMap("foo", "bar") in this case.

jpkrohling · 2018-06-29T07:49:17Z

jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java

+  @Test
+  public void testNoLoggingingStackTracesOnDebug() {
+    log.setEnabledLevels(Level.WARN);
+    JaegerSpan jaegerSpan = (JaegerSpan)tracer.buildSpan("foo").start();


I just got a PR merged yesterday that makes this cast unnecessary. Could you rebase your PR and check it?

jpkrohling · 2018-06-29T07:49:34Z

jaeger-core/src/test/java/io/jaegertracing/JaegerSpanTest.java

+  @Test
+  public void testLoggingingStackTracesOnDebug() {
+    log.setEnabledLevels(Level.WARN, Level.DEBUG);
+    JaegerSpan jaegerSpan = (JaegerSpan)tracer.buildSpan("foo").start();


Same as the previous comment.

There have to be a few more changes for this to be possible (buildSpan has to return a JaegerTracer.SpanBuilder, and SpanBuilder needs to be public.

I'll make these changes, but I don't know if you want to do that in a separate diff

No no, just rebase to the latest master. Those changes are already there :)

https://github.com/jaegertracing/jaeger-client-java/blob/master/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java#L186

https://github.com/jaegertracing/jaeger-client-java/blob/master/jaeger-core/src/main/java/io/jaegertracing/JaegerTracer.java#L401

Do more logging on debug levels. Signed-off-by: Nikhil Bysani <nikhil.bysani@signifyd.com>

jpkrohling reviewed Jun 27, 2018

View reviewed changes

nikron force-pushed the dont_set_tag_after_finish branch 2 times, most recently from 70b9c76 to 1c66558 Compare June 27, 2018 14:28

yurishkuro reviewed Jun 27, 2018

View reviewed changes

nikron force-pushed the dont_set_tag_after_finish branch 2 times, most recently from c683b7e to 5eb07b0 Compare June 27, 2018 23:15

jpkrohling reviewed Jun 28, 2018

View reviewed changes

yurishkuro reviewed Jun 29, 2018

View reviewed changes

nikron force-pushed the dont_set_tag_after_finish branch from 9640ec7 to c24752e Compare June 29, 2018 05:33

jpkrohling approved these changes Jun 29, 2018

View reviewed changes

After finish, noop set methods.

5c6d8a5

Do more logging on debug levels. Signed-off-by: Nikhil Bysani <nikhil.bysani@signifyd.com>

nikron force-pushed the dont_set_tag_after_finish branch from 53b89dc to 5c6d8a5 Compare June 29, 2018 14:57

yurishkuro closed this in 8ba71a6 Jan 10, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

After finish, disallow setTag. #467

After finish, disallow setTag. #467

nikron commented Jun 27, 2018

codecov bot commented Jun 27, 2018 •

edited

Loading

jpkrohling left a comment

jpkrohling Jun 27, 2018

nikron Jun 27, 2018

nikron Jun 27, 2018

yurishkuro Jun 27, 2018

jpkrohling Jun 28, 2018

nikron commented Jun 27, 2018

yurishkuro left a comment

yurishkuro Jun 27, 2018

yurishkuro Jun 27, 2018

jpkrohling left a comment

yurishkuro commented Jun 28, 2018

nikron commented Jun 28, 2018

yurishkuro Jun 29, 2018

yurishkuro Jun 29, 2018

nikron Jun 29, 2018

jpkrohling left a comment

jpkrohling Jun 29, 2018

jpkrohling Jun 29, 2018

jpkrohling Jun 29, 2018

nikron Jun 29, 2018

jpkrohling Jun 29, 2018 •

edited

Loading

After finish, disallow setTag. #467

After finish, disallow setTag. #467

Conversation

nikron commented Jun 27, 2018

Which problem is this PR solving?

Short description of the changes

codecov bot commented Jun 27, 2018 • edited Loading

Codecov Report

jpkrohling left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nikron commented Jun 27, 2018

yurishkuro left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jpkrohling left a comment

Choose a reason for hiding this comment

yurishkuro commented Jun 28, 2018

nikron commented Jun 28, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jpkrohling left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jpkrohling Jun 29, 2018 • edited Loading

Choose a reason for hiding this comment

codecov bot commented Jun 27, 2018 •

edited

Loading

jpkrohling Jun 29, 2018 •

edited

Loading