dd-trace-js icon indicating copy to clipboard operation
dd-trace-js copied to clipboard
verified publisher icon DataDog

Getting TraceID from an OpenTracing DatadogSpanContext can throw "Cannot read properties of undefined (reading 'toString')

Open davidalpert opened this issue 1 year ago • 16 comments

Calling this DatadogSpanContext.toTraceId() method on what appears to be a valid span can sometimes error out with an undefined inner this._traceId value:

https://github.com/DataDog/dd-trace-js/blob/497c0b0d4333b6a7e7a434fb4de275595e5950c9/packages/dd-trace/src/opentracing/span_context.js#L33-L40

Suggested Solution

  • While I am not sure what might cause this scenario, a quick fix would be to make the dot property access of this._traceId a bit more defensive:

     toTraceId (get128bitId = false) {
    if (this._traceId && get128bitId) {
      return this._traceId.toBuffer().length <= 8 && this._trace.tags[TRACE_ID_128]
        ? this._trace.tags[TRACE_ID_128] + this._traceId.toString(16).padStart(16, '0')
        : this._traceId.toString(16).padStart(32, '0')
    }
    return this._traceId?.toString(10)
  }

Replication Steps

  • Using:

        "dd-trace": "5.25.0",

  • Initialize the tracer on startup:

    import tracer from 'dd-trace';
import { version } from '../../package.json';
import { buildVars } from '#root/.build/buildVars';

tracer.init({
  service: process.env.DD_SERVICE || 'my-fe-app',
  version: version ? `${version}-${buildVars.GIT_SHA}` : '0.0.0',
  tags: {
    pid: process.pid,
  },
  runtimeMetrics: true,
  logInjection: true,
});

  • Try to defensively get the active span's traceID at runtime

    import tracer from 'dd-trace';

...

    const span = tracer.scope().active();
    const traceID = span?.context()?.toTraceId() ?? 'n/a';

...

Expected result

  • traceID is either a valid Trace ID from the current span or undefined in which case we default to 'n/a/ based on the code above

Actual result

  • We regularly encounter an error whereby we seem to have a defined span (i.e. not null or undefined) with an empty or missing DatadogSpanContext._traceID property such that when we call toTraceId() on it we get the following error:

    .../my_app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span_context.js:39
     return this._traceId.toString(10)
                                      ^
TypeError: Cannot read properties of undefined (reading 'toString')
     at DatadogSpanContext.toTraceId (.../my_app/packages/dd-trace/src/opentracing/span_context.js:39:26)

Unit Tests

  • Here is a failing test we can add to packages/dd-trace/test/opentracing/span_context.spec.js to demonstrate the issue

    'use strict'

require('../setup/tap')

const { expect } = require('chai')
const id = require('../../src/id')

describe('SpanContext', () => {
  let SpanContext
  let TraceState

  beforeEach(() => {
    SpanContext = require('../../src/opentracing/span_context')
    TraceState = require('../../src/opentracing/propagation/tracestate')
  })

  ...
  describe('toTraceparent()', () => {
  ...

    it('should allow nullsafe access to trace ID', () => {
      const spanContext = new SpanContext({
        traceId: undefined,
        spanId: id('456', 16)
      })

      spanContext._trace.tags['_dd.p.tid'] = null

      expect(spanContext.toTraceId()).to.equal(undefined)
    })
  })
})

davidalpert avatar Dec 10 '24 14:12 davidalpert

We too are having trouble with this error sometimes after we upgraded from v5.24.0 to v5.25.0. Here are a portion of our code.

import tracer from 'dd-trace'

const serviceName = process.env['DD_SERVICE']

if (serviceName) {
  tracer.init({
    logInjection: true,
    service: serviceName,
  })
}

...

export function logger() {
  // Set req.traceId to http access log
  return (req: Request, res: Response, next: NextFunction) => {
    // dd-trace v5.25.0 sometimes raise error `Cannot read properties of undefined (reading 'toString')`
    // in https://github.com/DataDog/dd-trace-js/blob/497c0b0d4333b6a7e7a434fb4de275595e5950c9/packages/dd-trace/src/opentracing/span_context.js#L39
    req.traceId = tracer?.scope().active()?.context().toTraceId()
    delegate(req, res, next)
  }
}

const app = express()
app.use(logger())

...

mtgto avatar Dec 20 '24 04:12 mtgto

This set of libraries is honestly disappointingly unstable. I feel like every time we upgrade another random issue like this appears. We had it pinned since May 2024 to circumvent another bug, but yesterday I was forced to unpin to fix another problem, and now I wake up to several reports of this error reported here.

You seriously need to invest in better integration tests.

rdsedmundo avatar Jan 10 '25 12:01 rdsedmundo

@rochdev @uurien @watson any feedback here? This seems to be affecting all installations for a month now.

rdsedmundo avatar Jan 10 '25 17:01 rdsedmundo

We're using serverless-plugin-datadog and getting this library through the layer that is published in datadog-lambda-js, the dd-trace version there is not even v5 yet for some reason, but it also has this same problem here.

I've downgraded the layer to 112, which for us is the LKGC.

