sentry-javascript icon indicating copy to clipboard operation
sentry-javascript copied to clipboard

Sentry produces incorrect data when async code is involved

Open srcspider opened this issue 2 years ago • 28 comments

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

Package + Version

  • [x] @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).

transactions

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

transaction1

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

transaction2

Second transaction is also incorrect.

transaction3

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

transaction4

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

error

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.

srcspider avatar Oct 16 '21 21:10 srcspider

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?

andreialecu avatar Oct 19 '21 09:10 andreialecu

@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.

image

image

image

srcspider avatar Oct 19 '21 13:10 srcspider

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

https://github.com/getsentry/sentry-javascript/blob/99f9b5580d80b167e2d833fbc0e22972ab59b016/packages/hub/src/hub.ts#L132-L148

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 https://github.com/getsentry/sentry-javascript/issues/3572 along with a potential ugly workaround. I'm currently also running into this issue in my own projects and will investigate further.

andreialecu avatar Oct 19 '21 13:10 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.

andreialecu avatar Oct 19 '21 13:10 andreialecu

@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.

derekrprice avatar Oct 19 '21 15:10 derekrprice

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: https://github.com/nodejs/help/issues/2537 https://github.com/nodejs/help/issues/2546 https://github.com/nodejs/node/issues/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 https://github.com/Automattic/mongoose/issues/10020 - so AsyncLocalStorage still comes with its own set of problems.

andreialecu avatar Oct 19 '21 15:10 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.

andreialecu avatar Oct 19 '21 17:10 andreialecu

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

derekrprice avatar Oct 19 '21 17:10 derekrprice

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

andreialecu avatar Oct 19 '21 17:10 andreialecu

@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!

derekrprice avatar Oct 19 '21 19:10 derekrprice

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:

https://github.com/getsentry/sentry-javascript/blob/111ea284047f54f50dadb075be2fc4d367b826a0/packages/hub/src/hub.ts#L124-L126

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

andreialecu avatar Oct 19 '21 20:10 andreialecu

@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

srcspider avatar Oct 20 '21 08:10 srcspider

@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 https://github.com/apollographql/apollo-server/issues/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 https://github.com/Automattic/mongoose/issues/10020#issuecomment-946908407

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

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

andreialecu avatar Oct 20 '21 08:10 andreialecu

Scope propogation for async code is something we are aware of, but would require breaking changes to fully address: https://github.com/getsentry/sentry-javascript/issues/3751. It's on our radar though, we are actively thinking about the problem for both node and browser.

Also, async hook support is something we are considering also. See: https://github.com/getsentry/sentry-javascript/issues/3660

AbhiPrasad avatar Oct 21 '21 14:10 AbhiPrasad

@AbhiPrasad I've been able to work around this by creating a hub via (ref: https://github.com/getsentry/sentry-javascript/issues/4071#issuecomment-946935926):

const client = Sentry.getCurrentHub().getClient();
const hub = new Sentry.Hub(client);

Then I can call methods and start transactions on that hub instance instead of the global sentry object and things properly get isolated.

Is this the right approach? I haven't seen it documented, and the global hub is unusable in nodejs otherwise (as explained in the OP).

andreialecu avatar Oct 21 '21 14:10 andreialecu

Yup explicit propagation of hubs and scopes will always work - the issues arise when you try to implicitly propagate it (such as when you have automatic instrumentation of libraries). In the case of implicit propagation, the auto-instrumentation has to "pick" the correct hub/scope to call methods on, which breaks down in async environments. Using async hooks and domains is the way to work toward a solution here.

