sentry-javascript: Sentry produces incorrect data when async code is involved

With the 7.48.0 release of the JS SDK we use AsyncLocalStorage instead of domains under the hood.

If you want to manually wrap methods in an async context to isolate breadcrumbs/scope/spans, you can use Sentry.runWithAsyncContext, which is documented here: https://docs.sentry.io/platforms/node/configuration/async-context/

Note the above only works with Node - in Browser JavaScript environments there is no async context mechanism we can use to accomplish this (like @timfish mentioned above).

But @sentry/node doesn’t use AsyncLocalStorage

This is something we are tracking and working toward! https://github.com/getsentry/sentry-javascript/issues/3660. It’s also part of our roadmap this year: https://github.com/getsentry/sentry-javascript/discussions/5878

For instance, an http server processing 20 requests at the same time, where each request for example hits the pg auto-instrumentation, which calls the same global hub from all locations

If each request is isolated to it’s own domain, it should get a unique hub, which means that we isolate scope/transactions/breadcrumbs correctly. We do this out of the box for our express, nextjs, and remix integrations.

If you wrap your request handler (or whatever your concurrency generation mechanism is) with a new domain, it should stay isolated.

I know domains are deprecated, but for now they work - and support all the wide variety of Sentry users we have (different node versions, deployment configs, etc.). This year we are going to look at adding async hooks (or similar) - so look forward to news there about this.

We might also take a slighty different approach though, like around what cloudflare workers did with AsyncLocalStorage, seeing if we can generate a more performant approach by directly hooking into v8 or similar. We’ve started investigating this as part of our production profiling sdk and support for local variables in stacktraces - still need to experiment! Any feedback/thoughts about that is greatly appreciated.

@AbhiPrasad But @sentry/node doesn’t use AsyncLocalStorage, so it suffers the jumbling of spans problem that this issue is tracking. It’s not possible to use Sentry in Node without your spans getting randomly assigned to the latest transaction, instead of the unit of concurrency they should be. For instance, an http server processing 20 requests at the same time, where each request for example hits the pg auto-instrumentation, which calls the same global hub from all locations. Your pg query spans will be assigned to the wrong transactions, because obviously 20 different units of concurrency are all clobbering the same global.

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

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.

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.

There’s an issue tracking progress towards fixing this.

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.

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

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);
});

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

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