fix(node): Remove ambiguity and race conditions when matching local variables to exceptions #13501
Conversation
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
size-limit report 📦
|
This reverts commit 7ac938f.
|
Ok so with the async debugger via worker, this results in a memory leak. I guess this needs some cleanup. |
|
Do we have to worry about object size with a large number of errors? Or a bunch of long lived error objects? Just trying to think if there's any edge cases with storing the local vars on the error objects themselves. If we forsee any problem with that, then similar to the original approach it might be worth still using an extra datastructure to actually store the local variable state -- and force a maximum size (like with the LRU) that's configurable. And then have some sort of pointer to it on the error object instead (like a unique id). re: memory leaks, I wonder if there's references to the error objects lingering around somewhere. I doubt the inspector api would write objects that are unable to be garbage collected, but I suppose it's possible if for some reason the inspector is holding references to the objects it made? 🤷 |
It might be worth adding a limit regardless of how we're passing the variables.
I've managed to fix the memory leak for the async version (Node > v19) by calling |
Niiiiiiiice, this makes sense! |
|
Oh it stopped the memory leak but also stopped it from working. Back to the drawing board 😂 |
This comment was marked as outdated.
This comment was marked as outdated.
| await session.post('Runtime.callFunctionOn', { | ||
| functionDeclaration: `function() { this.${LOCAL_VARIABLES_KEY} = ${JSON.stringify(frames)}; }`, | ||
| silent: true, | ||
| objectId: errorObjectId, | ||
| }); |
There was a problem hiding this comment.
I have one question - now that we are doing more inspector work while the main application is paused, do we have an idea of how much time awaiting on this Runtime.callFunctionOn takes?
I'm concerned that we might block the main thread (and by extension, the whole event loop) for long enough to be noticeable. I don't know how inspector performance scales with application size either, so it's possible it'd be more impactful on large codebases?
At minimum, is there an approach you recommend that would let us track how long we spend 'paused' before we resume execution? In my normal apps I'd maintain a prometheus metric here or something.
And further, if there's an approach that might let us do the session.post asynchronously and then have the sentry code wait for the data? Increases complexity but might fix this problem. Not worth doing before we know the performance impact of awaiting here, unless there's a good approach you can think of.
There was a problem hiding this comment.
The memory test code catches an error and captures it's local variables once every millisecond. console.time suggests that the debugger is paused for 0.3-0.4ms on my machine to do this.
Whether this has an impact on your app will likely depend on a lot of variables. We have rate limiting for caught exceptions and maxExceptionsPerSecond defaults to 50. Rate limiting initially disables capture for 5 seconds and every subsequent rate limit trigger doubles this wait time. We have no rate limiting for uncaught exceptions.
There was a problem hiding this comment.
Gotcha. If we're pausing on the order of a low single digit milliseconds I'm sure for 99% of use cases this is fine. at 50 exceptions per second and 1ms per exception that blocks the event loop for only 50ms per second.
At 10ms, that's 500ms blocked.
At 20ms that's an entire second blocked. Which would even prevent us from hitting the 50 exceptions per second 😅
So yeah as long as we keep execution time low then it's more than fine.
Is it maybe worth adding a WARN log line if any single error execution takes longer than eg. 5ms? That way if people are debugging their slow applications they would be able to see it's the fault of the debugger?
In general, I just want to find a way to avoid the case where turning this feature on introduces a huge performance problem in some edge case and application developers have no idea why. That can lead to a lot of frustration when they eventually realize it's from an observability SDK. If we can expose runtime information somehow, or if we're confident that won't ever be a problem, that solves my worry :)
Thoughts?
There was a problem hiding this comment.
Yep, it might be a good idea to change our rate-limiting to be based around total blocked time rather than number of paused events
There was a problem hiding this comment.
I think the happy middleground is some kind of dynamic backpressure detector, so we can adjust rate-limiting according to the volume of exceptions accordingly.
In our server-side SDKs (not node yet though), we do basic heuristic analysis to downsample outgoing events based on relative volume. Spec here: https://develop.sentry.dev/sdk/telemetry/traces/backpressure/. I assume we can take the larger general concept and apply it here.
Let's give this a try afterwards, we can scope it out further.
I'm glad that we've found a way that works. Something doesn't smell right to me about this though... What do you think is going on? You probably have a better idea than I do. |
Not only what the functions do, but how all the commands should be used together! You can get a reasonable idea by looking what others have done via Github search.
Unfortunately not. Most that I've learnt has been through a lot of trial and error. The Chrome debugger has a protocol inspector so you can see the commands it's sending and learn a bit from that. From what I've observed, |
|
Hey @timfish I just tried this branch in my local with and without delaying Can you double check on your end? |
|
I'll be back looking at this on Monday evening on my way back from vacation. The e2e test failures in CI suggested that the delay was required but I'll double check it. |
While we get local variables without the delay in releasing, we still get a memory leak. It looks like |
Nice find. That sounds incredibly annoying to have found. This is awesome though, it makes the whole local variables integration much simpler and much more robust 💪 |
|
Plot twist... While |
Honestly, that is equal parts interesting and terrifying. Feels like we're relying on undefined behaviour somehow 😭 |
|
You know, if it were easy to do bisecting to the exact v8 engine version that introduces that behaviour change would probably reveal a lot about the internals of nodejs/the inspector/object releasing. I suspect the best way to do that is to checkout nodejs@ v22.x and bisect through But uhh, that's pretty time consuming for a probably-useless-except-for-knowledge outcome lol. Maaaybe it'd be a bug in v8, which would be cool i guess 🤷 . Or maybe this is just undefined behaviour with no guarantees because their api docs don't specify anything >.< More just saying this out loud to myself. Would be neat but won't pay the bills :'( |
Yeah, feels like this entire debug API is prone to race conditions.
Could try more node versions to find an exact version where it changes. If it ends up on a v8 upgrade, the changeset will be huge 😭
Even if we find a bug in v8, it's unlikely a fix would make it into an LTS Node version anyway. We'd need to cherry pick that fix and apply it to older v8 versions which might be too much work. It could also be a bug in the |
timfish
requested review from
Bruno-DaSilva,
mydea and
AbhiPrasad
and removed request for
Bruno-DaSilva
| function addLocalVariablesToEvent(event: Event, hint: EventHint): Event { | ||
| if ( | ||
| hint.originalException && | ||
| typeof hint.originalException === 'object' && | ||
| LOCAL_VARIABLES_KEY in hint.originalException && | ||
| Array.isArray(hint.originalException[LOCAL_VARIABLES_KEY]) | ||
| ) { | ||
| for (const exception of event.exception?.values || []) { | ||
| addLocalVariablesToException(exception, hint.originalException[LOCAL_VARIABLES_KEY]); | ||
| } | ||
|
|
||
| hint.originalException[LOCAL_VARIABLES_KEY] = undefined; |
There was a problem hiding this comment.
in both here and the worker, is it worth adding some kind of debug logging for when the sdk is in debug mode?
There was a problem hiding this comment.
I think we can validate it pretty easily by inspecting the event in beforeSend, so I think we don't explicitly need logging for every event, but @timfish if you think it's a good idea go for it.
There was a problem hiding this comment.
There's also the discussion over whether some of our logging here should be behind debug: true or regular console.*. If we hit rate limiting maybe this should always be logged rather than only when debug is enabled? Users are unlikely to have debug logging enabled in production but it's likely useful to know when you're hitting rate limiting.
There was a problem hiding this comment.
Finally catching up after vacation, thanks for all the help @Bruno-DaSilva!! I'll start reading through all the issues and leaving comments now 😄.
Could try more node versions to find an exact version where it changes. If it ends up on a v8 upgrade, the changeset will be huge 😭
If we can get a minimal reproduction going we should write up a Node.js ticket, I can help ping people to take a look. I don't think we should investigate it further until we can get help from them.
| } | ||
|
|
||
| // Only hash the 10 most recent frames (ie. the last 10) | ||
| return frames.slice(-10).reduce((acc, frame) => `${acc},${frame.function},${frame.lineno},${frame.colno}`, ''); |
There was a problem hiding this comment.
I wonder if we should filter out system frames here, so basically either
- pick all the frames (if less than 10)
- pick 10 most recent frames (after filtering out system frames)
There was a problem hiding this comment.
This code is for the sync debugger has simply been copied from ./common.ts as it's no longer common between the two implementations. I probably should have left it there! The sync debugger has seen no changes other than the moving of this code.
| function addLocalVariablesToEvent(event: Event, hint: EventHint): Event { | ||
| if ( | ||
| hint.originalException && | ||
| typeof hint.originalException === 'object' && | ||
| LOCAL_VARIABLES_KEY in hint.originalException && | ||
| Array.isArray(hint.originalException[LOCAL_VARIABLES_KEY]) | ||
| ) { | ||
| for (const exception of event.exception?.values || []) { | ||
| addLocalVariablesToException(exception, hint.originalException[LOCAL_VARIABLES_KEY]); | ||
| } | ||
|
|
||
| hint.originalException[LOCAL_VARIABLES_KEY] = undefined; |
There was a problem hiding this comment.
I think we can validate it pretty easily by inspecting the event in beforeSend, so I think we don't explicitly need logging for every event, but @timfish if you think it's a good idea go for it.
| await session.post('Runtime.callFunctionOn', { | ||
| functionDeclaration: `function() { this.${LOCAL_VARIABLES_KEY} = ${JSON.stringify(frames)}; }`, | ||
| silent: true, | ||
| objectId: errorObjectId, | ||
| }); |
There was a problem hiding this comment.
I think the happy middleground is some kind of dynamic backpressure detector, so we can adjust rate-limiting according to the volume of exceptions accordingly.
In our server-side SDKs (not node yet though), we do basic heuristic analysis to downsample outgoing events based on relative volume. Spec here: https://develop.sentry.dev/sdk/telemetry/traces/backpressure/. I assume we can take the larger general concept and apply it here.
Let's give this a try afterwards, we can scope it out further.
|
Gonna go ahead and merge this in. |
This PR contains the following updates: | Package | Type | Update | Change | |---|---|---|---| | [@sentry/node](https://github.com/getsentry/sentry-javascript/tree/master/packages/node) ([source](https://github.com/getsentry/sentry-javascript)) | dependencies | minor | [`8.26.0` -> `8.30.0`](https://renovatebot.com/diffs/npm/@sentry%2fnode/8.26.0/8.30.0) | | [@sentry/react](https://github.com/getsentry/sentry-javascript/tree/master/packages/react) ([source](https://github.com/getsentry/sentry-javascript)) | dependencies | minor | [`8.26.0` -> `8.30.0`](https://renovatebot.com/diffs/npm/@sentry%2freact/8.26.0/8.30.0) | --- ### Release Notes <details> <summary>getsentry/sentry-javascript (@​sentry/node)</summary> ### [`v8.30.0`](https://github.com/getsentry/sentry-javascript/blob/HEAD/CHANGELOG.md#8300) [Compare Source](getsentry/sentry-javascript@8.29.0...8.30.0) ##### Important Changes - *feat(node): Add `kafkajs` integration ([#​13528](getsentry/sentry-javascript#13528 This release adds a new integration that instruments `kafkajs` library with spans and traces. This integration is automatically enabled by default, but can be included with the `Sentry.kafkaIntegration()` import. ```js Sentry.init({ integrations: [Sentry.kafkaIntegration()], }); ``` ##### Other Changes - feat(core): Allow adding measurements without global client ([#​13612](getsentry/sentry-javascript#13612)) - feat(deps): Bump [@​opentelemetry/instrumentation-undici](https://github.com/opentelemetry/instrumentation-undici) from 0.5.0 to 0.6.0 ([#​13622](getsentry/sentry-javascript#13622)) - feat(deps): Bump [@​sentry/cli](https://github.com/sentry/cli) from 2.33.0 to 2.35.0 ([#​13624](getsentry/sentry-javascript#13624)) - feat(node): Use `@opentelemetry/instrumentation-undici` for fetch tracing ([#​13485](getsentry/sentry-javascript#13485)) - feat(nuxt): Add server config to root folder ([#​13583](getsentry/sentry-javascript#13583)) - feat(otel): Upgrade [@​opentelemetry/semantic-conventions](https://github.com/opentelemetry/semantic-conventions) to 1.26.0 ([#​13631](getsentry/sentry-javascript#13631)) - fix(browser): check supportedEntryTypes before caling the function ([#​13541](getsentry/sentry-javascript#13541)) - fix(browser): Ensure Standalone CLS span timestamps are correct ([#​13649](getsentry/sentry-javascript#13649)) - fix(nextjs): Widen removal of 404 transactions ([#​13628](getsentry/sentry-javascript#13628)) - fix(node): Remove ambiguity and race conditions when matching local variables to exceptions ([#​13501](getsentry/sentry-javascript#13501)) - fix(node): Update OpenTelemetry instrumentation package for solidstart and opentelemetry ([#​13640](getsentry/sentry-javascript#13640)) - fix(node): Update OpenTelemetry instrumentation package for solidstart and opentelemetry ([#​13642](getsentry/sentry-javascript#13642)) - fix(vue): Ensure Vue `trackComponents` list matches components with or without `<>` ([#​13543](getsentry/sentry-javascript#13543)) - ref(profiling): Conditionally shim cjs globals ([#​13267](getsentry/sentry-javascript#13267)) Work in this release was contributed by [@​Zen-cronic](https://github.com/Zen-cronic) and [@​odanado](https://github.com/odanado). Thank you for your contributions! ### [`v8.29.0`](https://github.com/getsentry/sentry-javascript/blob/HEAD/CHANGELOG.md#8290) [Compare Source](getsentry/sentry-javascript@8.28.0...8.29.0) ##### Important Changes - **Beta releases of official Solid and SolidStart Sentry SDKs** This release marks the beta releases of the `@sentry/solid` and `@sentry/solidstart` Sentry SDKs. For details on how to use them, check out the [Sentry Solid SDK README](https://github.com/getsentry/sentry-javascript/tree/develop/packages/solid) and the [Sentry SolidStart SDK README](https://github.com/getsentry/sentry-javascript/tree/develop/packages/solidstart) respectively. Please reach out on [GitHub](https://github.com/getsentry/sentry-javascript/issues/new/choose) if you have any feedback or concerns. - **feat(node): Option to only wrap instrumented modules ([#​13139](getsentry/sentry-javascript#13139 Adds the SDK option to only wrap ES modules with `import-in-the-middle` that specifically need to be instrumented. ```javascript import * as Sentry from '@​sentry/node'; Sentry.init({ dsn: '__PUBLIC_DSN__', registerEsmLoaderHooks: { onlyIncludeInstrumentedModules: true }, }); ``` - **feat(node): Update OpenTelemetry packages to instrumentation v0.53.0 ([#​13587](getsentry/sentry-javascript#13587 All internal OpenTelemetry instrumentation was updated to their latest version. This adds support for Mongoose v7 and v8 and fixes various bugs related to ESM mode. ##### Other Changes - feat(nextjs): Emit warning when using turbopack ([#​13566](getsentry/sentry-javascript#13566)) - feat(nextjs): Future-proof Next.js config options overriding ([#​13586](getsentry/sentry-javascript#13586)) - feat(node): Add `generic-pool` integration ([#​13465](getsentry/sentry-javascript#13465)) - feat(nuxt): Upload sourcemaps generated by Nitro ([#​13382](getsentry/sentry-javascript#13382)) - feat(solidstart): Add `browserTracingIntegration` by default ([#​13561](getsentry/sentry-javascript#13561)) - feat(solidstart): Add `sentrySolidStartVite` plugin to simplify source maps upload ([#​13493](getsentry/sentry-javascript#13493)) - feat(vue): Only start UI spans if parent is available ([#​13568](getsentry/sentry-javascript#13568)) - fix(cloudflare): Guard `context.waitUntil` call in request handler ([#​13549](getsentry/sentry-javascript#13549)) - fix(gatsby): Fix assets path for sourcemaps upload ([#​13592](getsentry/sentry-javascript#13592)) - fix(nextjs): Use posix paths for sourcemap uploads ([#​13603](getsentry/sentry-javascript#13603)) - fix(node-fetch): Use stringified origin url ([#​13581](getsentry/sentry-javascript#13581)) - fix(node): Replace dashes in `generic-pool` span origins with underscores ([#​13579](getsentry/sentry-javascript#13579)) - fix(replay): Fix types in WebVitalData ([#​13573](getsentry/sentry-javascript#13573)) - fix(replay): Improve replay web vital types ([#​13602](getsentry/sentry-javascript#13602)) - fix(utils): Keep logger on carrier ([#​13570](getsentry/sentry-javascript#13570)) Work in this release was contributed by [@​Zen-cronic](https://github.com/Zen-cronic). Thank you for your contribution! ### [`v8.28.0`](https://github.com/getsentry/sentry-javascript/blob/HEAD/CHANGELOG.md#8280) [Compare Source](getsentry/sentry-javascript@8.27.0...8.28.0) ##### Important Changes - **Beta release of official NestJS SDK** This release contains the beta version of `@sentry/nestjs`! For details on how to use it, check out the [README](https://github.com/getsentry/sentry-javascript/blob/master/packages/nestjs/README.md). Any feedback/bug reports are greatly appreciated, please reach out on GitHub. - **fix(browser): Remove faulty LCP, FCP and FP normalization logic ([#​13502](getsentry/sentry-javascript#13502 This release fixes a bug in the `@sentry/browser` package and all SDKs depending on this package (e.g. `@sentry/react` or `@sentry/nextjs`) that caused the SDK to send incorrect web vital values for the LCP, FCP and FP vitals. The SDK previously incorrectly processed the original values as they were reported from the browser. When updating your SDK to this version, you might experience an increase in LCP, FCP and FP values, which potentially leads to a decrease in your performance score in the Web Vitals Insights module in Sentry. This is because the previously reported values were smaller than the actually measured values. We apologize for the inconvenience! ##### Other Changes - feat(nestjs): Add `SentryGlobalGraphQLFilter` ([#​13545](getsentry/sentry-javascript#13545)) - feat(nestjs): Automatic instrumentation of nestjs interceptors after route execution ([#​13264](getsentry/sentry-javascript#13264)) - feat(nextjs): Add `bundleSizeOptimizations` to build options ([#​13323](getsentry/sentry-javascript#13323)) - feat(nextjs): Stabilize `captureRequestError` ([#​13550](getsentry/sentry-javascript#13550)) - feat(nuxt): Wrap config in nuxt context ([#​13457](getsentry/sentry-javascript#13457)) - feat(profiling): Expose profiler as top level primitive ([#​13512](getsentry/sentry-javascript#13512)) - feat(replay): Add layout shift to CLS replay data ([#​13386](getsentry/sentry-javascript#13386)) - feat(replay): Upgrade rrweb packages to 2.26.0 ([#​13483](getsentry/sentry-javascript#13483)) - fix(cdn): Do not mangle \_metadata ([#​13426](getsentry/sentry-javascript#13426)) - fix(cdn): Fix SDK source for CDN bundles ([#​13475](getsentry/sentry-javascript#13475)) - fix(nestjs): Check arguments before instrumenting with `@Injectable` ([#​13544](getsentry/sentry-javascript#13544)) - fix(nestjs): Ensure exception and host are correctly passed on when using [@​WithSentry](https://github.com/WithSentry) ([#​13564](getsentry/sentry-javascript#13564)) - fix(node): Suppress tracing for transport request execution rather than transport creation ([#​13491](getsentry/sentry-javascript#13491)) - fix(replay): Consider more things as DOM mutations for dead clicks ([#​13518](getsentry/sentry-javascript#13518)) - fix(vue): Correctly obtain component name ([#​13484](getsentry/sentry-javascript#13484)) Work in this release was contributed by [@​leopoldkristjansson](https://github.com/leopoldkristjansson), [@​mhuggins](https://github.com/mhuggins) and [@​filips123](https://github.com/filips123). Thank you for your contributions! ### [`v8.27.0`](https://github.com/getsentry/sentry-javascript/blob/HEAD/CHANGELOG.md#8270) [Compare Source](getsentry/sentry-javascript@8.26.0...8.27.0) ##### Important Changes - **fix(nestjs): Exception filters in main app module are not being executed ([#​13278](getsentry/sentry-javascript#13278 With this release nestjs error monitoring is no longer automatically set up after adding the `SentryModule` to your application, which led to issues in certain scenarios. You will now have to either add the `SentryGlobalFilter` to your main module providers or decorate the `catch()` method in your existing global exception filters with the newly released `@WithSentry()` decorator. See the [docs](https://docs.sentry.io/platforms/javascript/guides/nestjs/) for more details. ##### Other Changes - feat: Add options for passing nonces to feedback integration ([#​13347](getsentry/sentry-javascript#13347)) - feat: Add support for SENTRY_SPOTLIGHT env var in Node ([#​13325](getsentry/sentry-javascript#13325)) - feat(deps): bump [@​prisma/instrumentation](https://github.com/prisma/instrumentation) from 5.17.0 to 5.18.0 ([#​13327](getsentry/sentry-javascript#13327)) - feat(feedback): Improve error message for 403 errors ([#​13441](getsentry/sentry-javascript#13441)) - fix(deno): Don't rely on `Deno.permissions.querySync` ([#​13378](getsentry/sentry-javascript#13378)) - fix(replay): Ensure we publish replay CDN bundles ([#​13437](getsentry/sentry-javascript#13437)) Work in this release was contributed by [@​charpeni](https://github.com/charpeni). Thank you for your contribution! </details> --- ### Configuration 📅 **Schedule**: Branch creation - At any time (no schedule defined), Automerge - At any time (no schedule defined). 🚦 **Automerge**: Disabled by config. Please merge this manually once you are satisfied. ♻ **Rebasing**: Whenever PR becomes conflicted, or you tick the rebase/retry checkbox. 🔕 **Ignore**: Close this PR and you won't be reminded about these updates again. --- - [ ] <!-- rebase-check -->If you want to rebase/retry this PR, check this box --- This PR has been generated by [Renovate Bot](https://github.com/renovatebot/renovate). <!--renovate-debug:eyJjcmVhdGVkSW5WZXIiOiIzOC41NS4zIiwidXBkYXRlZEluVmVyIjoiMzguNzMuNyIsInRhcmdldEJyYW5jaCI6Im1haW4iLCJsYWJlbHMiOlsiZGVwZW5kZW5jaWVzIl19--> Reviewed-on: https://git.tristess.app/alexandresoro/ouca/pulls/61 Reviewed-by: Alexandre Soro <code@soro.dev> Co-authored-by: renovate <renovate@git.tristess.app> Co-committed-by: renovate <renovate@git.tristess.app>
Closes #13415
This PR only modifies the async version of this integration which is used for Node > v19. I tried applying similar changes to the sync integration and I cannot get it to work without causing memory leaks.
@Bruno-DaSilva has been helping me explore different ways to fix a few fundamental issues with the local variables integration. Bruno found a way to write to the error object from the debugger which removes any ambiguity over which variables go with which exception.
This allows us to remove the stack parsing and hashing which we were using previously to match up exceptions.
Rather than write the
objectIdto the error, I have used this to write the entire local variables array directly to the error object. This completely negates the need to post the local variables from the worker thread which removes any possibility of race conditions. We then later pull the local variables directly fromhint.originalException.__SENTRY_ERROR_LOCAL_VARIABLES__.