Spring-cloud-sleuth: @NewSpan annotation doesn't work

[zavale]

I have a problem with @NewSpan doesn't generate new span and as a result is not reported to Zipkin server. Explicit spans, created not by annotation, are successfully generated and reported. For reproducing the problem, please run attached Maven project. The project is based on a Maven project generated by https://start.spring.io/, with just a few components - Web, Sleuth and Zipkin client.

For reproducing, hit the endpoint http://localhost:8080/test
The simple Controller should generate the implicit trace with a custom span, but custom span is not generated - observed in the logs, and also on the locally running Zipkin server.

Few suspicious log generated during the application start are:

objc[48907]: Class JavaLaunchHelper is implemented in both /Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/bin/java (0x1097344c0) and /Library/Java/JavaVirtualMachines/jdk1.8.0_101.jdk/Contents/Home/jre/lib/libinstrument.dylib (0x10b7b64e0). One of the two will be used. Which one is undefined.
2017-06-16 18:00:48.608  INFO [bootstrap,,,] 48907 --- [           main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@36f0f1be: startup date [Fri Jun 16 18:00:48 PDT 2017]; root of context hierarchy
2017-06-16 18:00:48.785  INFO [bootstrap,,,] 48907 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'configurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$b19b06da] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
 :: Spring Boot ::        (v1.5.4.RELEASE)

2017-06-16 18:00:53.994  INFO [Demo,,,] 48907 --- [           main] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2017-06-16 18:00:54.005  INFO [Demo,,,] 48907 --- [           main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot.context.embedded.AnnotationConfigEmbeddedWebApplicationContext@404bbcbd: startup date [Fri Jun 16 18:00:54 PDT 2017]; parent: org.springframework.context.annotation.AnnotationConfigApplicationContext@36f0f1be
2017-06-16 18:00:54.407  INFO [Demo,,,] 48907 --- [           main] o.s.cloud.context.scope.GenericScope     : BeanFactory id=3e015390-8e57-32f2-b31c-06909b5945fd
2017-06-16 18:00:54.498  INFO [Demo,,,] 48907 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.sleuth.annotation.SleuthAnnotationAutoConfiguration' of type [org.springframework.cloud.sleuth.annotation.SleuthAnnotationAutoConfiguration$$EnhancerBySpringCGLIB$$97e64a0f] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2017-06-16 18:00:54.671  INFO [Demo,,,] 48907 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'sleuthAdvisorConfig' of type [org.springframework.cloud.sleuth.annotation.SleuthAdvisorConfig] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2017-06-16 18:00:54.673  INFO [Demo,,,] 48907 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration' of type [org.springframework.cloud.autoconfigure.ConfigurationPropertiesRebinderAutoConfiguration$$EnhancerBySpringCGLIB$$b19b06da] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

Where beans related to sleuth reported as not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)

demo-no_annotations_working.zip

[marcingrzejszczak]

Hi! Thanks for the issue. Could you please upload the sample to Github as a project? Thanks

[zavale]

@marcingrzejszczak You may import Maven project from https://github.com/zavale/spring-cloud-sleuth-NewSpan-annotation-defect Please note, Zipkin server is supposed to run on http://localhost:9411/ but even if it doesn't run there, you will be able to see the @NewSpan annotation being ignored from Sleuth debug logs.

[marcingrzejszczak]

It's not working cause you need to put the annotated method in a separate class. We're creating a proxy of the object so if you're calling a proxied method from the proxy itself then the method will be called directly without going through the proxy logic. I'll try to update the docs with that warning

[zavale]

@marcingrzejszczak I moved annotated method to the separate class, and it's still not working for me. I pushed the modification to https://github.com/zavale/spring-cloud-sleuth-NewSpan-annotation-defect master. The span from the annotation is not created - I cannot observe it, neither in the Sleuth debug logs or Zipkin traces. Could you please take a look?

[marcingrzejszczak]

Of course it's not working - you need to register it as a bean. That's how proxies work in Spring. Just annotate it with @Component

[zavale]

@marcingrzejszczak Thanks for the response - I added @Component annotation to

@Component
public
class SpanTest {

    @NewSpan
    public void spanTest() {
        for (int i=0; i<100000000; i++);
    }
}

Pushed to master here: https://github.com/zavale/spring-cloud-sleuth-NewSpan-annotation-defect

But span still doesn't appear in the trace - not in the logs, and not on the locally running Zipkin. Could you please refer me to the working code sample?

[marcingrzejszczak]

There you go https://github.com/spring-cloud-samples/sleuth-documentation-apps/blob/master/service1/src/main/java/io/spring/cloud/sleuth/docs/service1/Service2Client.java

[zavale]

@marcingrzejszczak Thanks for the reference, looking there, I managed to make my example working. Just wanted to summarize my understanding of how to make @NewSpan annotation working, and limitations that it imposes

1. To create Span for a method foo, using @NewSpan annotation, a class ClassOfFoo that method foo belongs to, has to be declared as Bean.

2. That means, that ClassOfFoo is a singleton - no dynamic instantiation, no multiple instances

3. Spans a created, only when method foo is called outside of ClassOfFoo.

4. That means that if method foo calls to method fooInternal, which also declared with @NewSpan annotation in a class ClassOfFoo, no span will be created for *fooInternal.

Could you please clarify that my understanding is correct.
I actually, tested that in a code, but want to make sure that I am not missing anything.

Thanks again!

[Koizumi85]

Hi @zavale.

your understanding is correct, with one single exception. Making a bean of ClassOfFoo not necessarily means, that there can't be multiple instances. There are ways to create beans for every Web-Request or for every Session for example using the scopes "request" or "session". Also with "prototype" scope, there can be any number of instances for a specific bean type. Please refer to the reference documentation of the spring framework (here).

[marcingrzejszczak]

@koizumi85 speaks the truth :) case closed :D

[zavale]

@marcingrzejszczak @Koizumi85 Thanks for the help.
Do you have any roadmap for making @NewSpan more generic?

I think that the limitation of "no spans generated" when methods of the same class call each other significantly reduces the usability.

[marcingrzejszczak]

It's not the limitation of Sleuth - it's how proxies work in Spring. You can file an issue in Spring if you want to change this approach.

As for the usability, I completely don't agree but I guess it's a matter of preference discussion.

[Koizumi85]

@zavale
I have to agree to everything @marcingrzejszczak said. This is the way EVERY annotation in spring works (@Cacheable, @Transactional, @Async, ...)

Also I have to say, that I am wondering how you are using Sleuth, if this behaviour is such a great limitation to you. Sleuth is about tracing distributed systems. So you would create spans if you leave/enter a specific system. For example if you call another microservice, a database or a third-party service. And usually for such calls, you would have a class only doing this specific stuff.
So if this limitation is making you trouble, you probably should rethink your architecture. Possibly your classes are doing to much stuff.

[zavale]

@marcingrzejszczak @Koizumi85 Thanks