Use of Java SDK in conjunction with auto-instrumentation agent - possible agent bug

[rnterbush]

Hi all, I recently had a conversation with @jkwatson on gitter regarding some issues with span contexts, and he suggested I start a discussion here. My issue was with a local app similar to the Http example, but I've reproduced similar behavior with the exact example in the repo.

The gist of the problem is that parent contexts don't get set correctly for spans created using the sdk, when the ot javaagent is attached. This applies to both out of process contexts passed through propagators, and inline contexts passed through makeCurrent() and Context.current().

To document my findings:
Here's output from the client/server without a javaagent attached:

rterbush ~/opentelemetry-java/examples/http $ java -cp ./build/libs/opentelemetry-examples-http-all-0.1.0-SNAPSHOT.jar io.opentelemetry.example.http.HttpClient
Jan 11, 2021 11:15:47 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: / d161d614e97d01a2a1f052a79819c7d6 08a568607ee69dea AttributesMap{data={http.method=GET, component=http, http.url=http://127.0.0.1:8080}, capacity=1000, totalAddedValues=3}
Response Code: 200
Response Msg: Hello World!
Jan 11, 2021 11:15:52 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: / 3ab3f99ec500401780feda07904a2726 ea2689b2bccd26cb AttributesMap{data={http.method=GET, component=http, http.url=http://127.0.0.1:8080}, capacity=1000, totalAddedValues=3}
Response Code: 200
Response Msg: Hello World!

rterbush ~/opentelemetry-java/examples/http $ java -cp ./build/libs/opentelemetry-examples-http-all-0.1.0-SNAPSHOT.jar io.opentelemetry.example.http.HttpServer
Server ready on http://127.0.0.1:8080
Served Client: /127.0.0.1:63199
Jan 11, 2021 11:15:47 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: GET / d161d614e97d01a2a1f052a79819c7d6 bb7357bea35d4191 AttributesMap{data={component=http, http.method=GET, http.scheme=http, http.host=localhost:8080, http.target=/}, capacity=1000, totalAddedValues=5}
Served Client: /127.0.0.1:63200
Jan 11, 2021 11:15:52 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: GET / 3ab3f99ec500401780feda07904a2726 4ef3de8a0f64c30c AttributesMap{data={component=http, http.method=GET, http.scheme=http, http.host=localhost:8080, http.target=/}, capacity=1000, totalAddedValues=5}

And now here is the same scenario with the OT javaagent attached:

rterbush ~/opentelemetry-java/examples/http $ java -javaagent:/Users/rterbush/Downloads/opentelemetry-javaagent-all-0.13.1.jar -cp ./build/libs/opentelemetry-examples-http-all-0.1.0-SNAPSHOT.jar io.opentelemetry.example.http.HttpClient
[opentelemetry.auto.trace 2021-01-11 11:17:13:092 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed span exporter: io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter
[opentelemetry.auto.trace 2021-01-11 11:17:13:100 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed metric exporter: io.opentelemetry.exporter.otlp.metrics.OtlpGrpcMetricExporter
Jan 11, 2021 11:17:13 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: / 93d50eee5b58801a5820f7a853ab7caf 9b17f34824901e8f AttributesMap{data={http.method=GET, component=http, http.url=http://127.0.0.1:8080}, capacity=1000, totalAddedValues=3}
Response Code: 200
Response Msg: Hello World!
Jan 11, 2021 11:17:18 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: / 16c433901c3010e4e37d1dcdff36a7b9 92fc8ef1f84986cb AttributesMap{data={http.method=GET, component=http, http.url=http://127.0.0.1:8080}, capacity=1000, totalAddedValues=3}
Response Code: 200
Response Msg: Hello World!

rterbush ~/opentelemetry-java/examples/http $ java -javaagent:/Users/rterbush/Downloads/opentelemetry-javaagent-all-0.13.1.jar -cp ./build/libs/opentelemetry-examples-http-all-0.1.0-SNAPSHOT.jar io.opentelemetry.example.http.HttpServer
[opentelemetry.auto.trace 2021-01-11 11:17:01:763 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed span exporter: io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter
[opentelemetry.auto.trace 2021-01-11 11:17:01:773 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed metric exporter: io.opentelemetry.exporter.otlp.metrics.OtlpGrpcMetricExporter
Server ready on http://127.0.0.1:8080
Served Client: /127.0.0.1:63210
Jan 11, 2021 11:17:13 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: GET / 0b85c4ab5ecea00a4d2840fb297ce6e3 3bb8d6256c6b586a AttributesMap{data={component=http, http.method=GET, http.scheme=http, http.host=localhost:8080, http.target=/}, capacity=1000, totalAddedValues=5}
Served Client: /127.0.0.1:63212
Jan 11, 2021 11:17:18 AM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: GET / 00508a0b77f0e5aaedc9d524eba0d606 302ab1f01fa120b4 AttributesMap{data={component=http, http.method=GET, http.scheme=http, http.host=localhost:8080, http.target=/}, capacity=1000, totalAddedValues=5}

Notice that the traceIds of the downstream server span don't match the ones exported by the HttpClient application.

The reason I've posted this as a discussion is to ask "Are there APIs that are safe to use in conjunction with the agent vs. ones that are unsafe?" If so, this should probably be well documented, because a use may start with the API and graduate to include the OT agent, which currently make break their API functionality.

[anuraaga]

Hi @rnterbush - the opentelemetry-api artifact methods are safe to use with the agent. However, the version of that artifact has to match 1:1 with the version of the agent you are using. Can you clarify which versions of opentelemetry-api and the agent you are using?

[rnterbush]

I pulled the latest from opentelemetry-java, so I assume the examples are using the 0.13.1 api/sdk. The instrumentation jar i'm adding is the 13.1 compatible version downloaded from https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases

I'm just using the steps in the readme to run the examples, with one small change to HttpServer to get it to compile.

[anuraaga]

Ah sorry now I'm understanding the logging better - so you're saying that there are two applications with different trace IDs. You will need to enable a remote propagator to have the trace ID sent from upstream to downstream, for example -Dotel.propagators=tracecontext. Does that help?

https://github.com/open-telemetry/opentelemetry-java-instrumentation#propagator

[rnterbush]

Adding that option did not change the behavior:

Client:

rterbush ~/opentelemetry-java/examples/http $ java -Dotel.propagators=tracecontext -javaagent:/Users/rterbush/Downloads/opentelemetry-javaagent-all-0.13.1.jar -cp ./build/libs/opentelemetry-examples-http-all-0.1.0-SNAPSHOT.jar io.opentelemetry.example.http.HttpClient
[opentelemetry.auto.trace 2021-01-11 16:42:45:469 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed span exporter: io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter
[opentelemetry.auto.trace 2021-01-11 16:42:45:477 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed metric exporter: io.opentelemetry.exporter.otlp.metrics.OtlpGrpcMetricExporter
[opentelemetry.auto.trace 2021-01-11 16:42:45:516 -0800] [main] INFO io.opentelemetry.javaagent.tooling.PropagatorsInitializer - Added tracecontext propagator
Jan 11, 2021 4:42:46 PM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: / 50f2032a0af9d2475a075496b09ccdfc fbcba56ecd1e6f83 AttributesMap{data={http.method=GET, component=http, http.url=http://127.0.0.1:8080}, capacity=1000, totalAddedValues=3}
Response Code: 200
Response Msg: Hello World!
Jan 11, 2021 4:42:51 PM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: / 0ec07a7d36dc373d4b69d79f155aa3ef 780850d70ca4137e AttributesMap{data={http.method=GET, component=http, http.url=http://127.0.0.1:8080}, capacity=1000, totalAddedValues=3}
Response Code: 200
Response Msg: Hello World!

Server:

rterbush ~/opentelemetry-java/examples/http $ java -Dotel.propagators=tracecontext -javaagent:/Users/rterbush/Downloads/opentelemetry-javaagent-all-0.13.1.jar -cp ./build/libs/opentelemetry-examples-http-all-0.1.0-SNAPSHOT.jar io.opentelemetry.example.http.HttpServer
[opentelemetry.auto.trace 2021-01-11 16:42:34:999 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed span exporter: io.opentelemetry.exporter.otlp.trace.OtlpGrpcSpanExporter
[opentelemetry.auto.trace 2021-01-11 16:42:35:010 -0800] [main] INFO io.opentelemetry.javaagent.tooling.OpenTelemetryInstaller - Installed metric exporter: io.opentelemetry.exporter.otlp.metrics.OtlpGrpcMetricExporter
[opentelemetry.auto.trace 2021-01-11 16:42:35:055 -0800] [main] INFO io.opentelemetry.javaagent.tooling.PropagatorsInitializer - Added tracecontext propagator
Server ready on http://127.0.0.1:8080
Served Client: /127.0.0.1:51110
Jan 11, 2021 4:42:46 PM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: GET / 97ed5d95828f93deb8da2033e9e8fc91 51440e62e1d86117 AttributesMap{data={component=http, http.method=GET, http.scheme=http, http.host=localhost:8080, http.target=/}, capacity=1000, totalAddedValues=5}
Served Client: /127.0.0.1:51112
Jan 11, 2021 4:42:51 PM io.opentelemetry.exporter.logging.LoggingSpanExporter export
INFO: GET / 962ee50f3b1e5b42c4c6a1be8a77feb0 bc5940d568185fbc AttributesMap{data={component=http, http.method=GET, http.scheme=http, http.host=localhost:8080, http.target=/}, capacity=1000, totalAddedValues=5}

[trask]

-Dotel.propagators=tracecontext shouldn't be needed, the default is tracecontext,baggage (https://github.com/open-telemetry/opentelemetry-java-instrumentation#propagator).

@rnterbush can you push your repro to a github repository? I agree with @anuraaga that we think this should be a supported scenario.

[rnterbush]

The logs i've posted are from running the http example in the opentelemetry-java repo here: https://github.com/open-telemetry/opentelemetry-java/tree/master/examples/http . The only modification I made to the code was to line 41 of HttpServer, because it wouldn't compile (changed to new TextMapPropagator.Getter<HttpExchange>() {

The command i use to invoke both the client and server applications are included in the log snippets as the first line. Let me know if you need any other info. As mentioned in a previous comment, the OT javaagent jar is the latest from the instrumentation repo releases page.