Spring Cloud OpenTracing + Elastic APM OpenTracing bridge produces weird traces

[gquintana]

Describe the bug Trying to use Spring Cloud OpenTracing with Elastic APM as OpenTracing backend.

Traces shown in Kibana do not clearly reflect reality.

To Reproduce

Two SpringBoot apps with Spring Cloud OpenTracing and Elastic APM bridge. The esapm-front application calls esapm-back application using a RestTemplate.

Expected behavior

Trace shown in Kibana is:

• esapm-front: EsApmFrontApplication#callHome
• esapm-front: GET localhost
• esapm-front: GET
• esapm-front: GET localhost
• esapm-back: EsApmBackApplication#call
• esapm-back: GET

I would expect something like:

• esapm-front: GET localhost:8080
• esapm-front: EsApmFrontApplication#callHome
• esapm-front: GET localhost:8090
• esapm-back: GET localhost:8090
• esapm-back: EsApmBackApplication#call

Debug logs

Front app

2019-01-14 15:29:32.837 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.3.0 as esapm-front on Java 1.8.0_121 (Oracle Corporation) Windows 7 6.1
2019-01-14 15:29:32.867 [apm-server-healthcheck] INFO co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: {"ok":{"build_date":"2018-12-17T20:15:09Z","build_sha":"fd4f1ac006d8896e4957b6c01fb1e9b9ff04afd7","version":"6.5.4"}}
...
2019-01-14 15:30:19.401 [http-nio-8080-exec-3] WARN co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating a span (00-d919db2c8b0b85f6dc3681d1d00a4475-a8fab9a19ee6698e-01) which is not the currently active span ('EsApmFrontApplication#callHome' 00-d919db2c8b0b85f6dc3681d1d00a4475-a8fab9a19ee6698e-01). This can happen when not properly deactivating a previous span.

Back app

2019-01-14 15:29:22.256 [main] INFO co.elastic.apm.agent.configuration.StartupInfo - Starting Elastic APM 1.3.0 as esapm-back on Java 1.8.0_121 (Oracle Corporation) Windows 7 6.1
2019-01-14 15:29:22.273 [apm-server-healthcheck] INFO co.elastic.apm.agent.report.ApmServerHealthChecker - Elastic APM server is available: {"ok":{"build_date":"2018-12-17T20:15:09Z","build_sha":"fd4f1ac006d8896e4957b6c01fb1e9b9ff04afd7","version":"6.5.4"}}
...
2019-01-14 15:29:48.489 [http-nio-8090-exec-1] WARN co.elastic.apm.agent.impl.ElasticApmTracer - Deactivating a span (00-e18a097ab35c5e124a8137fcf01d4a3e-85c035ad543abca8-01) which is not the currently active span ('EsApmBackApplication#home' 00-e18a097ab35c5e124a8137fcf01d4a3e-85c035ad543abca8-01). This can happen when not properly deactivating a previous span.

[felixbarny]

Hi and thanks for the bug report. Could you upload/link to your test application?

[gquintana]

Sample project: mvn install to build then use esapm-*.sh scripts to run esapm-demo.zip

[gquintana]

Sample trace obtained with this app

[eyalkoren]

@gquintana please explain more about the expected behaviour -

esapm-front: EsApmFrontApplication#callHome
esapm-front: GET localhost
esapm-front: GET
esapm-front: GET localhost
esapm-back: EsApmBackApplication#call
esapm-back: GET

I don't know what to relate some of those to. Is this a behaviour you get with another OpenTracing implementation for this same app?

What I would expect, just from the app code, is to get a Transaction for the entry point at each tier (front and back) and a span for the outgoing HTTP request, so I would expect something like:

esapm-front: EsApmFrontApplication#callHome
esapm-front: GET
esapm-back: EsApmBackApplication#home

What am I missing here?

[gquintana]

@eyalkoren Your expectation are right.

• To have HTTP span (GET localhost) before a code call span (Application#call ), not after. There may be a bug in my code.
• Not to have this stack of HTTP span (GET localhost) in the front application or at least explain why there are so many spans.

[eyalkoren]

@gquintana please set the instrument config option to false (to deactivate automatic agent instrumentation and get only the Spring Cloud OpenTracing stuff). In addition, you will have to use this snapshot: elastic-apm-agent-1.3.1-SNAPSHOT.jar.zip, or wait to next release, as there was a small fix needed to be done in this regard. This is what I get when testing your application with it:

I hope this will produce satisfactory results.

[eyalkoren]

@gquintana I am closing this issue for now. Next version will contain two fixes in this regard. In addition, the requirement is to disable our instrumentation through the configuration described above when relying entirely on OpenTracing APIs. If something still doesn't seem right, please just reopen or let us know otherwise. Thanks for the great input!