When a span is created using @NewSpan, timestamp and duration are not sent

Question

I am using Spring Cloud Sleuth and Zipkin (via HTTP), by adding spring-cloud-starter-zipkin version 2.0.0.M6 to my dependencies (based on Spring Boot 2.0.0.RC1 and Spring Cloud Finchley M6).

I am using @Newspan annotation to mark a child span around some (expensive) operation. When the span information is sent to Zipkin, I notice that the timestamp and duration of the child span are missing. This leads to a strange rendering on Zipking side. However, when I create the child span by calling tracer#newChild, it works as expected.

Am I missing something? Would this be an issue with Sleuth 2.0.0.M6?

When I run the same code using Spring Boot 1.5.9 and Spring Cloud Edgware SR2, it behaves as expected.

Here's the JSON received on Zipkin side. The span named "child-span-with-annotation" is the one created using @NewSpan, whereas the span "childspanwithnewchild" is created using tracer#newChild.

[
  {
    "traceId": "b1c2636366c919be",
    "id": "b1c2636366c919be",
    "name": "get",
    "timestamp": 1518495271073166,
    "duration": 862032,
    "annotations": [
      {
        "timestamp": 1518495271073166,
        "value": "sr",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      },
      {
        "timestamp": 1518495271935198,
        "value": "ss",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      }
    ],
    "binaryAnnotations": [
      {
        "key": "ca",
        "value": true,
        "endpoint": {
          "serviceName": "",
          "ipv6": "::1",
          "port": 51982
        }
      },
      {
        "key": "http.path",
        "value": "/hello",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      },
      {
        "key": "mvc.controller.class",
        "value": "MyRestController",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      },
      {
        "key": "mvc.controller.method",
        "value": "sayHello",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      }
    ]
  },
  {
    "traceId": "b1c2636366c919be",
    "id": "14be7ac6eafb0e01",
    "name": "child-span-with-annotation",
    "parentId": "b1c2636366c919be",
    "binaryAnnotations": [
      {
        "key": "class",
        "value": "MyService",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      },
      {
        "key": "method",
        "value": "expensiveOperation1",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      }
    ]
  },
  {
    "traceId": "b1c2636366c919be",
    "id": "b34a4f910f27fdb4",
    "name": "childspanwithnewchild",
    "parentId": "b1c2636366c919be",
    "timestamp": 1518495271479040,
    "duration": 453747,
    "binaryAnnotations": [
      {
        "key": "lc",
        "value": "",
        "endpoint": {
          "serviceName": "sample-sleuth-app",
          "ipv4": "---.---.---.---"
        }
      }
    ]
  }
]

Marcin Grzejszczak Marcin Grzejszczak · Accepted Answer · 2018-02-13T09:15:18

It's a bug - https://github.com/spring-cloud/spring-cloud-sleuth/issues/855 . I've fixed it ATM. A workaround is to start it manually either in each method that uses @NewSpan by calling start() method on current span (that doesn't scale too nicely)

@Autowired SpanCustomizer customizer;

@NewSpan
void foo() {
    this.customizer.start();
}

You can also create a bean of SpanCreator (you can check the fixed version here https://github.com/spring-cloud/spring-cloud-sleuth/blob/master/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/annotation/DefaultSpanCreator.java)

class MySpanCreator implements SpanCreator {

    private static final Log log = LogFactory.getLog(MySpanCreator.class);

    private final Tracing tracer;

    MySpanCreator(Tracing tracer) {
        this.tracer = tracer;
    }

    @Override public Span createSpan(MethodInvocation pjp, NewSpan newSpanAnnotation) {
        String name = StringUtils.isEmpty(newSpanAnnotation.name()) ?
                pjp.getMethod().getName() : newSpanAnnotation.name();
        String changedName = SpanNameUtil.toLowerHyphen(name);
        if (log.isDebugEnabled()) {
            log.debug("For the class [" + pjp.getThis().getClass() + "] method "
                    + "[" + pjp.getMethod().getName() + "] will name the span [" + changedName + "]");
        }
        return this.tracer.tracer().nextSpan().name(changedName).start();
    }

}

Notice the .start() at the end of the method.

When a span is created using @NewSpan, timestamp and duration are not sent

1 Answers