Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
davidalpert opened this issue Dec 10, 2024 · 9 comments

Comments

@davidalpert
Copy link

davidalpert commented Dec 10, 2024

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

toTraceId (get128bitId = false) {
if (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)
}

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)
        })
      })
    })
    
@mtgto
Copy link

mtgto commented Dec 20, 2024

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())

...

@rdsedmundo
Copy link

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
Copy link

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

@rdsedmundo
Copy link

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.

@watson
Copy link
Collaborator

watson commented Jan 13, 2025

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?

@smartinio
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

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.

@KnisterPeter
Copy link

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants