Sentry produces incorrect data when async code is involved

[srcspider]

• Review the documentation: https://docs.sentry.io/
• Search for existing issues: https://github.com/getsentry/sentry-javascript/issues
• Use the latest release: https://github.com/getsentry/sentry-javascript/releases

Package + Version

• @sentry/node

Version:

6.13.3

Description

When dealing with async code sentry fails to properly record data. Not only does it fail to record data, it also constantly adds bad data.

Exception 1: The problem is somewhat hidden when you deal with a context that sits in a sandbox environment which only exists for the duration of ONE AND ONLY ONE transaction. The most popular example would be a browser session, but since we're speaking node scenarios the other example would be a "cloud function" (ie. pops into existence per request, and only ever handles hopefully the one transactions); there's also the scenarios that use actual threads (which are rare in the current ecosystem). Needless to say, those 3 I just mentioned are also technically only fine so long as they use only one transactions; if more then one is used for any reason they're suddenly going to have bad data.

Exception 2: The problem is also hidden when transactions are completely dependent on user input (eg. user has to click some navigation item) and also happen faster then user input. This creates an artificial serial nature to them, hiding the fact that if more then one run at once they botch things since no more then one would ever run at once. However, the more complex the system, the less likely this exception will save you.

The problem is most evident and most aggravating in the scenario of a http server (which arguably covers a lot of the use cases for sentry with nodejs). Since a http server will pickup requests and work on them as-they-come, regardless of if the previous one is finished, sentry has to work perfectly with 2, 3, 1000 transactions running simultaneously.

In general, with your average http server (and similar use cases), it's your job to keep your stuff in one request out of the others. This isn't particularly hard normally since all it means is: don't use globals. Unfortunately sentry seems to do just that, for everything.

I've read though maybe 50 issues, and this problem has been brought before under various forms, some more direct then others. The solution has also been mentioned several times. And I've also seen the reply of "works for us" with the not-very obvious subtext "in this environment where only one transaction would ever exist before the process exists".

So, I'll make this very very simple, by giving you some code you can easily run (and is in accordence to what your documentation, responses to issues, etc are saying is the "correct way") along with screenshots of your dashboards with datapoints that are as obvious as I can possibly make them for you.

---

There will be only one file, so just copy all the blocks in a main.mjs file; .mjs is the current nodejs of saying the file uses modern imports.

First some basic boilerplate.

import Sentry from '@sentry/node';

const SENTRY_DSN = ""; // add your test project DSN here

Sentry.init({

	dsn: SENTRY_DSN,

	release: 'v1', // increment to get clean test sample

	// Set tracesSampleRate to 1.0 to capture 100%
	// of transactions for performance monitoring.
	// We recommend adjusting this value in production
	tracesSampleRate: 1.0

});

Next we'll add a function to help simulate "real world long async operations"

async function delay(time, fn) {
	return new Promise((resolve) => {
		setTimeout(async () => {
			resolve(await fn());
		}, time);
	});
}

Next we'll add a function that simulates all the breadcrumbs sentry adds whenever some random 3rd party library is used god knows where in dependencies. The parameter theRealTransaction is only used to make it obvious what the breadcrumbs and spans actually originate from.

async function randomThirdPartyIntegration(theRealTransaction) {

	// eg. "Got" library or whatever you guys are doing that's capturing HTTP

	// This context intentionally doesn't have access to objects in parameters
	// or other methods since that's how it typically happens in the real world.

	let hub = Sentry.getCurrentHub();
	let scope = hub.getScope();
	let transaction = scope.getTransaction();

	let span;
	if (transaction) {
		span = transaction.startChild({
			op: 'http_req',
			description: `http://google.com (real transaction: ${theRealTransaction})`
		});
	}

	scope.addBreadcrumb({
		category: 'http',
		message: `REQ http://google.com [Start] (real transaction: ${theRealTransaction})`
	});

	return await delay(300, () => {
		scope.addBreadcrumb({
			category: 'http',
			message: `REQ http://google.com [End] (real transaction: ${theRealTransaction})`
		});
		if (span) {
			span.finish();
		}
	});

}