On the browser though, this is still something that needs to be figured out (unless one uses a library like https://www.npmjs.com/package/zone.js)

AbhiPrasad avatar Oct 21 '21 14:10 AbhiPrasad

We have further discussion about this here: https://develop.sentry.dev/sdk/research/performance/#scope-propagation

AbhiPrasad avatar Oct 21 '21 15:10 AbhiPrasad

@AbhiPrasad, have you had a look at my code on #3572? It works around the async issue without changing the Sentry SDK API by taking advantage of the fact that JS stack traces preserve the correct call chain even with async functions. Using that fact, it moves the scope stack into an object and uses a withScope() method to wrap anything you wish to trace with a function with a name containing the nested scope's key for that object. Basically, the technique should work as a polyfill for the async context feature available after node 1.16. I read through your associated links, but I still don't understand why this isn't an acceptable way to find the correct nested scope. Can you be more specific? Thanks!

derekrprice avatar Oct 21 '21 17:10 derekrprice

Yup we have @derekrprice - your polyfill is a great way to approach a possible solution - though some care would have to be put in to manage call stack issues.

We actually want to extend the API so that users can select whatever scope management strategy they prefer - hence we are waiting for the next major version to roll out these changes. So for example, you can use async storage, your solution, or something completely custom.

The hope is that this will scale so that we can have a common scope propagation API that node, browser, electron, react native, and any other js platform can all share.

AbhiPrasad avatar Oct 21 '21 18:10 AbhiPrasad

@AbhiPrasad

Scope propogation for async code is something we are aware of, but would require breaking changes to fully address: #3751. It's on our radar though, we are actively thinking about the problem for both node and browser.

I assume it's on radar for v8? since v7 doesn't have it: https://github.com/getsentry/sentry-javascript/milestone/7

the issues arise when you try to implicitly propagate it (such as when you have automatic instrumentation of libraries)

Do you have an option or workaround to disable all of that? I assume that's not a "breaking change" to add.

[edit]

Also want to mention that, while it causes probably problems in browsers too (read though your research paper), I actually don't care as much there as I do for a nodejs server. It's just so aggrieving on nodejs compared to the browser.

Also solutions like the client/hub one from @andreialecu should just be in your docs.

srcspider avatar Oct 21 '21 19:10 srcspider

@AbhiPrasad

Yup explicit propagation of hubs and scopes will always work

In my opening post example, replacing all instances of Sentry. with hub created via @andreialecu's method and even passing hub to the randomThirdPartyIntegration and only using that will mostly work and is sure hell of a lot better then nothing, BUT breadcrumbs will vanish on all transactions, users will not get recorded on all transactions and tags will not get recorded on all transactions. The error will however have the user, tags and breadcrumbs (and correct ones at that). So yes a lot better, but far from "will always work"

You may need to revisit other aspects of what exactly Sentry does vs just hub does. Since there's either an extra step or something else to make it a full workaround.

srcspider avatar Oct 21 '21 19:10 srcspider

users will not get recorded on all transactions

Users are being logged for all transactions for me and I have a relatively high traffic app, make sure you attach the user to the transaction. This seems to work for me:

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

andreialecu avatar Oct 21 '21 19:10 andreialecu

Tested a bunch of variations. You're right only passing any scope change though hub.configureScope over and over seems to work. Trying to use things like const scope = hub.pushScope(); while in theory should work (since the configureScope method is only grabbing the top scope) they only actually produce anything when used with the Sentry global version and produce nothing when used with the explicit hub version.

Thanks @andreialecu

srcspider avatar Oct 21 '21 20:10 srcspider

For anyone stumbling on this, here's a wrapper.

Only tested on my original example code (which doesn't cover all cases). Still, produces perfect result when refactored to use the wrapper; including when randomThirdPartyIntegration is refactored to use the wrapper's findTransaction method that uses async_hooks.

import Sentry from '@sentry/node';
import { AsyncLocalStorage } from 'async_hooks';
import { Client, Hub, Span, SpanContext, Transaction, User } from '@sentry/types';

const TrasanctionStorage = new AsyncLocalStorage<TracerTransaction>();

type SpanOptions = Pick<SpanContext, "status" | "tags" | "startTimestamp" | "endTimestamp" | "data">;

enum TracerSeverity {
    Fatal = "fatal",
    Error = "error",
    Warning = "warning",
    Log = "log",
    Info = "info",
    Debug = "debug",
    Critical = "critical"
}

enum TracerSpanStatus {
    /** The operation completed successfully. */
    Ok = "ok",
    /** Deadline expired before operation could complete. */
    DeadlineExceeded = "deadline_exceeded",
    /** 401 Unauthorized (actually does mean unauthenticated according to RFC 7235) */
    Unauthenticated = "unauthenticated",
    /** 403 Forbidden */
    PermissionDenied = "permission_denied",
    /** 404 Not Found. Some requested entity (file or directory) was not found. */
    NotFound = "not_found",
    /** 429 Too Many Requests */
    ResourceExhausted = "resource_exhausted",
    /** Client specified an invalid argument. 4xx. */
    InvalidArgument = "invalid_argument",
    /** 501 Not Implemented */
    Unimplemented = "unimplemented",
    /** 503 Service Unavailable */
    Unavailable = "unavailable",
    /** Other/generic 5xx. */
    InternalError = "internal_error",
    /** Unknown. Any non-standard HTTP status code. */
    UnknownError = "unknown_error",
    /** The operation was cancelled (typically by the user). */
    Cancelled = "cancelled",
    /** Already exists (409) */
    AlreadyExists = "already_exists",
    /** Operation was rejected because the system is not in a state required for the operation's */
    FailedPrecondition = "failed_precondition",
    /** The operation was aborted, typically due to a concurrency issue. */
    Aborted = "aborted",
    /** Operation was attempted past the valid range. */
    OutOfRange = "out_of_range",
    /** Unrecoverable data loss or corruption */
    DataLoss = "data_loss"
}

class TracerSpan {

    public parent: TracerTransaction;
    public alreadyFinished: boolean = false;
    public span: Span;

    constructor (
        parent: TracerTransaction,
        op: string,
        description: string,
        opts: SpanOptions = {}
    ) {
        this.parent = parent;
        if ( ! parent.noop) {
            this.span = parent.transaction.startChild({
                op, description, ...opts
            })
        }
    }

    status(status: TracerSpanStatus): TracerSpan {
        this.span?.setStatus(status);
        return this;
    }

    httpStatus(httpStatus: number): TracerSpan {
        this.span?.setHttpStatus(httpStatus);
        return this;
    }

    ok(): TracerSpan {
        this.span?.setStatus(TracerSpanStatus.Ok);
        return this;
    }

    end(): void {
        if (this.alreadyFinished) {
            throw new Error('Span end() called multiple times.');
        }

        if (this.parent.alreadyFinished) {
            throw new Error('Span end() called after transaction ended.');
        }

        this.alreadyFinished = true;
        this.span?.finish();
    }
}

class TracerTransaction {

    public noop: boolean;

    public hub: Hub;
    public transaction: Transaction;
    public alreadyFinished: boolean = false;

    constructor() {
        this.noop = true; // by default unstarted, do nothing
    }

    start (
        op: string,
        name: string,
    ): void {
        this.noop = false;

        const client = Sentry.getCurrentHub().getClient();
        this.hub = new Sentry.Hub(client);

        this.transaction = this.hub.startTransaction({ op, name });

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

    /**
     * Binds transaction to context and executes context.
     * Returns whatever context returns.
     */
    bind<T>(context: (...args: any[]) => T): T {
        return TrasanctionStorage.run(this, context);
    }

    /**
     * Start new Span on the transaction.
     */
    span (
        op: string,
        description: string,
        opts: SpanOptions = {}
    ): TracerSpan {
        return new TracerSpan (
            this, op, description, opts
        );
    }

    setUser(user: User): TracerTransaction {
        this.hub?.configureScope(scope => {
            scope.setUser(user);
        });

        return this;
    }

    addTag (
        tagName: string,
        value: string | number
    ): TracerTransaction {
        this.hub?.configureScope(scope => {
            scope.setTag(tagName, value);
        });

        return this;
    }

    addBreadcrumb (
        category: string,
        message: string,
        type: string = null,
        severity: TracerSeverity = TracerSeverity.Info,
        data?: {
            [key: string]: any;
        }
    ): TracerTransaction {
        this.hub?.configureScope(scope => {
            scope.addBreadcrumb({
                category,
                message,
                type,
                level: Sentry.Severity.fromString(severity),
                data
            });
        });

        return this;
    }

    end(): void {
        if (this.alreadyFinished) {
            throw new Error('Transaction end() called multiple times.');
        }

        this.alreadyFinished = true;
        this.transaction.finish();
    }

    captureError(err: any): void {
        if (this.hub) {
            this.hub.captureException(err);
        }
        else { // no huh (ie. noop mode)
            Sentry.captureException(err);
        }
    }

    captureMessage (
        message: string,
        severity: TracerSeverity = TracerSeverity.Info
    ): void {
        if (this.hub) {
            this.hub.captureMessage(message, Sentry.Severity.fromString(severity));
        }
        else { // no huh (ie. noop mode)
            Sentry.captureMessage(message, Sentry.Severity.fromString(severity));
        }
    }

}

export class Tracer {

    // used only by setMasterTransaction / getMasterTransaction
    protected static master: TracerTransaction;

    /**
     * Optional functionality. Ideally just ensure you never have to find it
     * and always just know it by placing it in some context of the unit of
     * work in question.
     */
    static findTransaction(): TracerTransaction {
        let transaction: TracerTransaction | null
            = TrasanctionStorage.getStore() as TracerTransaction;

        if (transaction) {
            return transaction;
        }
        else { // failed to find transaction; just return a noop version
            return new TracerTransaction();
        }
    }

    /**
     * Limited in functionality due to use of global, but avoids use
     * of async_hooks for situations where they are not available and there's
     * only ever one transaction or transactions can be guranteed to
     * happen in a series (rather then parallel).
     *
     * See: getMaster
     */
    static setMaster(transaction: TracerTransaction): void {
        if (this.master && ! this.master.alreadyFinished) {
            throw new Error('Tried to set new master while current master was still ongoing.');
        }

        this.master = transaction;
    }

    /**
     * Limited in functionality due to use of global, but avoids use
     * of async_hooks for situations where they are not available.
     *
     * See: setMaster
     */
    static getMaster(): TracerTransaction {
        if (this.master && ! this.master.alreadyFinished) {
            // this isn't fully correct, but better then nothing
            return this.master;
        }
        else { // no master transaction was set; just return noop
            return new TracerTransaction();
        }
    }

    /**
     * Create new transaction and start it.
     *
     * Use the method transaction.bind if you wish to propagate the
     * transaction via async_hooks
     */
    static transaction (
        op: string,
        name: string
    ): TracerTransaction {
        let transaction = new TracerTransaction();
        transaction.start(op, name);
        return transaction;
    }

}

Usage

const transaction = Tracer.transaction (
    "test", `Test Transaction ${name}`
);
transaction.setUser({ username: user });
transaction.addTag(`T${tagName} Tag 1`, 'yes');
transaction.addBreadcrumb (
    'step', `Transaction ${name} Action #1`
);
await transaction.bind(async () => {
    await randomThirdPartyIntegration(name);
});
// at any level after you called transaction.bind on something
const transaction = Tracer.findTransaction(); // returns noop version if it doesn't find one
try {
    // ...
}
catch (err) {
    transaction.captureError(err)
}
finally {
    transaction.end();
}

etc

srcspider avatar Oct 22 '21 19:10 srcspider

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!


"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

github-actions[bot] avatar Nov 12 '21 21:11 github-actions[bot]

I've been looking into this issue and it seems that the code in the very first comment is not reflective of how the http handler in Sentry works i.e. Sentry.Handlers.requestHandler

When you include this piece of middleware in your request handling pipeline, it will create a new "domain":

https://github.com/getsentry/sentry-javascript/blob/2f2d099dcc668f12109913caf36097f73a1bc966/packages/node/src/handlers.ts#L412-L418

My understanding is that code run inside the domain callback (i.e. local.run(callback)) has its own storage, which you can use be checking the domain.active export. The last line in that code block runs getCurrentHub inside the domain, checks to see if the domain has a current hub (which it does not, to start with) and then creates one on the fly while running the getCurrentHub function via setHubOnCarrier:

https://github.com/getsentry/sentry-javascript/blob/2f2d099dcc668f12109913caf36097f73a1bc966/packages/hub/src/hub.ts#L591-L594

Could that not solve all your problems without having to write so much code? If you want to create a repository with your use case I can try and see how you can use the "domain" approach to solve it, in a way that is highly compatible with the rest of the Sentry SDK

The problem that I'm running into that lead me here is related, but possibly not the same. A hub can only have a "stack" of scopes, so pushing a new scope onto the stack only works if your spans are running sequentially

If you have concurrent async code that runs in parallel inside a single transaction, the "stack of scopes" does not allow implicit instrumentation to bind correctly. I am also hoping to use domain.create() and local.run() to trick the implicit code into grabbing the correct hub

mattfysh avatar Dec 23 '21 09:12 mattfysh

We're using uWebSockets.js and seem to have come across the same general problem. We have long-running sessions that run concurrently and our Sentry context and breadcrumbs tend to be useless except for whatever context we logged immediately before capturing an exception due to pollution across the different connections being handled. If we could manually setup an isolated sentry scope per request being handled we could probably work with that but that doesn't seem to be supported.

mmmoussa avatar Apr 14 '22 05:04 mmmoussa

Hi @mmmoussa, if you avoid using the global APIs (Sentry.* calls that mutate global state), and is willing to turn off integrations that are also inheritly global (those that hook up to global state, for example, Fetch and XHR, console, etc), then it is viable to use independent clients and scope per unit of concurrency. If for your app you can clearly determine which contextual data goes with which context of execution then you might even be able to bring back features like properly scoped breadcrumbs.

We've explored this subject in the past years and collectively learned it's hard to have a one-size-fits-all solution.

I'm sure the team still has this topic top of their mind.

rhcarvalho avatar Apr 14 '22 06:04 rhcarvalho

One solution that worked for my team was to new up a Hub to pass around with each client request received by the NodeJS App (in our scenario we have an Apollo + Express GraphQL service). It's a little ugly, because you need to pass your client instance to the Hub constructor, and calling the global init method returns void instead of the client instance so you need to find which global methods give you that instance, but it does work.

elliotleelewis avatar Jan 19 '23 21:01 elliotleelewis

This documentation: https://develop.sentry.dev/sdk/research/performance/#scope-propagation

Is incorrect, when it states:

JavaScript, for example, is single-threaded with an event loop and async code execution. There is no standard way to carry contextual data that works across async calls.

The standard way is https://nodejs.org/api/async_context.html

JVMartin avatar Jan 31 '23 19:01 JVMartin