Sentry gets wrong active transaction when going through pino stream destination

[swantzter]

Is there an existing issue for this?

• [X] I have checked for existing issues https://github.com/getsentry/sentry-javascript/issues
• [X] I have reviewed the documentation https://docs.sentry.io/
• [X] I am using the latest SDK release https://github.com/getsentry/sentry-javascript/releases

How do you use Sentry?

Self-hosted/on-premise

Which SDK are you using?

@sentry/node

SDK Version

7.88.0

Framework Version

No response

Link to Sentry event

No response

SDK Setup

Adding in a minimal repro

const pino = require('pino')
const Sentry = require('@sentry/node')
const build = require('pino-abstract-transport')

Sentry.init({
  enableTracing: true
})

const sentryStream = build(async function (source) {
  for await (let obj of source) {
    Sentry.addBreadcrumb()
    const span = Sentry.getActiveSpan()
    const transaction = Sentry.getActiveTransaction()
    console.log({
      ...obj,
      spanId: span?.spanId,
      transactionId: transaction?.traceId
    })
  }
}, { })

const dest = pino.multistream([process.stdout, sentryStream])

const logger = pino({}, dest)

function run () {
  const transaction = Sentry.startTransaction({
    op: "test",
    name: "My First Test Transaction",
  })

  Sentry.startSpan({}, async (span) => {
    console.log(span?.spanId)
    logger.info({ mainSpanId: span.spanId, mainTransactionId: transaction.traceId })
  })

  transaction.finish()
}

run()
run()

setTimeout(() => {}, 1000)

Steps to Reproduce

Run the code above

Expected Result

The console should log something like:

{
  level: 30,
  mainSpanId: '857973d878e72ec3',
  mainTransactionId: '6df9fe9a68194199864b4b82bdacddf6',

  spanId: '857973d878e72ec3',
  transactionId: '33c334bc400e4a29b51829a8800d122c'
}
{
  level: 30,

  mainSpanId: '841655e2160cc571',
  mainTransactionId: 'e0b25eea29f648dd9f996194919a739d',

  spanId: '841655e2160cc571',
  transactionId: 'e0b25eea29f648dd9f996194919a739d'
}

Actual Result

The current span and transaction id when processing the log line are stuck on the first transaction:

{
  level: 30,

  mainSpanId: '857973d878e72ec3',
  mainTransactionId: '6df9fe9a68194199864b4b82bdacddf6',

  spanId: '857973d878e72ec3',
  transactionId: '33c334bc400e4a29b51829a8800d122c'
}
{
  level: 30,

  mainSpanId: '841655e2160cc571',
  mainTransactionId: 'e0b25eea29f648dd9f996194919a739d',

  spanId: '857973d878e72ec3',
  transactionId: '33c334bc400e4a29b51829a8800d122c'
}

[AbhiPrasad]

you might need to use https://docs.sentry.io/platforms/node/configuration/async-context/ to do isolation, does that help?

[swantzter]

@AbhiPrasad changing my code above to do

[snip]
Sentry.runWithAsyncContext(async () => run())
Sentry.runWithAsyncContext(async () => run())
[snip]

and also separately tried

[snip]
function run () {
  Sentry.runWithAsyncContext(async () => {
[snip]
  })
[snip]

and the results were.... worse:

{
  level: 30,

  mainSpanId: 'a5211349ba5dfebf',
  mainTransactionId: '237ce9c66dcf44449ccc14afd6653b6c',

  spanId: undefined,
  transactionId: undefined
}
{
  level: 30,

  mainSpanId: '8c2e0aadea8b06ae',
  mainTransactionId: '61a0aa3c86d24845968834c31756bd7f',

  spanId: undefined,
  transactionId: undefined
}

context was completely lost instead of just being wrong

[lforst]

I think we are breaking out of the async context by calling getActive... inside the callback, we pass to build. I think you would need to create the stream inside the same (or parent) async context as the run() invocation.

[AbhiPrasad]

So this should be better with 8.x of the Node SDK. You can follow our guide to upgrade: https://docs.sentry.io/platforms/javascript/guides/express/migration/v7-to-v8/

Closing as such, but please reach out if there are issues with 8.x of the SDK!