Next we'll create a function that simulates what may happen in typical http server (or whatever else) request handle; we'll call it exampleInput since it will be the only function that takes input in theory (our randomThirdPartyIntegration is also a dependency of it).

Edit 1: Original function had incorrect tag code. (As such tags errors were ignored, does not affect rest of issue) Scope has been added to exception handler, to be even more correct. (Still produces same problems)

async function exampleInput ({
	name, // the name of this transaction
	user, // the user for the transaction
	throwsError,
	timers: { // delays between actions
		action1,
		action2,
		action3
	}
}) {

	const tagName = name.replace('#', '');

	const hub = Sentry.getCurrentHub();
	const scope = hub.pushScope();

	scope.setUser({ username: user });

	const transaction = hub.startTransaction({
		op: "test",
		name: `Test Transaction ${name}`,
	});

	scope.setSpan(transaction);

	try {

		// Tag

		scope.setTag(`T${tagName} Tag 1`, 'yes');

		// Action 1

		let span1 = transaction.startChild({
			op: 'action',
			description: `Transaction ${name} Action #1`
		})

		try {
			await delay(action1, () => {
				scope.addBreadcrumb({
					category: 'step',
					message: `Transaction ${name} Action #1`
				});
			});
		}
		finally {
			span1.finish();
		}

		// Tag

		scope.setTag(`T${tagName} Tag 2`, 'yes')

		// Action 2

		let span2 = transaction.startChild({
			op: 'action',
			description: `Transaction ${name} Action #2`
		})

		try {
			await delay(action2, () => {
				scope.addBreadcrumb({
					category: 'step',
					message: `Transaction ${name} Action #2`
				});
			});
		}
		finally {
			span2.finish();
		}

		// Random Third Party Dependency

		let span3 = transaction.startChild({
			op: 'third_party',
			description: `Transaction ${name} Third-Party Thing`
		});

		try {
			await randomThirdPartyIntegration(name);
		}
		finally {
			span3.finish();
		}

		// Tag

		scope.setTag(`T${tagName} Tag 3`, 'yes')

		if (throwsError) {
			throw new Error("Test Error: Something went wrong");
		}

		// Action 3

		let span4 = transaction.startChild({
			op: 'action',
			description: `Transaction ${name} Action #3`
		});

		try {
			await delay(action3, () => {
				scope.addBreadcrumb({
					category: 'step',
					message: `Transaction ${name} Action #3`
				});
			});
		}
		finally {
			span4.finish();
		}

		// Tag

		scope.setTag(`T${tagName} Tag 4`, 'yes');

	}
	catch (err) {
		Sentry.captureException(err, scope)
	}
	finally {
		hub.popScope();
		transaction.finish();
	}

}

And, finally we'll simulate some transactions. I've included a Timeline, but be aware that the timeline isn't something that will necessarily happen guaranteed as it suggests, its simply where the current settings in the example actually align if plotted on a timeline.

// The following simulates what a basic http server would do
// We don't wait for one transaction to finish before other starts because
// no sane server in the world does that sh*t

// a1 = action1, a2 = action2, a3 = action3
//
// Timeline (ms)      0        300  400  500  600  700  800  900  1000  1100
// -----------------------------------------------------------------------------
// Transaction 1      start              a1             a2              a3
// Transaction 2      start    a1             a2             a3
// Transaction 3      start         a1             a2             a3
// Transaction 3      start                   a1   a2 -> err

exampleInput ({
	name: '#1',
	user: 'transaction1_user',
	throwsError: false,
	timers: {
		action1: 500,
		action2: 300,
		action3: 300
	}
})

exampleInput ({
	name: '#2',
	user: 'transaction2_user',
	throwsError: false,
	timers: {
		action1: 300,
		action2: 300,
		action3: 300
	}
})

exampleInput ({
	name: '#3',
	user: 'transaction3_user',
	throwsError: false,
	timers: {
		action1: 400,
		action2: 300,
		action3: 300
	}
})

exampleInput ({
	name: '#4',
	user: 'transaction4_user',
	throwsError: true,
	timers: {
		action1: 600,
		action2: 100,
		action3: 100
	}
})

To run this just do. (after you provide the SENTRY_DSN)

node ./main.mjs

