java-agent-based instrumentation plus manual instrumentation creates 2 different trace contexts

[magicliang]

I met an issue that when I combined java-agent-based instrumentation to manual instrumentation, then got 2 different traces, I don't know how this happens.

I have a play app which has dependency like this:

val tracingDependencies = Seq(
  // https://mvnrepository.com/artifact/io.opentelemetry/opentelemetry-bom
  //  libraryDependencies += "io.opentelemetry" % "opentelemetry-bom" % "1.14.0" pomOnly(),

  // https://mvnrepository.com/artifact/io.opentelemetry/opentelemetry-sdk
  libraryDependencies += "io.opentelemetry" % "opentelemetry-sdk" % "1.14.0",
  libraryDependencies += "io.opentelemetry" % "opentelemetry-sdk-trace" % "1.14.0",
  libraryDependencies += "io.opentelemetry" % "opentelemetry-api" % "1.14.0",

  // https://mvnrepository.com/artifact/io.opentelemetry/opentelemetry-exporter-otlp
  libraryDependencies += "io.opentelemetry" % "opentelemetry-exporter-otlp" % "1.14.0",
  // https://mvnrepository.com/artifact/io.opentelemetry/opentelemetry-exporter-logging-otlp
  libraryDependencies += "io.opentelemetry" % "opentelemetry-exporter-logging-otlp" % "1.14.0",

  // https://mvnrepository.com/artifact/io.opentelemetry.instrumentation/opentelemetry-logback-1.0
  libraryDependencies += "io.opentelemetry.instrumentation" % "opentelemetry-logback-1.0" % "1.9.2-alpha" % "runtime",
  libraryDependencies += "io.opentelemetry" % "opentelemetry-extension-annotations" % "0.17.1",
  // https://mvnrepository.com/artifact/io.opentelemetry/opentelemetry-sdk-extension-autoconfigure
  libraryDependencies += "io.opentelemetry" % "opentelemetry-sdk-extension-autoconfigure" % "1.14.0-alpha",
  // https://mvnrepository.com/artifact/io.grpc/grpc-stub
  libraryDependencies += "io.grpc" % "grpc-stub" % "1.46.0"
)

then I bootstrap my application like this:

/Users/magicliang/Desktop/Programming/sdk/jdk1.8.0_322.jdk/Contents/Home/bin/java -agentlib:jdwp=transport=dt_socket,address=localhost:53813,suspend=n,server=y -Xdebug -server -Dsbt.supershell=false -Xmx2048M -javaagent:/Users/magicliang/Desktop/Programming/sdk/opentelemetry-javaagent.jar -Dotel.exporter.otlp.endpoint=http://localhost:4317 -Dotel.resource.attributes=service.name=app-name-local -Dotel.metrics.exporter=none -Dotel.logs.exporter=none -Didea.managed=true -Dfile.encoding=UTF-8 "-Didea.installation.dir=/Applications/IntelliJ IDEA.app/Contents" -jar /Users/magicliang/.sdkman/candidates/sbt/1.2.8/bin/sbt-launch.jar early(addPluginSbtFile=\"\"\"/private/var/folders/f1/s8ncc6ts4j552dblgplg1h000000gn/T/idea270.sbt\"\"\") "; set ideaPort in Global := 49817 ; idea-shell"

then I have a structure like this:

@WithSpan
public void foo() {
    bar1();
    bar2();
    bar3();
}


public void bar3() {

final Tracer tracer = GlobalOpenTelemetry.get().getTracer("app-name", "1.0.0");
final Span span = tracer.spanBuilder(String.format("%s.%s", "test", "bar3"))
                .setParent(Context.current().with(Span.current()))
                .startSpan();
        try (Scope ignored = span.makeCurrent()) {
          // do something
        } catch (Throwable throwable) {
            span.setStatus(StatusCode.ERROR, "Something bad happened！");
            span.recordException(throwable);
            throw throwable;
        } finally {
            span.end();
        }

}

according to my understanding of Opentelemetry, bar3 and foo should share same context(with 1 trace id i can search all operation in Jaeger), but it turns out I got 2 traces, one is foo trace, another is bar3 trace.

any one can explain how this can happen?

[magicliang]

I think I figure out the answer: if javaagent-sdk's version is different with Opentelemetry-sdk's version, that will create 2 traces at same thread, same invocation.

[jkwatson]

Yes, that is correct. There isn't any magic solution here. :)

[trask]

this might work if you have control of your main method: https://github.com/open-telemetry/opentelemetry-java-contrib/tree/main/runtime-attach

[magicliang]

this might work if you have control of your main method: https://github.com/open-telemetry/opentelemetry-java-contrib/tree/main/runtime-attach

It depends on how to define "control of main method". I am not developing a spring-boot framework, but a play framework. In play framework, we definitely have some lifecycle hooks which can do some initilization work at early stage of a JVM application, but it is not a main - an explicit entry point of a program. And I think I should ask a clarrifying question - before what stage, we should init an agent. Using an agent java lib in java command is far more ealier than a main, even earlier than the JVM loading the bytecode.

[trask]

we are only recommending/testing "runtime attach" at the very beginning of main. attaching later can lead to issues like open-telemetry/opentelemetry-java-instrumentation#1932

[magicliang]

we are only recommending/testing "runtime attach" at the very beginning of main. attaching later can lead to issues like open-telemetry/opentelemetry-java-instrumentation#1932

Per my poor understanding, this example issue would be an expected "unexpected behavior".

Java specification provides javaagent specification only, but agent authors do not have a public guideline to announce to each other:" how would my instrumentation be ordered in a global sequence. Perhaps every agent should work independently, actually some agent relies on certain timing, certain instrumentation point, which can not be controled by other instrumentation"

So the safest approach would be what is pointed out at the beginning: use javaagent at the bootstrap command. That would take highest precedence at all, which is hard decision to make for me. After all, as a Play framework programmer, I need to customize an tracing framework according to my business logic, and I never have a chance to hook something at the very beginning of main, before any other component is initilized and instrumented.