Sentry doesn't use trace provided in request

max-prtsr commented 4 weeks ago

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?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/node

SDK Version

8.25.0

Framework Version

"express": "4.17.1"

Link to Sentry event

https://protosure.sentry.io/issues/4798675845/?project=1531391&query=is%3Aunresolved+issue.priority%3A%5Bhigh%2C+medium%5D&referrer=issue-stream&statsPeriod=7d&stream_index=3

Reproduction Example/SDK Setup

// server.ts
/* eslint-disable import/order,import/first */
import * as Sentry from '@sentry/node'
import { nodeProfilingIntegration } from '@sentry/profiling-node'

// Sentry must be inited before the all other imports
const SENTRY_DSN = process.env.JS_BACKEND_SENTRY_DSN
if (!SENTRY_DSN) throw new Error('SENTRY_DSN is not set')
Sentry.init({
  dsn: SENTRY_DSN,
  integrations: [
    Sentry.debugIntegration(),
    nodeProfilingIntegration(),
    Sentry.onUnhandledRejectionIntegration({ mode: 'strict' }),
    Sentry.expressIntegration(),
  ],
  tracesSampleRate: 0.1,
})

import '@babel/polyfill'
import express, { Router } from 'express'

const routes = Router()
routes.get('/healthcheck/test_sentry/', (req, res) => {
  throw new Error('Test Sentry "JS Backend Error"')
})

const app = express()
  .set('port', process.env.PORT || 3000)
  .use('/', routes)

Sentry.setupExpressErrorHandler(app)

app.listen(app.get('port'), () => {
  console.log(`Server running on port ${app.get('port')}`)
})

Steps to Reproduce

I'm sending trace stuff from the python server:

        headers = {
            'Content-type': 'application/json',
            'Accept': 'text/plain',
            'sentry-trace': sentry_sdk.get_traceparent(),
            'baggage': sentry_sdk.get_baggage(),
        }
        response = requests.request(
            method, url, data=data, headers=headers, timeout=settings.JSBACKEND_REQUESTS_TIMEOUT
        )

And you can see the correct trace_id is being sent in debug info

Expected Result

Exception in express uses trace got in sentry-trace - 5e4d5a3d98584bfcbe381e77fd509701-866c84dc2567c8f8-1

Actual Result

It creates new trace 9233d99781ed8d5b932ffb019d8e791e

debug info

