Different requestIds for same request in GraphQL (when using an Interceptor)

[francescosalvi]

Greetings! While trying out this module within an app using GraphQL, I have come across an odd behavior: I have defined a simple interceptor that logs the requestId (csl.getId()) and applied it to a GQL resolver, which resolves a bunch of fields for an object type (@ResolveField).

---

When I configure the module to use the middleware:

ClsModule.forRoot({
  middleware: {
    generateId: true,
    mount: true,
  },
});

I get, as expected, all log statements showing the same requestId.

(sidenote: documentation states for GQL I must set useEnterWith: true, but practically things work even without - I then assumed that this was somehow being automatically set, but debugging revealed that the code was still hitting ClsService.run, so that's another mystery to me...).

---

When I configure the module to use the interceptor/guard:

ClsModule.forRoot({
  interceptor | guard: {
    generateId: true,
    mount: true,
  },
});

all the log statements show different requestId values.

By the way, the reason I was investigating the other two approaches was, aside from the security concerns of EnterWith, to test out suppport for GraphQL over websocket (GraphQL suscriptions), which, as per documentation, turns out to not be working with the middleware approach.

[Papooch]

First of all

documentation states for GQL I must set useEnterWith: true, but practically things work even without

This is great news! Are you using apollo or mercurius? If you see that it works without useEnterWith, then something probably changed in the way that the resolvers are registered, so that it's no longer necessary and I'll update the documentation.

The reason you see different Ids might be because the interceptor can get triggered multiple times in a single request and the ID is re-generated, if the resolvers are nested - this is something that occurred to me only now and I don't have tests for that scenario. It should not happen with different kinds of transports though.

That makes me thing of a feature, where you could specify if you want to re-use an existing context if one exists instead of creating a new one - in case different parts of the context are added in different enhancers. It would also fix your problem with multiple IDs.

Btw, you can test that it actually runs multiple times by using something like this as the idGenerator: () => { console.log('running'); return 'abc' }

[francescosalvi]

Are you using apollo or mercurius

apollo

something probably changed in the way that the resolvers are registered

for more context:

@nestjs/core@npm:9.3.9
@nestjs/common@npm:9.3.9
@nestjs/platform-express@npm:9.3.9
@nestjs/graphql@npm:10.2.0

@nestjs/apollo@npm:10.2.0
apollo-server-core@npm:3.11.1
apollo-server-express@npm:3.11.1

Btw, you can test that it actually runs multiple times by using something like this as the idGenerator: () => { console.log('running'); return 'abc' }

well the actual real test I did was to try and share some state (cache authentication data) across the different executions of my custom interceptor, and I noticed it was always "missing" the cache, then I also noticed that the requestId was different all the times (unless I used middleware approach ofc).

[Papooch]

It seems that since @nestjs/graphql@10, the enterWith method is no longer necessary, so it should be safe to use the middleware with auto mount. I've also updated the README to reflect that.

I started working on the feature to reuse existing context if an enhancer is triggered multiple times, so it should solve your use-case.

As a workaround for now, you can use something like this:

{
  setup: (cls) => {
    if (!cls.has(CLS_ID)) cls.set(CLS_ID, generateSomeId())
  }
}

[francescosalvi]

Thanks for looking into this. I tried to add the setup config above (within ClsModuleOptions.interceptor) but it looks liks the set statement is never hit (an existing value is always found).

[Papooch]

@francescosalvi Even if you set generateId to false? Would you be so kind and share your repository, or some minimal reproduction, that I can use as a reference?

[francescosalvi]

Even if you set generateId to false? Would you be so kind and share your repository, or some minimal reproduction

I'll see if I have time to, in the meanwhile

ClsModule.forRoot({
  interceptor: {
    mount: true,
    generateId: false,
    setup: (cls: ClsService): void => {
      if (!cls.has(CLS_ID)) {
        console.log('no CLS_ID found, setting');
        cls.set(CLS_ID, randomUUID());
      } else {
        console.log('found existing CLS_ID');
      }
    },
  },
});

[Nest] 47  - 02/28/2023, 8:16:46 AM   DEBUG [ClsModule] ClsInterceptor will be automatically mounted
[...]
no CLS_ID found, setting (~8 times)

(I am calling a Query with a bunch of nested fields with each their own custom resolver)

[Papooch]

So it's the other way around - the set statement is always executed. But yeah, this is most likely because each interceptor wraps the next code with cls.run(), which does not inherit context from the parent scope, so you can't see it has been set. It seems that using middleware is the only built-in option for GQL.

Alternatively, you could put together a custom ClsInterceptor and not use the built-in one:

@Injectable()
export class CustomClsInterceptor implements NestInterceptor {
    constructor(
        private readonly cls: ClsService
    ) {}

    intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
        if (this.cls.isActive()) {
            // skip cls.run() if we're inside an active context already
            return next.handle()
        }
        return new Observable((subscriber) => {
            cls.run(async () => {
                cls.set(CLS_ID, genrateRandomId());

                // ... more custom setup

                next.handle()
                    .pipe()
                    .subscribe({
                        next: (res) => subscriber.next(res),
                        error: (err) => subscriber.error(err),
                        complete: () => subscriber.complete(),
                    });
            });
        });
    }
}

Note: I'm not sure if wrapping the next.handle() call in another cold observable is still needed - it was before @nestjs/graphql < 10 - so you may experiment with it.

[Papooch]

@francescosalvi Hello there, I have finally gotten around to address this issue. It all boils down to how Nest wraps execution context around resolvers. In the end I had to store the CLS values in the GQL context in the case of an interceptor and I have a working solution now.

I published it as a pre-release, so you can try it now with nestjs-cls@3.3.2-0. If you get the time and this is still relevant, please report back if this version fixes the issue you.

[Papooch]

Fixed in 3.4.0

[francescosalvi]

Hi @Papooch , sorry for late reply

I just tested the project branch where I was experimenting with the library, where I was targeting v3.0.5, re-reproduced the issue (made sure I was using interceptor mode), then updated (to v3.4.0), and I can confirm I now correctly see the expected "cache hits" during subsequent calls to the store.

Thanks!