rdsedmundo avatar Jan 10 '25 18:01 rdsedmundo

I've not been able to reproduce this on v5.25.0 with the code snippets provided (tried continuously sending requests to the express app over a 1000 times). Would it be possible for any of you to create a self contained application that successfully reproduces the problem so we can better investigate?

watson avatar Jan 13 '25 08:01 watson

We ran into this issue after upgrading from 5.21 -> 5.30, without any explicit userland code interacting with DatadogSpanContext

Downgraded to 5.24 after reading this thread and now the issue is resolved

From what I can tell, the only way a DatadogSpanContext can have this._traceId === undefined is if its constructor is called without it

Only obvious example I could find was from this commit

It could also theoretically happen if the SpanContext constructor is called with a truthy context parameter that for some reason doesn't have a traceId, but it's a bit harder to follow the code for this case

I assume there's a reasonable explanation to why this project isn't using static types (e.g. TS) for its source code, since it would largely eliminate this class of problems

smartinio avatar Jan 13 '25 11:01 smartinio

Some debug log snippets from prod:

First error:

"2025-01-10T14:50:37.503Z","Extract from carrier: {}."
"2025-01-10T14:50:37.503Z","Error: Error injecting trace"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46"
"2025-01-10T14:50:37.503Z","at withNoop (/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)"
"2025-01-10T14:50:37.503Z","at onError (/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","at Object.error (/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:102:20)"
"2025-01-10T14:50:37.503Z","at DatadogTracer.inject (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:94:11)"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/plugins/log_plugin.js:49:19"
"2025-01-10T14:50:37.503Z","at wrappedHandler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:79:24)"
"2025-01-10T14:50:37.503Z","at Subscription._handler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:15:9)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","TypeError: Cannot read properties of undefined (reading 'toString')"
"2025-01-10T14:50:37.503Z","at DatadogSpanContext.toTraceId (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span_context.js:40:26)"
"2025-01-10T14:50:37.503Z","at LogPropagator.inject (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/propagation/log.js:20:43)"
"2025-01-10T14:50:37.503Z","at DatadogTracer.inject (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:92:33)"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/plugins/log_plugin.js:49:19"
"2025-01-10T14:50:37.503Z","at wrappedHandler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:79:24)"
"2025-01-10T14:50:37.503Z","at Subscription._handler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:15:9)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","at mixinWithTrace (/app/node_modules/dd-trace/packages/datadog-instrumentations/src/pino.js:47:8)"
"2025-01-10T14:50:37.503Z","at Pino.write (/app/node_modules/pino/lib/proto.js:204:35)"
"2025-01-10T14:50:37.503Z","at Pino.LOG (/app/node_modules/pino/lib/tools.js:62:21)"

This is immediately followed by attempting to encode a payload that is the first one to be missing a trace_id and then another error which disables the plugin (fastify in our case), causing no further traces or metrics to be sent for fastify.request which is our primary operation:

"2025-01-10T14:50:37.503Z","Encoding payload: [{""span_id"":""3031b78499b8bd26"",""parent_id"":""0000000000000000"",""name"":""fastify.request"", ...

"2025-01-10T14:50:37.503Z","Error: Error in plugin handler:"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46"
"2025-01-10T14:50:37.503Z","at withNoop (/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)"
"2025-01-10T14:50:37.503Z","at onError (/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","at Object.error (/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:102:20)"
"2025-01-10T14:50:37.503Z","at wrappedHandler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:81:16)"
"2025-01-10T14:50:37.503Z","at Subscription._handler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:15:9)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","at ServerResponse.emit (/app/node_modules/dd-trace/packages/datadog-instrumentations/src/http/server.js:50:22)"
"2025-01-10T14:50:37.503Z","at onFinish (node:_http_outgoing:1077:10)"
"2025-01-10T14:50:37.503Z","TypeError: Cannot read properties of undefined (reading 'toArray')"
"2025-01-10T14:50:37.503Z","at AgentEncoder._encodeId (/app/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js:158:13)"
"2025-01-10T14:50:37.503Z","at AgentEncoder._encode (/app/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js:94:12)"
"2025-01-10T14:50:37.503Z","at AgentEncoder.encode (/app/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js:39:10)"
"2025-01-10T14:50:37.503Z","at Writer._encode (/app/node_modules/dd-trace/packages/dd-trace/src/exporters/common/writer.js:39:19)"
"2025-01-10T14:50:37.503Z","at Writer.append (/app/node_modules/dd-trace/packages/dd-trace/src/exporters/common/writer.js:35:10)"
"2025-01-10T14:50:37.503Z","at AgentExporter.export (/app/node_modules/dd-trace/packages/dd-trace/src/exporters/agent/index.js:45:18)"
"2025-01-10T14:50:37.503Z","at SpanProcessor.process (/app/node_modules/dd-trace/packages/dd-trace/src/span_processor.js:59:30)"
"2025-01-10T14:50:37.503Z","at DatadogSpan.finish (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span.js:242:21)"
"2025-01-10T14:50:37.503Z","at Object.finishSpan (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/util/web.js:327:18)"
"2025-01-10T14:50:37.503Z","at Object.finishAll (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/util/web.js:338:9)"
"2025-01-10T14:50:37.503Z","Disabling plugin: undefined"
"2025-01-10T14:50:37.503Z","Error: Error injecting trace"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46"
"2025-01-10T14:50:37.503Z","at withNoop (/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)"
"2025-01-10T14:50:37.503Z","at onError (/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","at Object.error (/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:102:20)"
"2025-01-10T14:50:37.503Z","at DatadogTracer.inject (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:94:11)"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/plugins/log_plugin.js:49:19"
"2025-01-10T14:50:37.503Z","at wrappedHandler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:79:24)"
"2025-01-10T14:50:37.503Z","at Subscription._handler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:15:9)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","TypeError: Cannot read properties of undefined (reading 'toString')"
"2025-01-10T14:50:37.503Z","at DatadogSpanContext.toTraceId (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span_context.js:40:26)"
"2025-01-10T14:50:37.503Z","at LogPropagator.inject (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/propagation/log.js:20:43)"
"2025-01-10T14:50:37.503Z","at DatadogTracer.inject (/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:92:33)"
"2025-01-10T14:50:37.503Z","at /app/node_modules/dd-trace/packages/dd-trace/src/plugins/log_plugin.js:49:19"
"2025-01-10T14:50:37.503Z","at wrappedHandler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:79:24)"
"2025-01-10T14:50:37.503Z","at Subscription._handler (/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:15:9)"
"2025-01-10T14:50:37.503Z","at Channel.publish (node:diagnostics_channel:143:9)"
"2025-01-10T14:50:37.503Z","at mixinWithTrace (/app/node_modules/dd-trace/packages/datadog-instrumentations/src/pino.js:47:8)"
"2025-01-10T14:50:37.503Z","at Pino.write (/app/node_modules/pino/lib/proto.js:204:35)"

