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

continueTrace with startInactiveSpan does not work correctly with Sentry v8 #13126

Closed
3 tasks done
mikan3rd opened this issue Jul 31, 2024 · 14 comments
Closed
3 tasks done
Labels
Package: node Issues related to the Sentry Node SDK Type: Bug

Comments

@mikan3rd
Copy link

mikan3rd commented Jul 31, 2024

Is there an existing issue for this?

How do you use Sentry?

Sentry Saas (sentry.io)

Which SDK are you using?

@sentry/node

SDK Version

8.20.0

Framework Version

No response

Link to Sentry event

https://bizforward.sentry.io/issues/5659614696/events/e33fe93c614b41779919285369087372/

Reproduction Example/SDK Setup

No response

Steps to Reproduce

In Sentry v7, continueTrace is used as follows, and checking the Sentry Issue confirms that the traceId used in the frontend is successfully passed on to the backend.

  const server = new ApolloServer({
    context: async ({ req }): Promise<Context> => {
      const sentryTraceHeaders = req.headers['sentry-trace'];
      const sentryTrace = Array.isArray(sentryTraceHeaders) ? sentryTraceHeaders.join(',') : sentryTraceHeaders;
      const baggage = req.headers['baggage'];
      const sentrySpan = Sentry.continueTrace({ sentryTrace, baggage }, (transactionContext) => {
        return Sentry.startInactiveSpan({
          ...transactionContext,
          op: 'gql',
          name: req.body.operationName,
        });
      });
      return { sentrySpan };
    },
  );

In Sentry v8, the transactionContext argument of the continueTrace callback has been removed, so I changed the code as follows.
However, when I did so, the traceId displayed in Sentry's Issue was different for frontend and backend.

  const server = new ApolloServer({
    context: async ({ req }): Promise<Context> => {
      const sentryTraceHeaders = req.headers['sentry-trace'];
      const sentryTrace = Array.isArray(sentryTraceHeaders) ? sentryTraceHeaders.join(',') : sentryTraceHeaders;
      const baggage = req.headers['baggage'];
      const sentrySpan = Sentry.continueTrace({ sentryTrace, baggage }, () => {
        return Sentry.startInactiveSpan({
          op: 'gql',
          name: req.body.operationName,
        });
      });
      return { sentrySpan };
    },
  );

I would like to know the cause and countermeasures.

Do I have to use startSpan, and if I use ApolloServer, how do I use startSpan?

Expected Result

The trace ID in the Issue must match the sentryTrace in the request header.

Actual Result

The trace ID listed in the Issue does not match the sentryTrace in the request header.

@github-actions github-actions bot added the Package: node Issues related to the Sentry Node SDK label Jul 31, 2024
@mydea
Copy link
Member

mydea commented Jul 31, 2024

Hey,

do you actually need to manually continue the trace at all in v8? I would have thought that this should be automatically continued anyhow?

Looking at the issue you linked, I do see the span you started there connected to the frontend - If you click "View full trace" at the top of the issue, the trace contains a http.client span which has a child gql span. Is this not what you would expect? This seems correct to me! Or what would you expect differently?

Generally speaking, could you share your Sentry.init() code, and possibly the output when you configure debug: true? I think GraphQL/Apollo should be auto instrumented, you shouldn't really have to do anything yourself to get spans for this, I believe! Maybe there is a deeper setup issue there 🤔

@mikan3rd
Copy link
Author

mikan3rd commented Aug 1, 2024

Sorry, I didn't provide enough links to refer to.
See the following frontend and backend Issue.
"View full trace" shows that the trace ID allocated on the frontend side is not carried over on the backend side.

@mikan3rd
Copy link
Author

mikan3rd commented Aug 1, 2024

The following is the log

Log
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'https' }
Sentry Logger [debug]: Recording is off, propagating context in a non-recording span
Sentry Logger [debug]: @opentelemetry/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [debug]: @opentelemetry/instrumentation-http http.ClientRequest return request
Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on response()
Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on end()
Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on request close()
query: SELECT `User`.`id` AS `User_id`, `User`.`uid` AS `User_uid`, `User`.`email` AS `User_email`, `User`.`company_id` AS `User_company_id`, `User`.`created_at` AS `User_created_at`, `User`.`updated_at` AS `User_updated_at` FROM `users` `User` WHERE ((`User`.`uid` = ?)) LIMIT 1 -- PARAMETERS: ["CDx21CRc4Ub5QxqY6gOJjU7lqmU2"]
{
  sentryTrace: '15cfb66b7f894742af09b2338291fd77-90da34b18370fa7c-1',
  baggage: 'XXX'
}
Sentry Logger [log]: [Tracing] Inheriting remote parent's sampled decision for UserDashboardTemplateLatestLead: true
Sentry Logger [log]: [Tracing] Starting sampled root span
  op: gql
  name: UserDashboardTemplateLatestLead
  ID: c94eaf3187b58549
  parent ID: 90da34b18370fa7c
{
  sentrySpan: Span {
    attributes: {
      'sentry.op': 'gql',
      'sentry.sample_rate': 1,
      'sentry.parentIsRemote': true
    },
    links: [],
    events: [],
    _droppedAttributesCount: 0,
    _droppedEventsCount: 0,
    _droppedLinksCount: 0,
    status: { code: 0 },
    endTime: [ 0, 0 ],
    _ended: false,
    _duration: [ -1, -1 ],
    name: 'UserDashboardTemplateLatestLead',
    _spanContext: {
      traceId: '15cfb66b7f894742af09b2338291fd77',
      spanId: 'c94eaf3187b58549',
      traceFlags: 1,
      traceState: [TraceState]
    },
    parentSpanId: '90da34b18370fa7c',
    kind: 0,
    _performanceStartTime: 126573.554792,
    _performanceOffset: 0.185302734375,
    _startTimeProvided: false,
    startTime: [ 1722487020, 413000000 ],
    resource: Resource {
      _attributes: [Object],
      asyncAttributesPending: false,
      _syncAttributes: [Object],
      _asyncAttributesPromise: undefined
    },
    instrumentationLibrary: { name: '@sentry/node', version: '8.20.0', schemaUrl: undefined },
    _spanLimits: {
      attributeValueLengthLimit: Infinity,
      attributeCountLimit: 128,
      linkCountLimit: 128,
      eventCountLimit: 128,
      attributePerEventCountLimit: 128,
      attributePerLinkCountLimit: 128
    },
    _attributeValueLengthLimit: Infinity,
    _spanProcessor: MultiSpanProcessor { _spanProcessors: [Array] }
  }
}
[2024-08-01T04:37:00.416Z]  INFO: 44273 on mf-3145-mm01:  (userId=1)
    graphql: {
      "operationName": "UserDashboardTemplateLatestLead",
      "query": "query UserDashboardTemplateLatestLead {\n  latestLead {\n    leadSource\n    ...UserDetailTable\n    ...ApplicationDetailTable\n    ...NextLeadRegistration\n    ...BranchModalElements\n    __typename\n  }\n}\n\nfragment UserDetailTable on Lead {\n  id\n  lastName\n  firstName\n  company {\n    id\n    name\n    postalCode\n    prefecture\n    address1\n    address2\n    __typename\n  }\n  __typename\n}\n\nfragment ApplicationDetailTable on Lead {\n  id\n  createdAt\n  amount\n  preferredDateClass\n  preferredDate\n  purpose\n  __typename\n}\n\nfragment NextLeadRegistration on Lead {\n  sessionId\n  leadSource\n  __typename\n}\n\nfragment BranchModalElements on Lead {\n  amount\n  preferredDate\n  preferredDateClass\n  createdAt\n  __typename\n}",
      "variables": {}
    }
[2024-08-01T04:37:00.466Z] ERROR: 44273 on mf-3145-mm01:  (userId=1)
    errors: [
      {
        "name": "Error",
        "message": "Sentry Test2!!!",
        "stack": "Error: Sentry Test2!!!\n    at Object.<anonymous> (/Users/dev/src/app/resolvers/lead.ts:146:15)\n    at Generator.next (<anonymous>)\n    at /Users/dev/src/app/resolvers/lead.ts:8:71\n    at new Promise (<anonymous>)\n    at __awaiter (/Users/dev/src/app/resolvers/lead.ts:4:12)\n    at Object.latestLead (/Users/dev/src/app/resolvers/lead.ts:146:24)\n    at /Users/dev/node_modules/.pnpm/[email protected][email protected]/node_modules/graphql-middleware/dist/applicator.js:9:112\n    at middleware (/Users/dev/node_modules/.pnpm/[email protected][email protected][email protected][email protected]/node_modules/graphql-shield/cjs/generator.js:30:30)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)"
      }
    ]
[2024-08-01T04:37:00.467Z] ERROR: 44273 on mf-3145-mm01: Sentry Test2!!!
    formattedError: {
      "message": "Sentry Test2!!!",
      "locations": [
        {
          "line": 2,
          "column": 3
        }
      ],
      "path": [
        "latestLead"
      ],
      "extensions": {
        "code": "INTERNAL_SERVER_ERROR",
        "stacktrace": [
          "Error: Sentry Test2!!!",
          "    at Object.<anonymous> (/Users/dev/src/app/resolvers/lead.ts:146:15)",
          "    at Generator.next (<anonymous>)",
          "    at /Users/dev/src/app/resolvers/lead.ts:8:71",
          "    at new Promise (<anonymous>)",
          "    at __awaiter (/Users/dev/src/app/resolvers/lead.ts:4:12)",
          "    at Object.latestLead (/Users/dev/src/app/resolvers/lead.ts:146:24)",
          "    at /Users/dev/node_modules/.pnpm/[email protected][email protected]/node_modules/graphql-middleware/dist/applicator.js:9:112",
          "    at middleware (/Users/dev/node_modules/.pnpm/[email protected][email protected][email protected][email protected]/node_modules/graphql-shield/cjs/generator.js:30:30)",
          "    at processTicksAndRejections (node:internal/process/task_queues:95:5)"
        ]
      }
    }
    --
    err: {
      "message": "Sentry Test2!!!",
      "locations": [
        {
          "line": 2,
          "column": 3
        }
      ],
      "path": [
        "latestLead"
      ]
    }
Sentry Logger [log]: [Tracing] Finishing "gql" root span "UserDashboardTemplateLatestLead" with ID c94eaf3187b58549
Sentry Logger [log]: SpanExporter exported 1 spans, 0 unsent spans remaining

@Lms24
Copy link
Member

Lms24 commented Aug 1, 2024

Can you show us your Sentry.init call in your Apollo server? There are some suspicious logs that might hint some config problem:

Recording is off, propagating context in a non-recording span

I wonder why this is printed at all, given we're starting spans afterwards

Finishing "gql" root span "UserDashboardTemplateLatestLead" with ID c94eaf3187b58549

So this suggests to me that a span was actually started and sent but it's not connected to the error that was thrown in between.

Also, would you mind letting us know why you need to call continueTrace at all? This shouldn't be necessary if you initialize the SDK correctly.

@mikan3rd
Copy link
Author

mikan3rd commented Aug 1, 2024

The following is Sentry.init.

Code
  Sentry.init({
    dsn: process.env.SENTRY_DSN,
    environment: process.env.APP_ENV,
    enabled: true,
    debug: true,
    release: process.env.SENTRY_RELEASE,
    serverName: 'app',
    sampleRate: 1.0,
    tracesSampleRate: 1.0,
    normalizeDepth: 10,
    beforeSend(event, hint) {
      event.fingerprint = [
        '{{ default }}',
        event.exception?.values?.[0]?.type ?? '',
        event.exception?.values?.[0]?.value ?? '',
      ];
      return event;
    },
  });

  const server = new ApolloServer({
    context: async ({ req }): Promise<Context> => {
      const sentryTraceHeaders = req.headers['sentry-trace'];
      const sentryTrace = Array.isArray(sentryTraceHeaders) ? sentryTraceHeaders.join(',') : sentryTraceHeaders;
      const baggage = req.headers['baggage'];
      const sentrySpan = Sentry.continueTrace({ sentryTrace, baggage }, () => {
        return Sentry.startInactiveSpan({
          op: 'gql',
          name: req.body.operationName,
        });
      });
      return { sentrySpan };
    },
    plugins: [
      ApolloServerSentryPlugin,
    ],
  );

const ApolloServerSentryPlugin: ApolloServerPlugin<Context> = {
  requestDidStart: async () => ({
    didEncounterErrors: async ({ contextValue, errors, request }) => {
      errors.forEach((error) => {
        reportError(error, { cloudTraceId: contextValue.cloudTraceId, user: contextValue.user, request });
      });
    },
    willSendResponse: async ({ contextValue }) => {
      contextValue.sentrySpan?.end();
    },
  }),
};

export const reportError = (
  err: Error | GraphQLError,
  { cloudTraceId, request, user }: { cloudTraceId?: string; request?: GraphQLRequest; user?: Context['user'] },
) => {
  Sentry.withScope((scope) => {
    scope.setTag('cloud_trace_id', cloudTraceId);
    scope.setExtra('error', err);

    if (request) {
      const { operationName, query, variables } = request;
      scope.setTag('operationName', operationName);
      scope.setContext('Apollo Error', {
        operationName,
        query,
        variables,
      });
    }

    if (err instanceof GraphQLError && err.path) {
      scope.addBreadcrumb({
        category: 'query-path',
        message: err.path.join(' > '),
        level: 'debug',
      });
    }

    if (user) {
      scope.setUser({
        id: user.userId?.toString(),
        uid: user.uid,
        email: user.email,
      });
    }

    Sentry.captureException(err);
  });
};

@chargome
Copy link
Member

chargome commented Aug 1, 2024

@mikan3rd Did you try running your Apollo server without manually continuing the trace, or is there a specific reason for the code inside your context function?

@mikan3rd
Copy link
Author

mikan3rd commented Aug 2, 2024

I removed the code and the code about continueTrace, but the frontend and backend trace IDs remained different.

Log
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'http' }
Sentry Logger [debug]: @opentelemetry/instrumentation-http Applying instrumentation patch for nodejs core module on require hook { module: 'https' }
Sentry Logger [debug]: Recording is off, propagating context in a non-recording span
Sentry Logger [debug]: @opentelemetry/instrumentation-http https instrumentation outgoingRequest
Sentry Logger [debug]: @opentelemetry/instrumentation-http http.ClientRequest return request
Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on response()
Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on end()
Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on request close()
query: SELECT `User`.`id` AS `User_id`, `User`.`uid` AS `User_uid`, `User`.`email` AS `User_email`, `User`.`company_id` AS `User_company_id`, `User`.`created_at` AS `User_created_at`, `User`.`updated_at` AS `User_updated_at` FROM `users` `User` WHERE ((`User`.`uid` = ?)) LIMIT 1 -- PARAMETERS: ["9E9EqEuw59hzY9dT4N96ZSFpxk53"]
[2024-08-02T02:30:34.889Z]  INFO: 14387 on mf-3145-mm01:  (userId=27)
    graphql: {
      "operationName": "UserDashboardTemplateLatestLead",
      "query": "query UserDashboardTemplateLatestLead {\n  latestLead {\n    leadSource\n    ...UserDetailTable\n    ...ApplicationDetailTable\n    ...NextLeadRegistration\n    ...BranchModalElements\n    __typename\n  }\n}\n\nfragment UserDetailTable on Lead {\n  id\n  lastName\n  firstName\n  company {\n    id\n    name\n    postalCode\n    prefecture\n    address1\n    address2\n    __typename\n  }\n  __typename\n}\n\nfragment ApplicationDetailTable on Lead {\n  id\n  createdAt\n  amount\n  preferredDateClass\n  preferredDate\n  purpose\n  __typename\n}\n\nfragment NextLeadRegistration on Lead {\n  sessionId\n  leadSource\n  __typename\n}\n\nfragment BranchModalElements on Lead {\n  amount\n  preferredDate\n  preferredDateClass\n  createdAt\n  __typename\n}",
      "variables": {}
    }
[2024-08-02T02:30:34.923Z] ERROR: 14387 on mf-3145-mm01:  (userId=27)
    errors: [
      {
        "name": "Error",
        "message": "SentryTest3",
        "stack": "Error: SentryTest3\n    at Object.<anonymous> (/Users/dev/src/app/resolvers/lead.ts:146:15)\n    at Generator.next (<anonymous>)\n    at /Users/dev/src/app/resolvers/lead.ts:8:71\n    at new Promise (<anonymous>)\n    at __awaiter (/Users/dev/src/app/resolvers/lead.ts:4:12)\n    at Object.latestLead (/Users/dev/src/app/resolvers/lead.ts:146:24)\n    at /Users/dev/node_modules/.pnpm/[email protected][email protected]/node_modules/graphql-middleware/dist/applicator.js:9:112\n    at middleware (/Users/dev/node_modules/.pnpm/[email protected][email protected][email protected][email protected]/node_modules/graphql-shield/cjs/generator.js:30:30)\n    at processTicksAndRejections (node:internal/process/task_queues:95:5)"
      }
    ]
[2024-08-02T02:30:34.923Z] ERROR: 14387 on mf-3145-mm01: SentryTest3
    formattedError: {
      "message": "SentryTest3",
      "locations": [
        {
          "line": 2,
          "column": 3
        }
      ],
      "path": [
        "latestLead"
      ],
      "extensions": {
        "code": "INTERNAL_SERVER_ERROR",
        "stacktrace": [
          "Error: SentryTest3",
          "    at Object.<anonymous> (/Users/dev/src/app/resolvers/lead.ts:146:15)",
          "    at Generator.next (<anonymous>)",
          "    at /Users/dev/src/app/resolvers/lead.ts:8:71",
          "    at new Promise (<anonymous>)",
          "    at __awaiter (/Users/dev/src/app/resolvers/lead.ts:4:12)",
          "    at Object.latestLead (/Users/dev/src/app/resolvers/lead.ts:146:24)",
          "    at /Users/dev/node_modules/.pnpm/[email protected][email protected]/node_modules/graphql-middleware/dist/applicator.js:9:112",
          "    at middleware (/Users/dev/node_modules/.pnpm/[email protected][email protected][email protected][email protected]/node_modules/graphql-shield/cjs/generator.js:30:30)",
          "    at processTicksAndRejections (node:internal/process/task_queues:95:5)"
        ]
      }
    }
    --
    err: {
      "message": "SentryTest3",
      "locations": [
        {
          "line": 2,
          "column": 3
        }
      ],
      "path": [
        "latestLead"
      ]
    }

@mydea
Copy link
Member

mydea commented Aug 2, 2024

Could you paste the logs from application startup? The ones that show e.g. "Integration added...." plus everything until the app has settled/fully started up?

@mikan3rd
Copy link
Author

mikan3rd commented Aug 5, 2024

The following is the logs from application startup.

Logs
[INFO] 11:06:42 ts-node-dev ver. 2.0.0 (using ts-node ver. 10.9.2, typescript ver. 5.5.4)
Debugger listening on ws://127.0.0.1:9229/bbbfeaeb-b7ea-48d8-81fe-f15da2092a96
For help, see: https://nodejs.org/en/docs/inspector
Sentry Logger [log]: Initializing Sentry: process: 77113, 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: LocalVariablesAsync
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]: 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.
query: SELECT VERSION() AS `version`
[2024-08-05T02:07:18.579Z]  INFO: 77113 on mf-3145-mm01: 🚀  Server ready at http://localhost:4000/

@Lms24
Copy link
Member

Lms24 commented Aug 5, 2024

@mikan3rd looking at your Sentry.init code above and given that I don't see any logs about opentelemetry wrapping graphql (or related libraries): Can you confirm that you call Sentry.init before you require any other module? This is crucial to work for all our instrumentation, except for http(s). More information here.

@mikan3rd
Copy link
Author

mikan3rd commented Aug 20, 2024

Thanks for the reply.
I have managed to get trace to work by putting Sentry.init before all imports.
However, I am concerned that I am getting the following error after starting the server.
What is the problem?

Sentry Logger [debug]: @opentelemetry/instrumentation-http outgoingRequest on request error() Error: socket hang up
    at Socket.socketCloseListener (node:_http_client:473:25)
    at Socket.emit (node:events:531:35)
    at TCP.<anonymous> (node:net:339:12)
    at TCP.callbackTrampoline (node:internal/async_hooks:130:17) {
  code: ‘ECONNRESET’
}

@andreiborza
Copy link
Member

Hello @mikan3rd,

We are currently on company-wide hackweek and thus on limited support. We'll take a look at this next week.

@lforst
Copy link
Member

lforst commented Aug 26, 2024

@mikan3rd I believe this error can just be ignored. It may be something that your application swallowed up until now but since the SDK hooks in at quite a low level it surfaces it through a debug log. We don't have reason to believe the SDK causes a socket hangup.

@mikan3rd
Copy link
Author

My problem seems to be solved, thank you very much!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Package: node Issues related to the Sentry Node SDK Type: Bug
Projects
Archived in project
Development

No branches or pull requests

6 participants