open-telemetry / open-telemetry/opentelemetry-java-instrumentation

[Kotlin] Incorrectly linked spans, incorrect durations when Coroutine Dispatchers are used

Open
#6,502 9 comments 3 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug repro provided
Dominant language
Java
Stars
2.6k
Forks
1.2k
Avg merge
2d 18h
Merged PRs (30d)
228

Description

Describe the bug

When using the Java Agent & annotation driven auto-instrumentation with Kotlin - and the Coroutine Dispatcher is used (to dispatch some Coroutines outside of the main thread); we see broken traces consistently. Here's how the traces appear to be broken:

  1. Functions within a Dispatched block appear as their own traces - their spans untethered to their direct parent or calling method (but sometimes still tethered to the parent's parent).
  2. As a consequence of (1), you see two spans for the same method; when there was only one execution of it.
  3. Methods that use Dispatch blocks have durations that are inaccurately reported - they appear to finish much quicker than the method actually does.

Steps to reproduce

A minimal reproducible example below.

  companion object {
    private val log = logger {}

    fun runit() {
      runBlocking {
        log.info { "Starting the example" }
        breakingSpans()
      }
    }

    @JvmStatic
    fun main(args: Array<String>) {
      runit()
    }

    @WithSpan
    suspend fun breakingSpans() {
      kotlin.runCatching {
        blockingWork()
        usingIOPool()
      }
    }

    @WithSpan
    suspend fun blockingWork() {
      delay(2000L)
    }

    @WithSpan
    suspend fun usingIOPool() {
      return withContext(Dispatchers.IO) {
        fetchUpstreamResource()
        log.info { "Finished getting upstream resource" }
      }
    }

    @WithSpan
    suspend fun fetchUpstreamResource(){
      delay(2000L)
    }
  }

What did you expect to see?

  • I expect to see a single breakingSpans trace per run.
  • I expect to see fetchUpstreamResource, usingIOPool and blockingWork in the same trace.
  • I expect the durations of these methods to represent the time it took for them to complete - which is at least 2 seconds.

What did you see instead?

  • I see multiple (3) traces from breakingSpans
    • One with breakingSpans -> blockingWork (surprisingly and not the focus of this post since this is not Dispatched work but blockingWork's duration is also inaccurate)
    • One with breakingSpans -> usingIOPool (but duration of usingIOPool is inaccurate)
    • One with just fetchUpstreamResource (but duration of fetchUpstreamResource is inaccurate)

Some pictures below to see how this looks; but also see the the Logs all the way at the end.

image image image

What version are you using?

opentelemetry-javaagent - version: 1.15.0

Environment
Compiler: Azul (OpenJDK) 16.0.2
OS: MacOS Monterey

Additional context

The logs are quite interesting as well, and show the 3 traces being emitted:

        io.plutocard.ServerApp [req.id=null]  Starting blockingWork 
[otel.javaagent 2022-08-23 11:19:16:580 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.blockingWork' : a67c5bfad57eb68d79dd239ea51dc0ea f0c9ea759b7231d3 INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:16:580 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.breakingSpans' : a67c5bfad57eb68d79dd239ea51dc0ea 09e8b492d7e466b7 INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
2022-08-23 11:19:18.586 [main] INFO 
        io.plutocard.ServerApp [req.id=null]  Finished blockingWork 
2022-08-23 11:19:18.588 [main] INFO 
        io.plutocard.ServerApp [req.id=null] Started usingIOPool
[otel.javaagent 2022-08-23 11:19:18:587 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.blockingWork' : f9518af01d2d50cfa01f90844baca7f7 2ec970a1fc21956d INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:18:603 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.usingIOPool' : d404221fd5b24595bda24fde15f1b780 e3843e87db13b61b INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:18:603 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.breakingSpans' : d404221fd5b24595bda24fde15f1b780 f2e62b9951c48a0f INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:18:605 -0400] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.fetchUpstreamResource' : ef65b66b1081ac297646d5e0cd129ad4 cb76a767dbc0ef94 INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=DefaultDispatcher-worker-1, thread.id=20}, capacity=128, totalAddedValues=2}
2022-08-23 11:19:18.604 [DefaultDispatcher-worker-1] INFO 
        io.plutocard.ServerApp [req.id=null] Started fetchUpstreamResource
2022-08-23 11:19:20.611 [DefaultDispatcher-worker-1] INFO 
        io.plutocard.ServerApp [req.id=null] Finished fetchUpstreamResource
[otel.javaagent 2022-08-23 11:19:20:611 -0400] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.fetchUpstreamResource' : 0461ccfc74e6ae8b7d7cf1522c4d5f2c 2e4d70998f21930a INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=DefaultDispatcher-worker-1, thread.id=20}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:20:611 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.breakingSpans' : 96cd29c74e0d1e99db3ab94876aa8797 faedee63fcaa99da INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the minimal Kotlin example using the Java Agent, @WithSpan, runBlocking, and withContext(Dispatchers.IO), and reproduce the traces with the logging exporter. Trace context should remain linked across dispatched coroutines, each method should produce one span, and span durations should cover the actual delay and dispatched work.

Written by the indexing model from the issue text.

Assessment

Tech stack
java, kotlin
Domain
observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.