Skip to content

[BUG]: Express tracing errors then stops sending traces #5111

Open
@vernak2539

Description

@vernak2539

Tracer Version(s)

5.29.0, v5.29.1, v5.30.0

Node.js Version(s)

22.11.0

Bug Report

I originally put this in #5092, but separated into it's own issue.

Since upgrading to the affected versions, we're finding that tracing stops after a bit of time. It's quite arbitrary, but it seems to be after 4-6 hours. When our application is redeployed, the tracing begins again. I've put a screenshot below to illustrate. While the screenshot shows the express.middleware operation this also happens for the express.request operation.

Image

Versions less than the affected versions (I've tested 5.13.0, 5.21.0, 5.26.0, 5.28.0) don't seem to have this issue.

I've just enabled the logs and debug modes for our app to find out more, but initially there was no indication output as to why the tracing stopped.

I should also note that this happened in our staging and production environments. While our staging environment doesn't always have traffic, our production environment does. Additionally, both staging and production have health check endpoints that are hit by our ALBs, which should show up in tracing. During the times of no tracing, not even the health check endpoint is visible in tracing.

I've been able to find the logs, which are below. It seems the dd-trace module is encountering errors for some reason. The log:

2025-01-13T22:08:17.196Z DD_TRACE-INFO: Disabling plugin: undefined

Feels like the cause for tracing to be stopped.

Maybe it's related to #4987. But since #4987 deals with different affected versions, maybe it's different.

Note: The log Package 'next' was loaded before dd-trace! This may break instrumentation. is present in working versions. The next.request operation works fine in previous versions and in the affected versions. Our start command below which should load the instrumentation before next (we use a express custom server with next):

$ DD_TRACE_DEBUG=true DD_TRACE_LOG_FILE=ddtrace_logs.log NODE_ENV=production node --import ./src/node-instrumentation.mjs src/server/index.mjs

Reproduction Code

// ./src/server/node-instrumentation.mjs 

import tracer from 'dd-trace';

  tracer.init({
    hostname: process.env.STATSD_HOST,
    service: 'app',
    startupLogs: true,
    debug: true,
    logLevel: 'debug',
    logger: {
      error: (err) => console.error('DD_TRACE-ERROR: ', err),
      warn: (message) => console.warn('DD_TRACE-WARN: ', message),
      info: (message) => console.info('DD_TRACE-INFO: ', message),
      debug: () => {}, // (message) => console.trace('DD_TRACE-DEBUG: ', message),
    },
  });

tracer.use('express')
// ./src/server/index.mjs

import express from 'express';

const app = express()
const port = 3000

app.get('/', (req, res) => {
  res.send('Hello World!')
})

app.listen(port, () => {
  console.log(`Example app listening on port ${port}`)
})

Error Logs

2025-01-13T17:56:38.138Z DD_TRACE-WARN:  Warning: Package 'next' was loaded before dd-trace! This may break instrumentation.
2025-01-13T17:56:38.138Z DD_TRACE-WARN:  Warning: Please ensure dd-trace is loaded before other modules.
2025-01-13T17:56:39.067Z DD_TRACE-INFO:  Found incompatible integration version: [email protected]
2025-01-13T17:56:54.762Z DD_TRACE-INFO:  DATADOG TRACER CONFIGURATION - {"date":"2025-01-13T17:56:54.760Z","os_name":"Linux","os_version":"5.10.228-219.884.amzn2.x86_64","architecture":"x64","version":"5.29.0","lang":"nodejs","lang_version":"22.11.0","service":"app","agent_url":"http://10.0.13.177:8126","debug":true,"sampling_rules":[],"tags":{"service":"app","version":"0.0.1","runtime-id":"5cc1d25d-8a7f-4266-a79b-a487cb107430"},"dd_version":"0.0.1","log_injection_enabled":false,"runtime_metrics_enabled":false,"profiling_enabled":false,"integrations_loaded":["fetch","net","dns","http","express","child_process","next"],"appsec_enabled":false}
2025-01-13T22:08:16.608Z DD_TRACE-ERROR: Error: Error injecting trace
2025-01-13T22:08:16.608Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46
2025-01-13T22:08:16.608Z    at withNoop (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)
2025-01-13T22:08:16.608Z    at onError (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)
2025-01-13T22:08:16.608Z    at Channel.publish (node:diagnostics_channel:143:9)
2025-01-13T22:08:16.608Z    at Object.error (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:82:20)
2025-01-13T22:08:16.608Z    at DatadogTracer.inject (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:94:11)
2025-01-13T22:08:16.608Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-http/src/client.js:62:19)
2025-01-13T22:08:16.608Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-fetch/src/index.js:18:25)
2025-01-13T22:08:16.608Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/tracing.js:81:59
2025-01-13T22:08:16.608Z    at StoreBinding._transform (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:36:11)
2025-01-13T22:08:16.608Z DD_TRACE-ERROR: TypeError: Cannot read properties of undefined (reading 'toString')
2025-01-13T22:08:16.608Z    at DatadogSpanContext.toTraceId (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span_context.js:40:26)
2025-01-13T22:08:16.608Z    at HttpPropagator._injectDatadog (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/propagation/text_map.js:88:37)
2025-01-13T22:08:16.608Z    at HttpPropagator.inject (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/propagation/text_map.js:59:10)
2025-01-13T22:08:16.608Z    at DatadogTracer.inject (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:92:33)
2025-01-13T22:08:16.608Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-http/src/client.js:62:19)
2025-01-13T22:08:16.608Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-fetch/src/index.js:18:25)
2025-01-13T22:08:16.608Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/tracing.js:81:59
2025-01-13T22:08:16.608Z    at StoreBinding._transform (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:36:11)
2025-01-13T22:08:16.608Z    at node:diagnostics_channel:84:17
2025-01-13T22:08:16.608Z    at Channel.runStores (node:diagnostics_channel:164:12)
2025-01-13T22:08:17.010Z DD_TRACE-ERROR: Error: Error injecting trace
2025-01-13T22:08:17.010Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46
2025-01-13T22:08:17.010Z    at withNoop (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)
2025-01-13T22:08:17.010Z    at onError (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)
2025-01-13T22:08:17.010Z    at Channel.publish (node:diagnostics_channel:143:9)
2025-01-13T22:08:17.010Z    at Object.error (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:82:20)
2025-01-13T22:08:17.010Z    at DatadogTracer.inject (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:94:11)
2025-01-13T22:08:17.010Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-http/src/client.js:62:19)
2025-01-13T22:08:17.010Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-fetch/src/index.js:18:25)
2025-01-13T22:08:17.010Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/tracing.js:81:59
2025-01-13T22:08:17.010Z    at StoreBinding._transform (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:36:11)
2025-01-13T22:08:17.010Z DD_TRACE-ERROR: TypeError: Cannot read properties of undefined (reading 'toString')
2025-01-13T22:08:17.010Z    at DatadogSpanContext.toTraceId (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span_context.js:40:26)
2025-01-13T22:08:17.010Z    at HttpPropagator._injectDatadog (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/propagation/text_map.js:88:37)
2025-01-13T22:08:17.010Z    at HttpPropagator.inject (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/propagation/text_map.js:59:10)
2025-01-13T22:08:17.010Z    at DatadogTracer.inject (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/tracer.js:92:33)
2025-01-13T22:08:17.010Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-http/src/client.js:62:19)
2025-01-13T22:08:17.010Z    at FetchPlugin.bindStart (/path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-fetch/src/index.js:18:25)
2025-01-13T22:08:17.010Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/tracing.js:81:59
2025-01-13T22:08:17.010Z    at StoreBinding._transform (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:36:11)
2025-01-13T22:08:17.010Z    at node:diagnostics_channel:84:17
2025-01-13T22:08:17.010Z    at Channel.runStores (node:diagnostics_channel:164:12)
2025-01-13T22:08:17.196Z DD_TRACE-ERROR: Error: Error in plugin handler:
2025-01-13T22:08:17.196Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46
2025-01-13T22:08:17.196Z    at withNoop (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)
2025-01-13T22:08:17.196Z    at onError (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)
2025-01-13T22:08:17.196Z    at Channel.publish (node:diagnostics_channel:143:9)
2025-01-13T22:08:17.196Z    at Object.error (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:82:20)
2025-01-13T22:08:17.196Z    at wrappedHandler (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:81:16)
2025-01-13T22:08:17.196Z    at Subscription._handler (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:15:9)
2025-01-13T22:08:17.196Z    at Channel.publish (node:diagnostics_channel:143:9)
2025-01-13T22:08:17.196Z    at ServerResponse.emit (/path/to/my/app/node_modules/dd-trace/packages/datadog-instrumentations/src/http/server.js:50:22)
2025-01-13T22:08:17.196Z    at onFinish (node:_http_outgoing:1077:10)
2025-01-13T22:08:17.196Z DD_TRACE-ERROR: TypeError: Cannot read properties of undefined (reading 'toArray')
2025-01-13T22:08:17.196Z    at AgentEncoder._encodeId (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js:158:13)
2025-01-13T22:08:17.196Z    at AgentEncoder._encode (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js:94:12)
2025-01-13T22:08:17.196Z    at AgentEncoder.encode (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/encode/0.4.js:39:10)
2025-01-13T22:08:17.196Z    at Writer._encode (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/common/writer.js:39:19)
2025-01-13T22:08:17.196Z    at Writer.append (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/common/writer.js:35:10)
2025-01-13T22:08:17.196Z    at AgentExporter.export (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/agent/index.js:45:18)
2025-01-13T22:08:17.196Z    at SpanProcessor.process (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/span_processor.js:59:30)
2025-01-13T22:08:17.196Z    at DatadogSpan.finish (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/opentracing/span.js:242:21)
2025-01-13T22:08:17.196Z    at /path/to/my/app/node_modules/dd-trace/packages/datadog-plugin-router/src/index.js:82:14
2025-01-13T22:08:17.196Z    at wrappedHandler (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/plugins/plugin.js:79:24)
2025-01-13T22:08:17.196Z DD_TRACE-INFO: Disabling plugin: undefined
2025-01-13T22:08:19.985Z DD_TRACE-ERROR: Error: Error sending payload to the agent (status code: 400)
2025-01-13T22:08:19.985Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:46
2025-01-13T22:08:19.985Z    at withNoop (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:21:3)
2025-01-13T22:08:19.985Z    at onError (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/writer.js:69:18)
2025-01-13T22:08:19.985Z    at Channel.publish (node:diagnostics_channel:143:9)
2025-01-13T22:08:19.985Z    at Object.error (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/log/index.js:82:20)
2025-01-13T22:08:19.985Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/agent/writer.js:44:13
2025-01-13T22:08:19.985Z    at /path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/agent/writer.js:105:5
2025-01-13T22:08:19.985Z    at IncomingMessage.<anonymous> (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/common/request.js:116:9)
2025-01-13T22:08:19.985Z    at /path/to/my/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:50:55
2025-01-13T22:08:19.985Z    at AsyncLocalStorage.run (node:internal/async_local_storage/async_hooks:91:14)
2025-01-13T22:08:19.985Z DD_TRACE-ERROR: Error: Error from http://10.0.13.177:8126/v0.4/traces: 400 Bad Request. Response from the endpoint: "msgp: attempted to decode type "array" with method for "str"  at 0/0
2025-01-13T22:08:19.985Z "
2025-01-13T22:08:19.985Z    at IncomingMessage.<anonymous> (/path/to/my/app/node_modules/dd-trace/packages/dd-trace/src/exporters/common/request.js:113:23)
2025-01-13T22:08:19.985Z    at /path/to/my/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:50:55
2025-01-13T22:08:19.985Z    at AsyncLocalStorage.run (node:internal/async_local_storage/async_hooks:91:14)
2025-01-13T22:08:19.985Z    at SentryContextManager.with (/path/to/my/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:33:40)
2025-01-13T22:08:19.985Z    at SentryContextManager.with (file:///path/to/my/app/node_modules/@sentry/opentelemetry/build/esm/index.js:1386:24)
2025-01-13T22:08:19.985Z    at IncomingMessage.contextWrapper (/path/to/my/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:50:32)
2025-01-13T22:08:19.985Z    at IncomingMessage.emit (node:events:530:35)
2025-01-13T22:08:19.985Z    at endReadableNT (node:internal/streams/readable:1698:12)
2025-01-13T22:08:19.985Z    at process.processTicksAndRejections (node:internal/process/task_queues:90:21) {
2025-01-13T22:08:19.985Z status: 400
2025-01-13T22:08:19.985Z }

Tracer Config

  tracer.init({
    hostname: process.env.STATSD_HOST,
    service: 'app',
    startupLogs: true,
    debug: true,
    logLevel: 'debug',
    logger: {
      error: (err) => console.error('DD_TRACE-ERROR: ', err),
      warn: (message) => console.warn('DD_TRACE-WARN: ', message),
      info: (message) => console.info('DD_TRACE-INFO: ', message),
      debug: () => {}, // (message) => console.trace('DD_TRACE-DEBUG: ', message),
    },
  });

Operating System

Darwin XXX 24.2.0 Darwin Kernel Version 24.2.0

Bundling

No Bundling

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions