Using Sentry breadcrumbs and tags alongside OpenTelemetry isn't working correctly #7538
Comments
|
Hey @seeARMS, thanks for writing in! To isolate your breadcrumbs/tags, you need to use our express request handler! // The request handler must be the first middleware on the app
app.use(Sentry.Handlers.requestHandler());This should make sure sentry data is isolated.
Yes, we need to adjust our docs for this, using dependency injected propagator is more correct than the global propagation API. Will fix! |
|
Created getsentry/sentry-docs#6501 and #7548 to update the docs! |
|
You shouldn't need to use the The Need to reproduce this, will try tomorrow! If you could provide a quick repro, would be a huge help as well! Also 👋 to fellow uwaterloo grad ^^ |
|
Here's a repro: https://github.com/seeARMS/sentry-javascript-7538-reproduction Clone it, run Here's an event in question that was logged using the repro (no breadcrumb present): https://paragraph.sentry.io/performance/node:f116399485744a8ab2452906b6d39fee/?environment=sentry-reproduction&project=6606495&query=&referrer=performance-transaction-summary&statsPeriod=2m&transaction=GET+%2F&unselectedSeries=p100%28%29 And hello! Always great to see other uWaterloo grads in the wild 😄 |
|
Hey @seeARMS thank you so much for the reproduction! Took me a while to debug, but the issue is due to inconsistency between how we isolate requests and how opentelemetry isolates requests. I opened a PR to fix this: #7577 Thank you for your patience while we figured it out - this will be part of the next release of the SDK (going out end of week). |
|
Nice! Thanks for the quick turn-around; really appreciate it! |
|
@AbhiPrasad, this seems to be happening again - did anything change in Sentry or OpenTelemtry? A given transaction seems to have a lot of tags, breadcrumbs, and console.logs from other requests. Using @sentry/node and @sentry/opentelemtry-node version 7.61.1. |
|
Hey, apologies for the trouble - let's try to figure out what's happening. Looking at https://github.com/getsentry/sentry-javascript/commits/develop/packages/opentelemetry-node nothing must have changed for the top level otel integration, but maybe it was a regression with the core functionality or otel itself. Did you upgrade your node version since then? Also could you share your otel version? A reproduction would help sped up the investigation. I don't have a ton of bandwidth next couple days, @mydea could you help take a look? |
|
I cloned my existing repo above (https://github.com/seeARMS/sentry-javascript-7538-reproduction), updated all dependencies to the latest using Using the old dependencies (eg cloning the repo above as-is) shows Sentry working as intended: ➜ npm run start
npm WARN cli npm v9.8.1 does not support Node.js v17.8.0. This version of npm supports the following node versions: `^14.17.0 || ^16.13.0 || >=18.0.0`. You can find the latest version at https://nodejs.org/.
> start
> node --require ./tracing.js app.js
Sentry Logger [log]: Integration installed: InboundFilters
Sentry Logger [log]: Integration installed: FunctionToString
Sentry Logger [log]: Integration installed: Console
Sentry Logger [log]: HTTP Integration is skipped because of instrumenter configuration.
Sentry Logger [log]: Integration installed: Http
Sentry Logger [log]: Integration installed: Undici
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: RequestData
Sentry Logger [log]: Integration installed: LinkedErrors
Sentry Logger [log]: Integration installed: ProfilingIntegration
http server listening on port 8085
Sentry Logger [log]: [Tracing] starting undefined transaction - GET
Sentry Logger [log]: [Profiling] started profiling transaction: GET
Sentry Logger [log]: [Tracing] Starting '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Finishing '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Starting '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Finishing '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Starting '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Finishing '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Starting '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Sentry Logger [log]: [Tracing] Finishing '< unknown op >' span on transaction 'GET' (9cfa7e02b183fb92).
Triggered route
Sentry Logger [log]: [Profiling] stopped profiling of transaction: GET /
Sentry Logger [log]: [Tracing] Finishing http.server transaction: GET /.
Sentry Logger [log]: [Tracing] starting undefined transaction - POST
Sentry Logger [log]: [Profiling] started profiling transaction: POST
After upgrading all deps to the latest, no Sentry debug lines showing that tracing or profiling is working: ➜ npm run start
> start
> node --require ./tracing.js app.js
Sentry Logger [log]: Integration installed: InboundFilters
Sentry Logger [log]: Integration installed: FunctionToString
Sentry Logger [log]: Integration installed: Console
Sentry Logger [log]: HTTP Integration is skipped because of instrumenter configuration.
Sentry Logger [log]: Integration installed: Http
Sentry Logger [log]: Integration installed: Undici
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: RequestData
Sentry Logger [log]: Integration installed: LinkedErrors
Sentry Logger [log]: Integration installed: ProfilingIntegration
http server listening on port 8085
Triggered routeHere are my OTEL versions of the prod install: I don't believe I've upgraded Node. |
|
Thank you for the repro! I digged into it, and it seems the problem is It works for me with these dependencies: I need to dig a bit further, but there are two relevant changes in 0.41.1 --> 0.41.2:
(just looking at the "not capturing at all" issue right now, not yet into breadcrumbs) |
|
Some further digging, I opened an issue for the grpc instrumentation here: open-telemetry/opentelemetry-js#4053 |
|
Thanks! Saw your comments. Upgraded all @sentry package to 7.65.0 and confirmed the GrpcInstrumentation is instantiated after the HTTPinstrumentation and tags/breadcrumbs are still not getting logged correctly. |
Can you share some more details on what is not happening correctly:
It would also be helpful if you are on SaaS if you could share the link of one or two events/transactions that have incorrect data added to them! |
|
I am not sure that is actually the case - I rewrote the code to completely bypass the logging library and use Sentry directly in a new middleware and it is still not working. Example request with mixed-up breadcrumbs using this new code: https://paragraph.sentry.io/performance/node:bba0b8e75eb54d98897cbeb403ab5076/?environment=paragraph-master&project=6606495&query=http.method%3APOST&statsPeriod=5m&transaction=POST+%2Ftasks%2Fpublish export function customLoggerMiddleware(
req: Request,
res: Response,
next: NextFunction
) {
const createCustomLogger = (baseLogger: any) => {
const handleLogging = (level: SeverityLevels, args: any[]) => {
Sentry.setTags(FLY_TAGS)
if (args.length > 0) {
if (typeof args[0] === "object" && !Array.isArray(args[0])) {
Sentry.setTags(args[0])
}
// ... snip, some custom logic to handle breadcrumbData
Sentry.addBreadcrumb(breadcrumbData)
if (level === "error") {
Sentry.captureException(new Error(args[messageIndex]))
}
}
}
baseLogger[level](...args)
}
return new Proxy(baseLogger, {
get: (target, property) => {
if (
["debug", "info", "error", "fatal", "warn"].includes(
property as string
)
) {
return (...args: any[]) => {
handleLogging(property as SeverityLevels, args)
}
} else if (property === "child") {
if ("fields" in target) {
setSentryTagsFromFields(target.fields)
}
// Ensure custom behavior is applied to child loggers
return (options: any) => createCustomLogger(target.child(options))
}
return target[property]
},
})
}
// Apply custom logger only if it hasn't been applied before
if (!req.log || !req.__isCustomLogger) {
const originalLogger = req.log
req.log = createCustomLogger(originalLogger)
req.__isCustomLogger = true
}
next()
}This is used in app.use(customLoggerMiddleware) |
|
Can you share what other Parts of the SDK you used and in what order? You may need to wrap your middleware in |
|
That didn't seem to have fixed it. Here is the relevant code: // init_sentry.ts
import * as Sentry from "@sentry/node"
import { ProfilingIntegration } from "@sentry/profiling-node"
export default function initSentry(app: any) {
Sentry.init({
dsn: "snip"
// Disable entirely on non-production environments.
enabled: !!isProduction,
debug: !!process.env.SENTRY_DEBUGGING,
includeLocalVariables: true,
release: process.env.COMMIT,
environment: process.env.FLY_APP_NAME || "development",
tracesSampler: (samplingContext) => {
if (checkIfSentryIgnore(samplingContext?.request?.url)) return 0
if (process.env.SENTRY_DEBUGGING) {
return 1.0
}
return TRACE_SAMPLE_PERCENTAGE
},
profilesSampleRate: 1.0, // Profiling sample rate is relative to tracesSampleRate
integrations: [
new Sentry.Integrations.OnUncaughtException({
// We handle our own exceptions.
exitEvenIfOtherHandlersAreRegistered: false,
}),
// @ts-ignore
new ProfilingIntegration(),
new Sentry.Integrations.Http({ tracing: true }),
new Sentry.Integrations.Express({ app }),
],
})
}
// app.ts
import f from "dotenv-flow"
f.config()
import initSentry from "./init_sentry"
import express from "express"
const app = express()
initSentry(app)
import * as Sentry from "@sentry/node"
app.use(Sentry.Handlers.requestHandler())
app.use(Sentry.Handlers.tracingHandler())
const { logger: gcpLogger, mw } = await lb.express.middleware({
logName: "api-" + process.env.FLY_APP_NAME,
level: "debug",
maxEntrySize: 200000,
})
app.use(mw)
// This is the Sentry logger middleware above
app.use(customLoggerMiddleware)
// lots of other middleware and routes
app.use(Sentry.Handlers.errorHandler())
const port = process.env.PORT || 8080
const server = app.listen(port, () => {
logger.info(
`HTTP server listening on port ${port} `
)
})
|
|
Generally looks good. I think whatever the baseLogger is doing might lose the async context that isolates requests. |
|
@seeARMS How are you getting I am only getting: {
samplingContext: {
transactionContext: { name: 'GET', parentSampled: undefined },
parentSampled: undefined
}
}and looking at the implementation of |
We'll adjust this (still WIP) so that the |
Any pointers how to workaround this meanwhile? |
|
I'll open a PR to add this for the next release! |
|
See: #10426 |
|
Moving this here, out of the PR - reply to #10426 (comment):
const traceparentData = spanToTraceHeader(span);
const dynamicSamplingContext = dynamicSamplingContextToSentryBaggageHeader(
getDynamicSamplingContextFromSpan(span),
);
const contentMeta = `<head>
<meta name="sentry-trace" content="${traceparentData}"/>
<meta name="baggage" content="${dynamicSamplingContext}"/>
`;Should work? |
@mydea The span accepted by these methods is not the same as what is returned by OpenTelemetry's |
|
This was useful: /**
* @see https://github.com/getsentry/sentry-javascript/blob/8bec42e0285ee301e8fc9bcaf02046daf48e0495/packages/core/src/utils/spanUtils.ts#L103
*/
export const spanIsSampled = (span: opentelemetry.api.Span) => {
const { traceFlags } = span.spanContext();
// eslint-disable-next-line no-bitwise
return Boolean(traceFlags & 0x1);
}; |
Ah right, of course - this work is still WIP. In v8, spans will be the same everywhere - you will generally get OpenTelemetry Spans everywhere when interacting with spans. We hope to have a alpha version of this in a few weeks, where you should be able to have a fully integrated experience with the Sentry SDK & OpenTelemetry! |
Any other suggestions on what I can do here? I'm a bit at my wits end and have spent far too long trying to get this to work |
|
@seeARMS Nope I am lost. Either we have a bug in the SDK or your logger is the offender. Can you reproduce this with a minimal setup and share it with us? That would be amazing! |
Is there an existing issue for this?
How do you use Sentry?
Sentry Saas (sentry.io)
Which SDK are you using? If you use the CDN bundles, please specify the exact bundle (e.g.
bundle.tracing.min.js) in your SDK setup.@sentry/node
SDK Version
7.43.0
Framework Version
No response
Link to Sentry event
https://paragraph.sentry.io/performance/node:08b586a3e77243548a96ac02db296d0f/?project=6606495&query=&statsPeriod=5m&transaction=POST+%2Fmetrics%2Fpost-track
SDK Setup
Steps to Reproduce
I've been happily using Sentry for some time. using @sentry/node with Express.
Today we switched from using Sentry tracing to OpenTelemetry-based tracing, using @sentry/opentelemetry-node. Transactions are getting logged fine, but it appears that breadcrumbs and tags are not correctly added to the transaction.
Viewing any Sentry event (eg the one linked above) has tags from what seems like other requests. Additionally, the breadcrumbs also don't correspond to this request.
There's a chance I'm doing something incorrect in Sentry.init() above. For example, I don't need to use any Sentry tracing functionality now that I have OpenTelemtry tracing working, right? The documentation here is a bit light so it's unclear to me.
Additionally, I'm getting an exception on startup (see logs below).
Expected Result
I'd expect to be able to use
Sentry.addBreadcrumbandSentry.addTagthroughout the codebase, and it would add the breadcrumb and tag to the current transaction/span created by Opentelemetry.Actual Result
I get this non-fatal exception on startup:
If I replace the NodeSDK init with the following, the error goes away, but I don't know if it's actually using SentryPropagator now:
The text was updated successfully, but these errors were encountered: