ZipkinSpanReporter is not working properly

Question

i am trying to evaluate zipkin to enable distributed tracing capability for all our micro-service. Below are versions in my setup.

1. Spring-boot version: 1.5.7.RELEASE

2. spring-cloud version: Camden.SR6

3. zipkin version : 2.2.1

   Configuration for seluth in application.properties

spring.sleuth.sampler.percentage=1.0

spring.sleuth.web.skipPattern=(^cleanup.|.+favicon.)

And i created the ZipkinSpanReporter bean as below. Note that I have setup the Eureka server as all micro services and even zipkin server registerred with Eureka server so that the Zipkin client can resolve zipkin server via eureka

 @Bean
    public ZipkinSpanReporter makeZipkinSpanReporter() {
        return new ZipkinSpanReporter() {
            private HttpZipkinSpanReporter delegate;
            private String baseUrl;

            @Override
            public void report(Span span) {

                InstanceInfo instance = eurekaClient
                        .getNextServerFromEureka("zipkin", false);
                if (!(baseUrl != null &&
                        instance.getHomePageUrl().equals(baseUrl))) {
                    baseUrl = instance.getHomePageUrl();
                    delegate = new HttpZipkinSpanReporter(baseUrl,
                            zipkinProperties.getFlushInterval(),
                            zipkinProperties.getCompression().isEnabled(),
                            spanMetricReporter);

                    if (!span.name.matches(skipPattern)) delegate.report(span);
                }
            }
        };
    }

What I have observered is that the zipkin client (book) is not reporting all spans back to zipkin server when I checked the zipkin. Some are reported, almost of spans are dropped

I have enabled the logging for

logging.level.org.springframework.cloud.sleuth.instrument.web=DEBUG
logging.file=book.log

below are logging info:

