Unexpected Asynchronous Spans

[astorm]

I ran into a situation where the Elastic Node.js Agent is marking span payloads with the sync=false key/value pair even when the spans themselves contain no asynchronous work.

Consider the following program

const http = require('http');

const requestListener = function (req, res) {
  const span1 = apm.startSpan('This is span 1')
  span1.end()
  const span2 = apm.startSpan('This is span 2')
  span2.end()
  const span3 = apm.startSpan('This is span 3')
  span3.end()
  res.writeHead(200);
  res.end('Hello, World!');
}

const server = http.createServer(requestListener);
server.listen(8080);

This program handles an HTTP request, and then manually starts and stops three spans. Payloads are generated for each span, and those payload have the value sync=false. As a user, my first instinct would be that these spans would be considered synchronous work.

It's unclear whether this is a bug, or a deliberate tradeoff decision to treat all NodeJS spans as async.

Next Steps: Investigate where and why these spans have their default sync=true property set to false.

[trentm]

Discussion:

Alan Storm
early debugging pointed to unrelated async work being able to set span.sync after a span had ended -- but I didn't want to go too deep down this rabbit hole without a map (edited)

Trent Mick
A guess:

  function before (asyncId) {
    const span = activeSpans.get(asyncId)
    if (span) {
      span.sync = false
    }

at this point the "ended" span is still in activeSpans (because that removal is async, I don't profess to be confident in this code path yet), but span.ended == true because that is set synchronously.