You can also change the release to have a clean copy you can filter to in transactions.

---

Now lets look at what sentry has to say after running it once. I'll highlight all the mistakes I can spot with red arrows (there may be more).

In the above transaction 1 doesn't have a user, even though we set user on every transactions.

Above is Transaction 1. We're missing the spans generated by the randomThirdPartyIntegration function itself, and we're missing all breadcrumbs.

Second transaction is also incorrect.

Third transaction somehow got wrong user and for some reason managed to miss the 3rd action breadcrumb.

Fourth transaction also got wrong user and also has 3rd party spans from transaction 2 and 3.

The 4th transaction was set to also throw a error. Above we can see what we get in the error. Why are we getting in the error breadcrumbs that never appear in the transactions themselves?

---

Anyway, so how is this fixed?

Technically speaking there are three approaches.

The first is to use is to use Async Context Tracking that is made available as stable api from nodejs 16 onwards. This doesn't solve all the problems with how (from a quick glance at the code) sentry seems to work, but it does mean sentry is able to consistently get the real context with out the use of globals. Specifically the only parts it doesnt' solve are how sentry currently works with scope; which is not even clear to me how exactly this "ever merging" scope is suppose to work with what is essentially "isolated contexts" (eg. http requests, work queues, etc)

The second method will work in all versions of node, including prior versions (and people paranoid about perf impact of async context tracking), and the method is to just REQUIRE every operation pass the transaction object. So things like Sentry.captureException(err) should really be Sentry.captureException(err, transaction) where the transaction is ignored if null (and I mean IGNORED, no guessing of what it might be, there is none). Scope should just be transaction.getScope().

The third method, and this is purely only for these special cases that sentry devs claim "works for them" is to have a method Sentry.setMasterTransaction that works as follows: if no transaction is set, set the transaction as the master; if a master is already set and not finished then error out and invalidate the master and the current transaction; if the master is set but finished (not counting transport costs), replace the current master with the new transaction. Essentially, you can have your "global transaction" but sentry guarantees you won't shoot yourself in the foot with it.

[andreialecu]

I'm not super familiar with the sentry api yet but captureException does take a second parameter which can be set to the scope:

Sentry.captureException(err, scope), if you add the scope there does it help?

[srcspider]

@andreialecu I've added that and also updated the original post, no significant change, still bleed everywhere and otherwise incorrect data. I've also fixed a problem with the tag code (was wrong originally).

Tag code is now correct in original post. And yes the data around tags is wrong. Note: given usage, each transaction should have unique tags.

[andreialecu]

Indeed, I just took a look at the code here:

sentry-javascript/packages/hub/src/hub.ts

Lines 132 to 148 in 99f9b55

	public pushScope(): Scope {
	// We want to clone the content of prev scope
	const scope = Scope.clone(this.getScope());
	this.getStack().push({
	client: this.getClient(),
	scope,
	});
	return scope;
	}
	/**
	* @inheritDoc
	*/
	public popScope(): boolean {
	if (this.getStack().length <= 1) return false;
	return !!this.getStack().pop();
	}

It seems evident that this isn't going to support async processes properly. The stack is a singleton, and popping and pushing from it might happen at any given time.

I notice some related discussion in #3572 along with a potential ugly workaround. I'm currently also running into this issue in my own projects and will investigate further.

[andreialecu]

A possible solution might be to instantiate a new Hub(client) instance manually on every "thread" and use that instead of using Sentry.getCurrentHub(); which seems to return a singleton.

The documentation does seem to hint at it here:
https://docs.sentry.io/platforms/javascript/enriching-events/scopes/#whats-a-scope-whats-a-hub

You can think of the hub as the central point that our SDKs use to route an event to Sentry. When you call init() a hub is created and a client and a blank scope are created on it. That hub is then associated with the current thread and will internally hold a stack of scopes.

This mentions it is associated with the current thread, but from what I can read from the code that doesn't happen. It's being reused for the entire app hence why events are all over the place.

Maybe you could check what happens if instead of let hub = Sentry.getCurrentHub(); you create a new hub instance.

[derekrprice]

