Why does Sleuth log a new Span when it isn't sending a request anywhere?

[shalako]

Client --> CF Router --> Sleuth App

Client request:

curl hello-sleuth-semipolitical-codicil.superman.cf-app.com

CF Router generates ids for trace and span and send them to the app in headers:

X-B3-TraceId: f1d33fbe60858c90
X-B3-SpanId: 8b8a69da8590b373

Sleuth App logs

[,f1d33fbe60858c90,c4270b8e465f6fd6,true]

Full log output: https://gist.github.com/shalako/15b63e3969f827bbf5b9e884420a2ec2
A new span suggests the app is sending a request somewhere, no? Ours is not. I would have expected to see the parent span logged, and no new span id generated.

We developed the app to return the following response:

$ curl hello-sleuth-semipolitical-codicil.superman.cf-app.com
current span: [Trace: f1d33fbe60858c90, Span: c4270b8e465f6fd6, exportable=true]
 parents: [8b8a69da8590b373]

This tells us that the app (Sleuth?) is aware of what the parent span is. I just don't know why a new span id is generated by the app.

[marcingrzejszczak]

If you take a look at - http://cloud.spring.io/spring-cloud-sleuth/spring-cloud-sleuth.html - in the picture you can see that...

... your case is that service 2 is CF Router and service 3 is Sleuth App. CF Router creates span D and Sleuth App receives a request with Span D. Then it creates Span E. That span wraps all the logic that will take place in terms of processing a request on the server side. Of course you can create more spans but by default Sleuth creates a new child span once a request is received. Otherwise the whole communication between multiple services would be wrapped in a single span (which makes no sense).

If you turn logs to debug for Sleuth you will see the parent span log too. It's logged in the internals of Sleuth.

This tells us that the app (Sleuth?) is aware of what the parent span is. I just don't know what a new span id is generated by the app.

Why do you need to know the span id of the child span?

[shalako]

To simplify let's say the CF Router is Service 1 and our test Sleuth app is Service 2. If Service 2 will not make any backend requests, why do we need Span C?

Similarly, why does Service 1 create Spans A and B if they are identical? They both represent the request from Service 1 to Service 2, correct?

Is this because Sleuth doesn't know if the app will be making 0, 1, or n backend requests, so it creates a span to represent the parent of all possible backend requests?

What isn't clear from the diagram is whether these extra spans (A, C, E, G), the ones that don't appear to have the {CS,SR,SS,CR} attributes, represent the span to the left or to the right. Does Span A represent the request from client to Service 1, or from Service 1 to Service 2?

Why do you need to know the span id of the child span?

I don't think we do; the fact that there is a child span (C in the diagram?) at all is what has been confusing.

To validate our implementation we want to use logs to correlate that the router sent a span id and the app received it, and that we're sending a Zipkin-compatible header as evidenced by Sleuth knowing what to do with it. The span the router sends is B in the diagram. We have not implemented a Span A, because the router will never send the request to more than one backend. We don't understand why the app logs Span C. We tweaked the app to return the parent span and we see that it treats the span the router sent (B) as a parent span.

Thank you!

[shalako]

Also, how do you configure Sleuth to log in debug mode? Here is our test app: https://github.com/cf-routing/spring-sleuth

Here are the log messages we currently get: https://gist.github.com/shalako/91ad3edf446921cef4166bbf9e152c7e

As you can see, it is not logging the parent span, but the log messages do appear to be debug level.

Thank you for our help; making sure this works with Sleuth in particular is a high priority, but our team has little/no experience with java.

[s4s0l]

try (yml):

logging:
  level:
    org.springframework.cloud.sleuth.log: TRACE

It will log all the start span stop span, continue etc.

For me it is also very confusing...but makes sense when i look at it in zipkin:)

[marcingrzejszczak]

@s4s0l what is confusing? It's normal that libraries log at different levels. Trace is a definite overkill whereas in debug we are logging a lot of stuff for debug purposes.

[marcingrzejszczak]

Ok so let's go back to our picture. There is a mistake in the picture in terms of Service 1 (I'll have to update the picture).

o simplify let's say the CF Router is Service 1 and our test Sleuth app is Service 2. If Service 2 will not make any backend requests, why do we need Span C?

To simplify let's say that the CF Router is Service 2 and our test Sleuth app is Service 3.

Currently in order to sketch a proper diagram of spans in Zipkin you need to have at least one server side span which does not involve an RPC call. That's why when a span is received on the server side (the one annotated with Server Received) a new Span is created. Like I tried to explain it to you a span doesn't have to always explain an RPC call. So it does make sense to create a child server side span (the E span).

Similarly, why does Service 1 create Spans A and B if they are identical?

Why do you think they are identical? Span A is a span on the Server side created when the request came in. Then a new span is created that can wrap a lot of method calls / custom logic, eventually a new span will be created for the RPC call. Why do you assume that those spans are identical?

They both represent the request from Service 1 to Service 2, correct?

No they don't Span A represents an incoming request and response. There should another Span between A and B (like you see in the Service 2 case) so I'll continue talking about the Service 2 situation.

Service 2 has received a request from service 1 (Span B). Server Received is put on the Span B. Span C is created - it's a child span of Span B. In that span you can do plenty of stuff in your code. You can do some logic in the service layer, you can calculate some stuff - whatever you want. Then you decide that inside your logic you need to call Service 3. So a new span is created for the RPC scenario.

What isn't clear from the diagram is whether these extra spans (A, C, E, G), the ones that don't appear to have the {CS,SR,SS,CR} attributes, represent the span to the left or to the right. Does Span A represent the request from client to Service 1, or from Service 1 to Service 2?

I thought that the different colors, span names and location are enough to show where which span belongs :D Let's look at C, E and G. C is a child span of B, it's inside Service 2. E is a child span of D and is inside Service 3. G is a child span of F - it's inside Service 4. You can create spans manually, not every span has to have RPC annotations (CS, SR, SS, CR). If you read the docs and look at the video you will see all of that explained.

I don't think we do; the fact that there is a child span (C in the diagram?) at all is what has been confusing.

You can wrap whatever you need in a span. That span is then represented as a bar in Zipkin. It doesn't have to be an RPC call.

This is taken from the docs:

        // Start a span. If there was a span present in this thread it will become
        // the `newSpan`'s parent.
        Span newSpan = this.tracer.createSpan("calculateTax");
        try {
            // ...
            // You can tag a span
            this.tracer.addTag("taxValue", taxValue);
            // ...
            // You can log an event on a span
            newSpan.logEvent("taxCalculated");
        } finally {
            // Once done remember to close the span. This will allow collecting
            // the span to send it to Zipkin
            this.tracer.close(newSpan);
        }

Let's assume that I wrote this code in Service 2. So this span with the name calculateTax would be a child span of span C.

If here

this.tracer.addTag("taxValue", taxValue);
            // ...
            // You can log an event on a span
            newSpan.logEvent("taxCalculated");

I'd make a rest call to Service 3 then the Spans would look like this

Service1 -> Service 2 (Span B) -> Service 2 (Span C) -> Service 2 (Span calculateTax) -> Service 2 (Span D)

To validate our implementation we want to use logs to correlate that the router sent a span id and the app received it, and that we're sending a Zipkin-compatible header as evidenced by Sleuth knowing what to do with it. The span the router sends is B in the diagram. We have not implemented a Span A, because the router will never send the request to more than one backend. We don't understand why the app logs Span C. We tweaked the app to return the parent span and we see that it treats the span the router sent (B) as a parent span.

If everything in the router is wrapped in a span and then you send a request to Sleuth and put the tracing headers in that request then it's ok. We wanted to differentiate the RPC (Span B) from request processing (SPan C).

Also, how do you configure Sleuth to log in debug mode? Here is our test app: https://github.com/cf-routing/spring-sleuth

Like any library you can set the properties of logging. You can read more here http://docs.spring.io/spring-boot/docs/current/reference/html/howto-logging.html . For Sleuth you can just type

logging:
  level:
    org.springframework.cloud.sleuth.log: DEBUG

As you can see, it is not logging the parent span, but the log messages do appear to be debug level.

Why do you want to log the parent span? By default we don't log it. As I've mentioned previously you can log that yourself if you need it. You can also tweak the Logging pattern to log that (by default Sleuth doesn't do it cause it's not necessary).

Thank you for our help; making sure this works with Sleuth in particular is a high priority, but our team has little/no experience with java.

No problem that's what we're for :)

[shalako]

This helps a ton. Most of this did not come across in the docs or the diagram. We've been thinking of spans only as RPC calls.

From docs:

The initial span that starts a trace is called a root span. The value of span id of that span is equal to trace id.

How should the CF Router know if it is initiating the root span with an RPC call to an app? If the request received by the router does not include X-B3-TraceId, we can send trace and span with equal values. But what if the request includes X-B3-TraceId but not X-B3-SpanId? If the router receives a trace, should we assume the root span was upstream?

[codefromthecrypt]

The initial span that starts a trace is called a root span. The value of span id of that span is equal to trace id.

side note particularly for marcin: this is true for sleuth, and a lot of zipkin systems, but isn't true for all zipkin systems (ex isn't true for htrace). It also won't be true in the future. Ex. "The root span has no parent" is a definition that will be true even after trace ids are 128bit. If there's any logic that requires span id as a trace id, we should fix that.

How should the CF Router know if it is initiating the root span with an RPC call to an app? If the request received by the router does not include X-B3-TraceId, we can send trace and span with equal values. But what if the request includes X-B3-TraceId but not X-B3-SpanId? If the router receives a trace, should we assume the root span was upstream?

X-B3-TraceId must be present with X-B3-SpanId to affect the trace identifiers. If they aren't specified together, whichever is present will be ignored and a new trace and span id will be provisioned. Added this to follow up openzipkin/b3-propagation#3

[shalako]

So when the CF Router is initiating the trace (request does not include trace and span ids), it should send different values for X-B3-TraceId and X-B3-SpanId? This is what we have implemented, so no change needed.

We will update the CF Router to initiate a new trace if it receives a request containing either trace or span but not both.

[codefromthecrypt]

@shalako small clarification is that the trace id is usually the same as the span id. IOTW, they aren't required to be different, but being different is fine.

your plan sounds good. FYI I'm adding some notes to openzipkin/b3-propagation#4 which you'll likely be interested in.

[shalako]

So when CF Router initiates the trace (request does not include trace and span), if the ids it generates for trace and span were the same, that would be more conventional?

[codefromthecrypt]

@shalako yeah conventionally they are the same. Even when we do 128bit ids, we'll likely have the lower 64 bits of the trace id as the root span id.

[marcingrzejszczak]

Can we close this?

[raouldh]

@marcingrzejszczak
Is you explanation in this issue still valid for spring-cloud-sleuth 2.x?
We are currently adding sleuth to our projects and are noticing that not all the Span's drawn in the image on http://cloud.spring.io/spring-cloud-sleuth/spring-cloud-sleuth.html
are being created. It looks like the Spans C, E and G from the image in the documentation are not there(in the log).

I took the example https://github.com/spring-cloud/spring-cloud-sleuth/tree/master/spring-cloud-sleuth-samples/spring-cloud-sleuth-sample-zipkin and ran it for the 1.0.5.RELEASE and 2.0.1.RELEASE versions with the logging for org.springframework.cloud.sleuth.log set to TRACE.
The 1.0.5.RELEASE seems to create Span's for the C, E and G like displayed in the documentation where the 2.0.1.RELEASE version does not.
When counting the different Span's in the log after calling the http://localhost:3380/ the 1.0.5.RELEASE has 4 different Span's where the 2.0.1.RELEASE has only two.

Question: Is the documentation still up to date or is this a bug?

Logging from 1.0.5.RELEASE when calling http://localhost:3380

2018-12-04 08:03:43.727 TRACE [testsleuthzipkin,5fb18c462120e410,5fb18c462120e410,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Starting span: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:43.727 TRACE [testsleuthzipkin,5fb18c462120e410,5fb18c462120e410,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:43.735 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Starting span: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:43.735 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:43.735 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:44.009  INFO [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] sample.SampleController                  : Home page
2018-12-04 08:03:44.009 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Starting span: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:44.009 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:44.010 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:44.011 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:44.011 TRACE [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Starting span: [Trace: 5fb18c462120e410, Span: dc3b82c1752cfff, Parent: 4de58fda720ddbb2, exportable:true]
2018-12-04 08:03:44.011 TRACE [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:44.011 TRACE [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 5fb18c462120e410, Span: dc3b82c1752cfff, Parent: 4de58fda720ddbb2, exportable:true]
2018-12-04 08:03:44.011  INFO [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] sample.SampleController                  : hi2
2018-12-04 08:03:45.010  INFO [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] sample.SampleZipkinApplication           : Reporting span [{"traceId":"5fb18c462120e410","name":"hi2","id":"0dc3b82c1752cfff","parentId":"4de58fda720ddbb2","timestamp":1543907024011000,"duration":995922,"annotations":[],"binaryAnnotations":[{"key":"lc","value":"unknown","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"mvc.controller.class","value":"SampleController","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"mvc.controller.method","value":"hi2","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"random-sleep-millis","value":"992","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}}]}]
2018-12-04 08:03:45.010 TRACE [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: dc3b82c1752cfff, Parent: 4de58fda720ddbb2, exportable:true]
2018-12-04 08:03:45.010 TRACE [testsleuthzipkin,5fb18c462120e410,dc3b82c1752cfff,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:45.015 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:45.015  INFO [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-5] sample.SampleZipkinApplication           : Reporting span [{"traceId":"5fb18c462120e410","name":"http:/hi2","id":"4de58fda720ddbb2","parentId":"3c6302786706d44c","timestamp":1543907024009000,"duration":1000000,"annotations":[{"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380},"timestamp":1543907024010000,"value":"cs"},{"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380},"timestamp":1543907025010000,"value":"cr"}],"binaryAnnotations":[{"key":"http.host","value":"localhost","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"http.method","value":"GET","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"http.path","value":"/hi2","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"http.url","value":"http://localhost:3380/hi2","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"sa","value":true,"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}}]}]
2018-12-04 08:03:45.015 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:45.015 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: 4de58fda720ddbb2, Parent: 3c6302786706d44c, exportable:true]
2018-12-04 08:03:45.015 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:45.015 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:45.015 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:45.016  INFO [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-6] sample.SampleZipkinApplication           : Reporting span [{"traceId":"5fb18c462120e410","name":"http:/hi2","id":"4de58fda720ddbb2","parentId":"3c6302786706d44c","timestamp":1543907024011000,"duration":1001035,"annotations":[{"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380},"timestamp":1543907024011000,"value":"sr"},{"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380},"timestamp":1543907025015000,"value":"ss"}],"binaryAnnotations":[]}]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,5fb18c462120e410,4de58fda720ddbb2,true] 22008 --- [nio-3380-exec-6] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: null
2018-12-04 08:03:45.017  INFO [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] sample.SampleZipkinApplication           : Reporting span [{"traceId":"5fb18c462120e410","name":"hi","id":"3c6302786706d44c","parentId":"5fb18c462120e410","timestamp":1543907023735000,"duration":1284112,"annotations":[],"binaryAnnotations":[{"key":"lc","value":"unknown","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"mvc.controller.class","value":"SampleController","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}},{"key":"mvc.controller.method","value":"hi","endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380}}]}]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: 3c6302786706d44c, Parent: 5fb18c462120e410, exportable:true]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,5fb18c462120e410,3c6302786706d44c,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,5fb18c462120e410,5fb18c462120e410,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,5fb18c462120e410,5fb18c462120e410,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:45.017  INFO [testsleuthzipkin,5fb18c462120e410,5fb18c462120e410,true] 22008 --- [nio-3380-exec-5] sample.SampleZipkinApplication           : Reporting span [{"traceId":"5fb18c462120e410","name":"http:/","id":"5fb18c462120e410","timestamp":1543907023727000,"duration":1287687,"annotations":[{"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380},"timestamp":1543907023727000,"value":"sr"},{"endpoint":{"serviceName":"testsleuthzipkin","ipv4":"127.0.0.1","port":3380},"timestamp":1543907025017000,"value":"ss"}],"binaryAnnotations":[]}]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,5fb18c462120e410,5fb18c462120e410,true] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 5fb18c462120e410, Span: 5fb18c462120e410, Parent: null, exportable:true]
2018-12-04 08:03:45.017 TRACE [testsleuthzipkin,,,] 22008 --- [nio-3380-exec-5] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: null
2018-12-04 08:03:45.027 TRACE [testsleuthzipkin,20279866b42fe23d,20279866b42fe23d,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Starting span: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.027 TRACE [testsleuthzipkin,20279866b42fe23d,20279866b42fe23d,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,856e78cc9efd9f29,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Starting span: [Trace: 20279866b42fe23d, Span: 856e78cc9efd9f29, Parent: 20279866b42fe23d, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,856e78cc9efd9f29,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,856e78cc9efd9f29,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Continued span: [Trace: 20279866b42fe23d, Span: 856e78cc9efd9f29, Parent: 20279866b42fe23d, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,856e78cc9efd9f29,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 20279866b42fe23d, Span: 856e78cc9efd9f29, Parent: 20279866b42fe23d, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,856e78cc9efd9f29,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,20279866b42fe23d,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,20279866b42fe23d,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : With parent: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,20279866b42fe23d,20279866b42fe23d,false] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: [Trace: 20279866b42fe23d, Span: 20279866b42fe23d, Parent: null, exportable:false]
2018-12-04 08:03:45.044 TRACE [testsleuthzipkin,,,] 22008 --- [nio-3380-exec-8] o.s.cloud.sleuth.log.Slf4jSpanLogger     : Stopped span: null

Logging from 2.0.1.RELEASE when calling http://localhost:3380

2018-12-04 07:48:31.410 TRACE [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/ea1b631414f2451d
2018-12-04 07:48:31.410 TRACE [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/ea1b631414f2451d
2018-12-04 07:48:31.410 TRACE [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/ea1b631414f2451d
2018-12-04 07:48:32.264  INFO [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] sample.SampleController                  : Home page
2018-12-04 07:48:32.294 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.294 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: -1577558306561309411
2018-12-04 07:48:32.294 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.294 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.294 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: -1577558306561309411
2018-12-04 07:48:32.311 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.311 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: -1577558306561309411
2018-12-04 07:48:32.311 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.311 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.311 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: -1577558306561309411
2018-12-04 07:48:32.311  INFO [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] sample.SampleController                  : hi2
2018-12-04 07:48:32.460 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.460 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.463 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: -1577558306561309411
2018-12-04 07:48:32.464 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.465 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.465 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.465 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : With parent: -1577558306561309411
2018-12-04 07:48:32.465 TRACE [testsleuthzipkin,ea1b631414f2451d,d3a1f93e29a7e5d0,true] 18992 --- [nio-3380-exec-2] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/d3a1f93e29a7e5d0
2018-12-04 07:48:32.477 TRACE [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/ea1b631414f2451d
2018-12-04 07:48:32.477 TRACE [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Starting scope for span: ea1b631414f2451d/ea1b631414f2451d
2018-12-04 07:48:32.477 TRACE [testsleuthzipkin,ea1b631414f2451d,ea1b631414f2451d,true] 18992 --- [nio-3380-exec-1] o.s.c.sleuth.log.Slf4jScopeDecorator     : Closing scope for span: ea1b631414f2451d/ea1b631414f2451d

[marcingrzejszczak]

I have to provide more detailed explanation of the image. Those additional spans are manually created spans for some operations. Like as if someone created one by hand.

[meetDeveloper]

@marcingrzejszczak Can you explain this There should another Span between A and B (like you see in the Service 2 case). When suppose a request comes, it has some span. Why does server not use that Span, it in current case creates another Span A, when it sends request to some one, it creates Span B, the server that receives that request creates Span C. Why are we giving request extra span. Why does Span B exist?

--Initial Request-> [Service (Span A)] ---Request(Span B)----->[Service(Span C)]

[marcingrzejszczak]

We create a new span for an rpc call. However we typically try to continue a span as much as possible.

[meetDeveloper]

@marcingrzejszczak Isn't the Service 1 in above diagram wrong?

[marcingrzejszczak]

No. Service 1 is fine, in Service 2, 3 and 4 I assumed that Spans C, E, G were created manually.

[meetDeveloper]

Isn't Span A also created manually, to wrap all the logic that will take place in terms of processing a request on the server side.

[marcingrzejszczak]

No

[meetDeveloper]

But Request to Service 1 did not had any span.

[marcingrzejszczak]

It didn't so Sleuth created a new root span (root meaning that span id is equal to trace id).

This issue is getting extremely chatty, please move this discussion to gitter https://gitter.im/spring-cloud/spring-cloud-sleuth