2017-10-30 12:51:41.747 DEBUG [book,73fdabf29eb273f2,73fdabf29eb273f2,true] 14088 --- [http-nio-8888-exec-1] o.s.c.sleuth.instrument.web.TraceFilter  : No parent span present - creating a new span
2017-10-30 12:51:41.749 DEBUG [book,73fdabf29eb273f2,73fdabf29eb273f2,true] 14088 --- [http-nio-8888-exec-1] o.s.c.s.i.web.TraceHandlerInterceptor    : Handling span [Trace: 73fdabf29eb273f2, Span: 73fdabf29eb273f2, Parent: null, exportable:true]
2017-10-30 12:51:41.750 DEBUG [book,73fdabf29eb273f2,73fdabf29eb273f2,true] 14088 --- [http-nio-8888-exec-1] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a method tag with value [checkedOut] to a span [Trace: 73fdabf29eb273f2, Span: 73fdabf29eb273f2, Parent: null, exportable:true]
2017-10-30 12:51:41.750 DEBUG [book,73fdabf29eb273f2,73fdabf29eb273f2,true] 14088 --- [http-nio-8888-exec-1] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a class tag with value [BookApplication] to a span [Trace: 73fdabf29eb273f2, Span: 73fdabf29eb273f2, Parent: null, exportable:true]
2017-10-30 12:51:41.752 DEBUG [book,73fdabf29eb273f2,73fdabf29eb273f2,true] 14088 --- [http-nio-8888-exec-1] o.s.c.sleuth.instrument.web.TraceFilter  : Closing the span [Trace: 73fdabf29eb273f2, Span: 73fdabf29eb273f2, Parent: null, exportable:true] since the response was successful
2017-10-30 12:51:42.133 DEBUG [book,,,] 14088 --- [http-nio-8888-exec-1] o.s.c.sleuth.instrument.web.TraceFilter  : Received a request to uri [/favicon.ico] that should not be sampled [true]
2017-10-30 12:51:42.134 DEBUG [book,9e7aab2fdb2313a9,9e7aab2fdb2313a9,false] 14088 --- [http-nio-8888-exec-1] o.s.c.sleuth.instrument.web.TraceFilter  : No parent span present - creating a new span
2017-10-30 12:51:42.142 DEBUG [book,9e7aab2fdb2313a9,9e7aab2fdb2313a9,false] 14088 --- [http-nio-8888-exec-1] o.s.c.sleuth.instrument.web.TraceFilter  : Closing the span [Trace: 9e7aab2fdb2313a9, Span: 9e7aab2fdb2313a9, Parent: null, exportable:false] since the response was successful
2017-10-30 12:52:05.167 DEBUG [book,,,] 14088 --- [http-nio-8888-exec-2] o.s.c.sleuth.instrument.web.TraceFilter  : Received a request to uri [/checked-out] that should not be sampled [false]
2017-10-30 12:52:05.168 DEBUG [book,05274e0bdf3038b9,05274e0bdf3038b9,true] 14088 --- [http-nio-8888-exec-2] o.s.c.sleuth.instrument.web.TraceFilter  : No parent span present - creating a new span
2017-10-30 12:52:05.171 DEBUG [book,05274e0bdf3038b9,05274e0bdf3038b9,true] 14088 --- [http-nio-8888-exec-2] o.s.c.s.i.web.TraceHandlerInterceptor    : Handling span [Trace: 05274e0bdf3038b9, Span: 05274e0bdf3038b9, Parent: null, exportable:true]
2017-10-30 12:52:05.171 DEBUG [book,05274e0bdf3038b9,05274e0bdf3038b9,true] 14088 --- [http-nio-8888-exec-2] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a method tag with value [checkedOut] to a span [Trace: 05274e0bdf3038b9, Span: 05274e0bdf3038b9, Parent: null, exportable:true]
2017-10-30 12:52:05.172 DEBUG [book,05274e0bdf3038b9,05274e0bdf3038b9,true] 14088 --- [http-nio-8888-exec-2] o.s.c.s.i.web.TraceHandlerInterceptor    : Adding a class tag with value [BookApplication] to a span [Trace: 05274e0bdf3038b9, Span: 05274e0bdf3038b9, Parent: null, exportable:true]
2017-10-30 12:52:05.174 DEBUG [book,05274e0bdf3038b9,05274e0bdf3038b9,true] 14088 --- [http-nio-8888-exec-2] o.s.c.sleuth.instrument.web.TraceFilter  : Closing the span [Trace: 05274e0bdf3038b9, Span: 05274e0bdf3038b9, Parent: null, exportable:true] since the response was successful
2017-10-30 12:52:05.589 DEBUG [book,,,] 14088 --- [http-nio-8888-exec-2] o.s.c.sleuth.instrument.web.TraceFilter  : Received a request to uri [/favicon.ico] that should not be sampled [true]
2017-10-30 12:52:05.589 DEBUG [book,b891d03ce6bccdf4,b891d03ce6bccdf4,false] 14088 --- [http-nio-8888-exec-2] o.s.c.sleuth.instrument.web.TraceFilter  : No parent span present - creating a new span
2017-10-30 12:52:05.594 DEBUG [book,b891d03ce6bccdf4,b891d03ce6bccdf4,false] 14088 --- [http-nio-8888-exec-2] o.s.c.sleuth.instrument.web.TraceFilter  : Closing the span [Trace: b891d03ce6bccdf4, Span: b891d03ce6bccdf4, Parent: null, exportable:false] since the response was successful

But I could not be able to find the traceId which is logged in book.log file from zipkin console

Could you please explain why many spans are not reported to zipkin server?

Thanks in advance.

Answer 1

Most likely your code is broken. You can check out the https://github.com/spring-cloud/spring-cloud-sleuth/blob/master/spring-cloud-sleuth-zipkin/src/main/java/org/springframework/cloud/sleuth/zipkin/ZipkinAutoConfiguration.java class where for Edgware we've added load balanced zipkin server resolution.

Answer 2

Is it correct that you are using the code example from the baeldung tutorial? (http://www.baeldung.com/tracing-services-with-zipkin - 3.2. Spring Config)

I think there is a mistake with line 34 and 35 (the closing curly brace).

I've fixed the problem by modifing the method like this:

@Bean
public ZipkinSpanReporter makeZipkinSpanReporter() {
    return new ZipkinSpanReporter() {
        private HttpZipkinSpanReporter delegate;
        private String baseUrl;

        @Override
        public void report(Span span) {

            InstanceInfo instance = eurekaClient
                    .getNextServerFromEureka("zipkin", false);
            if (!(baseUrl != null &&
                    instance.getHomePageUrl().equals(baseUrl))) {
                baseUrl = instance.getHomePageUrl();
                RestTemplate restTemplate = new RestTemplate();
                zipkinRestTemplateCustomizer.customize(restTemplate);
                delegate = new HttpZipkinSpanReporter(
                        restTemplate,
                        baseUrl,
                        zipkinProperties.getFlushInterval(),
                        spanMetricReporter);
            }

            if (!span.name.matches(skipPattern)) {
                delegate.report(span);
            }
        }
    };
}

Maybe this helps someone or maybe someone from baeldung reads this and could verify and correct the code example. ;)