@andreialecu, the problem with that is that your hub is still "global". There is no way to find the right one from an arbitrary location anymore than the right scope could be found. My workaround on #3572 fakes isolated scope by replacing withScope and getScope with versions that store a unique hash key in a function name that can be read later via a stack trace. It works fine but I haven't done any performance testing. The "right" way would be to use async context but, as the original poster noted, that isn't available until Node 16 and my team, at least, is still stuck using Node 14 for the time being. Perhaps the Sentry SDK could implement a fix using async context when it can and with my workaround implemented as a polyfill?

Sentry's response on #3572 has been that they can't implement this until they rewrite a bunch of other stuff, but I don't see why not. My workaround just replaces those two functions in a backwards compatible way.

Oh, @srcspider implies in his original post that this problem is hidden with "cloud functions", but this is just dependent on transaction volume and concurrency, just like with his HTTP server. This is exactly the case where we encountered the issue, with cloud functions processing hundreds of concurrent transactions. Sentry's scope and transaction tracking is almost useless in our environment. All the breadcrumb data for hundreds of transactions ends up getting submitted with a single transaction.

[andreialecu]

async_hooks has been experimental since node 8, so the implementation in node 14 is likely fine.

I have just been experimenting with it today in node 16 however, and it's seems it easily loses the context and doesn't integrate with EventEmitter.

Here are some reports:
nodejs/help#2537
nodejs/help#2546
nodejs/node#33723

In my case I'm not currently able to pass the context properly, it seems to be undefined. Probably because of the EventEmitter issue.

Edit: actually the problem is mongodb related ref: https://jira.mongodb.org/browse/NODE-3010 and Automattic/mongoose#10020 - so AsyncLocalStorage still comes with its own set of problems.

[andreialecu]

An update, I've been able to properly separate requests from what I can see from some initial tests.