{
  exception: { values: [ [Object] ] },
  event_id: 'dd4f893143a64780ad946446c0806acc',
  platform: 'node',
  contexts: {
    trace: {
      trace_id: '9233d99781ed8d5b932ffb019d8e791e',
      span_id: 'e7c2a0c3be38da78'
    },
    runtime: { name: 'node', version: 'v18.16.0' },
    app: {
      app_start_time: '2024-08-16T09:14:00.116Z',
      app_memory: 93126656
    },
    os: {
      kernel_version: '23.5.0',
      name: 'macOS',
      version: '14.5',
      build: '23F79'
    },
    device: {
      boot_time: '2024-07-22T04:46:49.546Z',
      arch: 'arm64',
      memory_size: 34359738368,
      free_memory: 72122368,
      processor_count: 12,
      cpu_description: 'Apple M2 Max',
      processor_frequency: 24
    },
    culture: { locale: 'en-US', timezone: 'Asia/Bangkok' },
    cloud_resource: {}
  },
  server_name: 'Maxims-MB14.local',
  sdkProcessingMetadata: {
    dynamicSamplingContext: {
      environment: 'production',
      public_key: '61a36cab7f7f56c62f2ca43be0e4287e',
      trace_id: '9233d99781ed8d5b932ffb019d8e791e',
      sampled: 'false'
    },
    request: IncomingMessage {
      _readableState: [ReadableState],
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      socket: [Socket],
      httpVersionMajor: 1,
      httpVersionMinor: 1,
      httpVersion: '1.1',
      complete: true,
      rawHeaders: [Array],
      rawTrailers: [],
      joinDuplicateHeaders: undefined,
      aborted: false,
      upgrade: false,
      url: '/healthcheck/test_sentry/',
      method: 'GET',
      statusCode: null,
      statusMessage: null,
      client: [Socket],
      _consuming: false,
      _dumped: true,
      addListener: [Function (anonymous)],
      on: [Function (anonymous)],
      once: [Function (anonymous)],
      prependListener: [Function (anonymous)],
      prependOnceListener: [Function (anonymous)],
      removeListener: [Function (anonymous)],
      off: [Function (anonymous)],
      removeAllListeners: [Function (anonymous)],
      next: undefined,
      baseUrl: undefined,
      originalUrl: '/healthcheck/test_sentry/',
      _parsedUrl: [Url],
      params: undefined,
      query: {},
      res: [ServerResponse],
      route: [Route],
      __onFinished: null,
      [Symbol(kCapture)]: false,
      [Symbol(kHeaders)]: [Object],
      [Symbol(kHeadersCount)]: 20,
      [Symbol(kTrailers)]: null,
      [Symbol(kTrailersCount)]: 0,
      [Symbol(OtListeners)]: [Object: null prototype]
    }
  },
  timestamp: 1723799661.515,
  environment: 'production',
  sdk: {
    integrations: [
      'InboundFilters',       'FunctionToString',
      'LinkedErrors',         'RequestData',
      'Console',              'Http',
      'NodeFetch',            'OnUncaughtException',
      'OnUnhandledRejection', 'ContextLines',
      'LocalVariables',       'Context',
      'Modules',              'Express',
      'Fastify',              'Graphql',
      'Mongo',                'Mongoose',
      'Mysql',                'Mysql2',
      'Redis',                'Postgres',
      'Nest',                 'Hapi',
      'Koa',                  'Connect',
      'ProfilingIntegration', 'Debug'
    ]
  },
  transaction: 'GET /healthcheck/test_sentry/',
  breadcrumbs: [
    {
      timestamp: 1723799641.118,
      category: 'console',
      level: 'log',
      message: 'Server running on port 3000'
    }
  ],
  request: {
    method: 'GET',
    cookies: {},
    headers: {
      host: 'host.docker.internal:3000',
      'sentry-trace': '5e4d5a3d98584bfcbe381e77fd509701-866c84dc2567c8f8-1, 5e4d5a3d98584bfcbe381e77fd509701-93087b3851841ee2-1',
      baggage: 'sentry-environment=production,sentry-release=protosure%40undefined,sentry-public_key=61a36cab7f7f56c62f2ca43be0e4287e,sentry-trace_id=5e4d5a3d98584bfcbe381e77fd509701,sentry-sample_rate=0.05,sentry-sampled=false, sentry-environment=production,sentry-release=protosure%40undefined,sentry-public_key=61a36cab7f7f56c62f2ca43be0e4287e,sentry-trace_id=5e4d5a3d98584bfcbe381e77fd509701,sentry-sample_rate=0.05,sentry-sampled=false',
      'user-agent': 'python-requests/2.32.2',
      'accept-encoding': 'gzip, deflate, br',
      accept: 'text/plain',
      connection: 'keep-alive',
      'content-type': 'application/json'
    },
    query_string: undefined,
    url: 'http://host.docker.internal:3000/healthcheck/test_sentry/'
  },
  modules: {
    'ts-node-dev': '1.1.8',
    'source-map-support': '0.5.21',
    'source-map': '0.6.1',
    'buffer-from': '1.1.2',
    'tsconfig-paths': '3.9.0',
    'strip-bom': '3.0.0',
    minimist: '1.2.6',
    resolve: '1.22.6',
    'is-core-module': '2.13.0',
    has: '1.0.4',
    shimmer: '1.2.1',
    'require-in-the-middle': '7.4.0',
    'supports-color': '7.2.0',
    'has-flag': '4.0.0',
    'module-details-from-path': '1.0.3',
    'import-in-the-middle': '1.11.0',
    'detect-libc': '2.0.3',
    'node-abi': '3.65.0',
    semver: '7.5.4',
    'lru-cache': '6.0.0',
    yallist: '4.0.0',
    'regenerator-runtime': '0.13.11',
    express: '4.17.1',
    'body-parser': '1.19.0',
    depd: '1.1.2',
    'merge-descriptors': '1.0.1',
    finalhandler: '1.1.2',
    encodeurl: '1.0.2',
    'escape-html': '1.0.3',
    'on-finished': '2.3.0',
    'ee-first': '1.1.1',
    parseurl: '1.3.3',
    statuses: '1.5.0',
    unpipe: '1.0.0',
    'array-flatten': '1.1.1',
    'path-to-regexp': '0.1.7',
    methods: '1.1.2',
    'utils-merge': '1.0.1',
    setprototypeof: '1.1.1',
    'content-disposition': '0.5.3',
    'content-type': '1.0.5',
    send: '0.17.1',
    inherits: '2.0.4',
    toidentifier: '1.0.0',
    etag: '1.8.1',
    fresh: '0.5.2',
    mime: '1.6.0',
    'range-parser': '1.2.1',
    'proxy-addr': '2.0.7',
    forwarded: '0.2.0',
    accepts: '1.3.8',
    negotiator: '0.6.3',
    'mime-types': '2.1.35',
    'mime-db': '1.52.0',
    'type-is': '1.6.18',
    'media-typer': '0.3.0',
    'cookie-signature': '1.0.6',
    cookie: '0.4.0',
    vary: '1.1.2',
    bytes: '3.1.0',
    'raw-body': '2.4.0',
    'iconv-lite': '0.4.24',
    'safer-buffer': '2.1.2',
    'serve-static': '1.14.1',
    'opentelemetry-instrumentation-fetch-node': '1.2.3'
  }
}
{
  event_id: 'dd4f893143a64780ad946446c0806acc',
  originalException: Error: Test Sentry "JS Backend Error"
      at /Volumes/code/triplepoint/prtsr/prtsr/frontend/js-backend/src/server.ts:24:9
      at Layer.handle [as handle_request] (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/layer.js:95:5)
      at next (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/route.js:137:13)
      at Route.dispatch (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/route.js:112:3)
      at patched (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/@opentelemetry/instrumentation-express/src/instrumentation.ts:285:27)
      at Layer.handle [as handle_request] (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/layer.js:95:5)
      at /Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:281:22
      at Function.process_params (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:335:12)
      at next (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:275:10)
      at Function.handle (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:174:3),
  syntheticException: Error: Sentry syntheticException
      at ScopeClass.captureException (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/@sentry/node/node_modules/@sentry/core/src/scope.ts:513:32)
      at Object.captureException (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/@sentry/node/node_modules/@sentry/core/src/exports.ts:38:28)
      at sentryErrorMiddleware (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/@sentry/node/src/integrations/tracing/express.ts:125:60)
      at Layer.handle_error (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/layer.js:71:5)
      at trim_prefix (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:315:13)
      at /Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:284:7
      at Function.process_params (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:335:12)
      at Immediate.next (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:275:10)
      at Immediate.arguments.<computed> (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/@opentelemetry/instrumentation-express/src/instrumentation.ts:280:29)
      at Immediate.<anonymous> (/Volumes/code/triplepoint/prtsr/prtsr/frontend/node_modules/express/lib/router/index.js:635:15),
  mechanism: { type: 'middleware', handled: false },
  integrations: [
    'InboundFilters',       'FunctionToString',
    'LinkedErrors',         'RequestData',
    'Console',              'Http',
    'NodeFetch',            'OnUncaughtException',
    'OnUnhandledRejection', 'ContextLines',
    'LocalVariables',       'Context',
    'Modules',              'Express',
    'Fastify',              'Graphql',
    'Mongo',                'Mongoose',
    'Mysql',                'Mysql2',
    'Redis',                'Postgres',
    'Nest',                 'Hapi',
    'Koa',                  'Connect',
    'ProfilingIntegration', 'Debug'
  ]
}

andreiborza commented 4 weeks ago

Hello, thanks for writing in.

Could you please add debug: true to your init and paste the logs?

I also noticed you add the expressIntegration, this is not necessary anymore.

max-prtsr commented 4 weeks ago

@andreiborza

Sentry Logger [log]: Initializing Sentry: process: 44816, thread: main.
Sentry Logger [log]: Integration installed: InboundFilters
Sentry Logger [log]: Integration installed: FunctionToString
Sentry Logger [log]: Integration installed: LinkedErrors
Sentry Logger [log]: Integration installed: RequestData
Sentry Logger [log]: Integration installed: Console
Sentry Logger [log]: Integration installed: Http
Sentry Logger [log]: Integration installed: NodeFetch
Sentry Logger [log]: Integration installed: OnUncaughtException
Sentry Logger [log]: Integration installed: OnUnhandledRejection
Sentry Logger [log]: Integration installed: ContextLines
Sentry Logger [log]: Integration installed: LocalVariables
Sentry Logger [log]: Integration installed: Context
Sentry Logger [log]: Integration installed: Modules
Sentry Logger [log]: Integration installed: Express
Sentry Logger [log]: Integration installed: Fastify
Sentry Logger [log]: Integration installed: Graphql
Sentry Logger [log]: Integration installed: Mongo
Sentry Logger [log]: Integration installed: Mongoose
Sentry Logger [log]: Integration installed: Mysql
Sentry Logger [log]: Integration installed: Mysql2
Sentry Logger [log]: Integration installed: Redis
Sentry Logger [log]: Integration installed: Postgres
Sentry Logger [log]: Integration installed: Nest
Sentry Logger [log]: Integration installed: Hapi
Sentry Logger [log]: Integration installed: Koa
Sentry Logger [log]: Integration installed: Connect
Sentry Logger [log]: Integration installed: ProfilingIntegration
Sentry Logger [log]: Integration installed: Debug
Sentry Logger [log]: Running in CommonJS mode.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for diag v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for trace v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for context v1.9.0.
Sentry Logger [debug]: @opentelemetry/api: Registered a global for propagation v1.9.0.
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-express Applying instrumentation patch for module on require hook {
  module: 'express',
  version: '4.17.1',
  baseDir: '/xxx/node_modules/express'
}

