Tsed: [BUG] AsyncLocalStorage loses context between middleware

[csnate]

Information

• Version: 6.x
• Packages: all

In v5 this worked correctly and works correctly with vanilla Express.

If you use AsyncLocalStorage (or async_hooks or cls-hooked) in a middleware and then attempt to access the store inside of another middleware or controller down the line, the execution context of the run method is lost between the middlewares and the store is no longer available. Calling next inside of the executing function should keep the executing context.

Example

I've created a small repo to reproduce the issue - https://github.com/csnate/tsed-scope

Run npm start to run the TsED server (http://localhost:8080/rest/health). Run npm run express to run the Express server (http://localhost:8080/health). Both are very small and expose a single route that calls 2 middleware. The first middleware starts the AsyncLocalStorage and runs it inside of the first middleware, setting a uuid as "correlation-id" in the store, logs some info to confirm the data is in the store, and then calls next inside of the executing function. The second middleware attempts to read from the store and get the correlation-id and log it.

Here are the logs from the TsED request:

[2021-03-16T08:17:07.960] [INFO ] [TSED] - In TestMiddleware
[2021-03-16T08:17:07.961] [INFO ] [TSED] - In TestMiddleware Async fa163902-37cf-4973-bf57-42a394161c33
[2021-03-16T08:17:07.961] [INFO ] [TSED] - In TestMiddleware Store:  fa163902-37cf-4973-bf57-42a394161c33
[2021-03-16T08:17:07.962] [INFO ] [TSED] - Test2Middleware: store missing

Here are the logs from the Express request:

In testMiddleware
In TestMiddleware Async 60336a85-ef12-4adf-a727-75a7f0220155
In TestMiddleware Store:  60336a85-ef12-4adf-a727-75a7f0220155
Test2Middleware:  60336a85-ef12-4adf-a727-75a7f0220155

I've check the TsED code, but have been unable to determine where/how the context is getting lost.

[Romakita]

Hello @csnate
Have you used the search github function and look on the Ts.ED documentation before open an issue :)

Ts.ED provide the @tsed/async-hook-context package to manage natively the async_hook.

See https://tsed.io/docs/request-context.html#asynchook-context

With that you can inject the PlatformContextand retrieve the requestId by using 'ctx.id'. But in a middleware isn't necessary to use the InjectContext decorator because context can be injected from method parameter:

@Middleware()
export class MyMiddleware {
  use(@Context() $ctx: PlatformContext) {
     console.log('requestId', $ctx.id);
  }
} 

See you
Romain

[csnate]

Yea I did. There's a separate branch https://github.com/csnate/tsed-scope/tree/with-async-hook-package. Doesn't work either. I did the same thing outlined in this issue - https://github.com/TypedProject/tsed/issues/1134 - by making the Server extend PlatformAsyncHookContext.

The problem is that I need to be able to access that store outside of a service/controller/middleware ultimately. I need to get that correlation-id inside of a custom Logging Layout so I can add that correlation-id to my logs.

[Romakita]

For me it works correctly with the @tsed/async-hook-context I have a project which works with!

[csnate]

So, how I would access that id inside of a custom Logging Layout? Would something like this work?

@Layout({ name: 'custom-layout' })
export class CustomLayout extends BaseLayout {

    @InjectContext()
    $ctx?: PlatformContext;

    public transform(loggingEvent: LogEvent, timezoneOffset?: number | undefined): string {
        const log: any = {
            categoryName: loggingEvent.categoryName,
            level: loggingEvent.level.toString(),
            message: loggingEvent.data.join(' '),
        };

        if (this.$ctx?.id) {
            log.correlationId = this.$ctx?.id;
        }
        return JSON.stringify(log);
    }
}

[Romakita]

But the documentation doesn't mention to extends the Server with PlatformAsyncHookContext !!! The issue isn't the official documentation to use the package ;)

Look the documentation here: https://tsed.io/docs/request-context.html#asynchook-context

[Romakita]

So, how I would access that id inside of a custom Logging Layout? Would something like this work?

No it won't works because, Layout is not an injectable provider. Logger is an independent project from the Ts.ED framework.
Let me find a way to do that.

[Romakita]

Here is the right with the Layout:

@Layout({ name: 'custom-layout' })
export class CustomLayout extends BaseLayout {
    public transform(loggingEvent: LogEvent, timezoneOffset?: number | undefined): string {
        const log: any = {
            categoryName: loggingEvent.categoryName,
            level: loggingEvent.level.toString(),
            message: loggingEvent.data.join(' '),
        };

        const $ctx = PlatformAsyncHookContext.getStore().getStore() // i know, it's strange...

        if ($ctx?.id) {// but requestId is already added to each log in loggingEvent.data (inspect data to see the field reqId)
            log.correlationId = this.$ctx?.id;
        }

        return JSON.stringify(log);
    }
}

but is really strange to create a CustomLayout to append requestId (correlationId) which is already present for each log generated by Ts.ED.

[csnate]

Solid, I'll give it a shot.

FYI - we don't use the TsED logs as the output wasn't playing nice with our log processors. So we have to use a custom layout, unfortunately.

[csnate]

Awesome it looks like this is going to work. Thanks for your help @Romakita !