The trick is this (I'm using a NestJS interceptor to isolate requests):

  async intercept(
    context: ExecutionContext,
    next: CallHandler,
  ): Promise<Observable<unknown>> {
    // trick is here (not sure if there's a better way to get the client)
    const client = this.sentry.instance().getCurrentHub().getClient();
    const hub = new Sentry.Hub(client);

    const transaction = hub.startTransaction({
      op: 'resolver',
      name: [context.getClass().name, context.getHandler().name].join('.'),
      tags: {
        class: context.getClass().name,
        handler: context.getHandler().name,
        // others
      },
    });

    hub.configureScope((scope) => {
      scope.setSpan(transaction);

      scope.setUser(sentryUser);
    });

    return new Observable((observer) => {
      runWithSentry(transaction, () => {
        next
          .handle()
          .pipe(
            tap({
              complete: () => {
                transaction.finish();
              },
              error: (exception) => {
                transaction.setStatus(SpanStatus.InternalError);
                transaction.finish();
                hub.withScope((scope) => {
                  if (req) {
                    const data = Sentry.Handlers.parseRequest({}, req);
                    scope.setExtra('req', data.request);
                    if (data.extra) scope.setExtras(data.extra);
                  }
                  scope.setUser(sentryUser);

                  hub.captureException(exception);
                });
              },
            }),
          )
          .subscribe({
            next: (res) => observer.next(res),
            error: (error) => observer.error(error),
            complete: () => observer.complete(),
          });
      });
    });
  }

It's important to call all methods on the hub instead of on the global Sentry object.

There's also this helper module for async hooks:

import { Transaction } from '@sentry/types';
import { AsyncLocalStorage } from 'async_hooks';

const storage = new AsyncLocalStorage<Transaction>();

export const getCurrentTransaction = (): Transaction | undefined =>
  storage.getStore();

export const runWithSentry = storage.run.bind(storage);

I'm now able to call const transaction = getCurrentTransaction(); elsewhere and get a proper reference to the transaction and add children to it.

Hope this helps.

[derekrprice]

@andreialecu, are you saying that this code works as a wrapper around the current SDK?

[andreialecu]

@derekrprice I just shared a sample of how I'm using it, hoping it helps. Not sure what you mean by wrapper.

[derekrprice]

@andreialecu, I just mean that your code is something that will work without modifying the current Sentry SDK, as opposed to a demonstration of how to fix the SDK. I think you just confirmed that. I should have some time to put it to the test next week. Thanks!

[andreialecu]

Yes, the sample above does not modify the SDK in any way, but I think the way it's being used is unconventional.

I'm not sure if any memory leaks would occur yet from creating new hub instances for every request. I haven't checked.

It also appears that it may repeatedly set up "integrations" unnecessarily on the client on each Hub instantiation:

sentry-javascript/packages/hub/src/hub.ts

Lines 124 to 126 in 111ea28

	if (client && client.setupIntegrations) {
	client.setupIntegrations();
	}

I'm hoping this issue gets triaged and we get an official response. The issue above can easily be solved with a PR.

[srcspider]

@andreialecu

I have just been experimenting with it today in node 16 however, and it's seems it easily loses the context and doesn't integrate with EventEmitter.

Here are some reports:
nodejs/help#2537
nodejs/help#2546
nodejs/node#33723

In all 3 example issues with problem from my understanding looking at them is that the functions in questions are not called, they're declared. The AsyncLocalStorage only works if it's called (I think), since the store only passes though functions that are called.

I haven't fully read though discussion there but seems all 3 are fixed by just doing something like binding the store to the callbacks, so it's available when they are called, then repassing it though a new AsyncLocalStorage call.

From my understanding (and it's more guessing) the rule of thumb with it should be that if it's not in your stacktrace it doesn't go though.

So in all those "doesn't work cases" you just do something like this... (copy paste everything in a single main.mjs file)

Boilerplate:

import { AsyncLocalStorage } from 'async_hooks';

const asyncLocalStorage = new AsyncLocalStorage();

Helper:

/**
 * Forces async store to pass though sync/async callback.
 */
function asyncstore_bind(fn) {
	let data = asyncLocalStorage.getStore();

	if (data != null) {
		return (...args) => {
			return asyncLocalStorage.run(data, () => {
				fn(...args)
			});
		}
	}
	// else: no store, just return the function as-is

	return fn;
}

We'll create something that takes a callback and uses it later (which is what all 3 of those issues seem to have)

class Example {

	handler = null;

	updateHandler(fn) {
		this.handler = fn;
	}

	runHandler(name) {
		this.handler(name);
	}

}

And now we run some test cases:

let expectedValue = 42;

// Bad Example (should not work)
// ===========

let test1 = new Example();

asyncLocalStorage.run(expectedValue, () => {
	test1.updateHandler(name => {
		let value = asyncLocalStorage.getStore();
		console.log(`${name}: ${expectedValue == value}`);
	})
});

test1.runHandler('Test 1')

// Good Example (should work)
// ============

let test2 = new Example();

asyncLocalStorage.run(expectedValue, () => {
	test2.updateHandler (
		asyncstore_bind (
			name => {
				let value = asyncLocalStorage.getStore();
				console.log(`${name}: ${expectedValue == value}`);
			}
		)
	)
});

test2.runHandler('Test 2');

// Good Example (async version)
// ============

let test3 = new Example();

asyncLocalStorage.run(expectedValue, () => {
	test3.updateHandler (
		asyncstore_bind (
			async (name) => {
				let value = asyncLocalStorage.getStore();
				console.log(`${name}: ${expectedValue == value}`);
			}
		)
	)
});

test3.runHandler('Test 3');

Output:

$ node main.mjs
Test 1: false
Test 2: true
Test 3: true

[andreialecu]

@srcspider it's not always that simple, unfortunately. Depending on which libraries you use, you can still lose the context in certain instances.

Take a look at https://stackoverflow.com/questions/64330910/nodejs-asynclocalstorage-getstore-return-undefined for some other reports about context being lost just by using bodyparser for express.

Also a report apollographql/apollo-server#2042 which also applies to AsyncLocalStorage about context being lost in Apollo server.

See the "Edit" I added in that post, in my case I'm using mongoose which uses mongodb via callbacks instead of promises internally. The callbacks lose the async local storage context. Without patching mongoose or mongodb this can't easily be fixed.

I have however found a workaround which I posted in Automattic/mongoose#10020 (comment)

Anyways, this discussion is a bit offtopic for this thread.

See my second post where I mentioned I got everything working. 🙂