chargome commented 4 weeks ago

Hey @max-prtsr , is there a reason why you manually add these headers to your request on the python side? They should be attached automatically anyway if you're using the requests library. Could you try omitting these and check if the automatic propagation works?

max-prtsr commented 3 weeks ago

They should be attached automatically anyway if you're using the requests library.

@chargome either you're missing something or sentry python is truly broken.

If sentry modifies ALL outer requests it means I'll 100% remove it and stop paying moving to anything else. Silently adding headers to outgoing requests in my production system feels like a ticking time bomb.

Could you please provide the exact part of documentation about it?

UPD: Yes, if I remove manual request patching then it works. Now please tell me how to turn it off by default, it's a serious problem I don't want to deal with in the future, https://developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Access-Control-Allow-Headers

mydea commented 3 weeks ago

You can find information about trace propagation in general, as well as about how to disable this, here: https://docs.sentry.io/platforms/javascript/guides/node/tracing/trace-propagation/#disabling-distributed-tracing

Note that only in Node headers are automatically attached, where CORS is not an issue. In the browser, headers are not automatically attached to external URLs, to avoid CORS issues.

chargome commented 3 weeks ago

@max-prtsr

For python:

Documentation about injecting tracing information to http requests.

Documentation about limiting propagation targets.

getsentry / sentry-javascript