Stack (at 2025-01-10):

  • runtime: Node.js 22.11.0 (ESM)
  • dd-trace: 5.30.0 (node --import dd-trace/register.js service.js)
  • agent: 7.52.0
  • server: Fastify 5.1.0
  • logger: Pino 8.19.0

smartinio avatar Jan 14 '25 08:01 smartinio

I've not been able to reproduce this on v5.25.0 with the code snippets provided (tried continuously sending requests to the express app over a 1000 times). Would it be possible for any of you to create a self contained application that successfully reproduces the problem so we can better investigate?

I haven't been able to create a local repro yet. Will post here if I do.

smartinio avatar Jan 14 '25 09:01 smartinio

This is a critical issue for us as well. We have to disable ASM + tracing in our apps.

@rochdev Any attempt from datadog to fix this. It is a severe issue for us using datadog.

KnisterPeter avatar Jan 14 '25 13:01 KnisterPeter

I'm currently attempting to fix this. Please downgrade to 5.24 to avoid seeing this issue for the time being

ida613 avatar Jan 22 '25 16:01 ida613

We ran into this upgrading from 4.48.0 -> 4.55.0.

ndevvy avatar Jan 27 '25 22:01 ndevvy

We are also seeing this in another place that does not appear to be covered in the open PR, when encoding the span:

TypeError: Cannot read properties of undefined (reading 'toArray')
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js", line 158, col 13, in AgentEncoder._encodeId
    id = id.toArray()
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js", line 94, col 12, in AgentEncoder._encode
    this._encodeId(bytes, span.trace_id)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js", line 39, col 10, in AgentEncoder.encode
    this._encode(bytes, trace)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/exporters/common/writer.js", line 39, col 19, in Writer._encode
    this._encoder.encode(payload)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/exporters/common/writer.js", line 35, col 10, in Writer.append
    this._encode(payload)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/exporters/agent/index.js", line 45, col 18, in AgentExporter.export
    this._writer.append(spans)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/span_processor.js", line 59, col 30, in SpanProcessor.process
    this._exporter.export(formatted)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/opentracing/span.js", line 252, col 21, in DatadogSpan.finish
    this._processor.process(this)
  File "/app/node_modules/.pnpm/[email protected]/node_modules/dd-trace/packages/dd-trace/src/tracer.js", line 84, col 18, in <anonymous>
    span.finish()
  File "node:internal/process/task_queues", line 105, col 5, in process.processTicksAndRejections

smcgivern avatar Jan 28 '25 15:01 smcgivern

We ran into this upgrading from "4.49.0" -> "5.35.0"

toly-k avatar Feb 12 '25 18:02 toly-k

We ran into this upgrading from "4.49.0" -> "5.35.0"

This should be fixed in 5.36.0

rochdev avatar Feb 12 '25 23:02 rochdev

Hello ! Do you have any news about the bug resolution ?

remijacquarthublo avatar Apr 30 '25 09:04 remijacquarthublo

@remijacquarthublo I guess you are using a never version than 5.36.0 or 5.36.0? Could you please post the concrete error and as much additional information as you have? :)

BridgeAR avatar Apr 30 '25 12:04 BridgeAR

Closing, since this got fixed in 5.36.0

BridgeAR avatar Sep 11 '25 23:09 BridgeAR