Context propagation for query logging

[tak1n]

Problem

Currently query logs can not relate to requests or a parent context from which they were invoked from. This means solutions like https://github.com/iamolegga/nestjs-pino or as well datadog tracing DataDog/dd-trace-js#1244 are not able to work properly.

Suggested solution

Context propagation into query logging should work properly. Sadly I'm quite new to nodejs and therefore aren't able to further specify how this should happen. Also not sure if the architecture of prisma is a blocker here (separate query engine process, and whether this gets simpler once n-api is used)

Alternatives

I've looked at https://github.com/Jeff-Lewis/cls-hooked (which nestjs-pino uses under the hood) so not a real alternative, but tried to understand whats happening here.

Additional context

Slack convo: https://prisma.slack.com/archives/CA491RJH0/p1623345269439900

[Sytten]

Duplicate of #6882

[janpio]

If you ignore the middleware aspect of this that you assumed @Sytten, this is essentially about e.g. creating a query id (or request id) and logging that with each query, so any external tooling can pick those out of the logs and correlate Prisma Client query to logged SQL query.

[tak1n]

Possibly also duplicate of #6519 and #5956

Would assume it shouldn't really depend on which tracing solution is used, but the end result should be queries being traced which are as well correlated to the trigger on prisma client side (and furthermore the root of the prisma client call -> API Request, Background Job, etc).

[lake2]

same issue + 1
any solution?

[moshcohen110]

Hi, having the same issue.
Is there any plan to create something like this?

[tak1n]

Hi, having the same issue.
Is there any plan to create something like this?

Its already on the roadmap of prisma https://www.notion.so/Support-Tracing-in-Prisma-Client-c0afd7599022435da2b8fc05c30cd1c0

[joshribakoff-sm]

@tak1n this doesn't require tracing support in Prisma, per se. The issue is that since Prisma queries are sent to a rust engine, all of the context from the dd-trace library added with https://nodejs.org/api/async_hooks.html#async-hooks is lost in the $on() callback. From dd-trace's perspective, $on() is its own entry-point into the app, and did not occur within the context of a GQL resolver or REST endpoint's span.

A simple solution would be to have callbacks that run synchronously on the client side, prior to sending the request to rust and after receiving the response, running within the context of our GQL resolver or REST endpoint. Instead, our only way with the existing API today is to observe the query via an asynchronous [inter process] RPC.

This is a feature request to have middleware in the client that wraps the outbound request to Rust, allowing us to log not only the request/response but also the surrounding context like dd-trace spans attached via https://nodejs.org/api/async_hooks.html#async-hooks would be preserved this way. This would be much preferred over logging UUIDs like @janpio suggested, since that does preserve the information but is otherwise a pain to extract by 3rd party tools. If it just logged on the client side, everything would "just work" :)

Instead, what we have today is a notification from Rust that it received an inbound request (at which point the context surrounding the original request we sent is lost)

A workaround would be for me to wrap my Prisma client to "decorate" the behavior by wrapping each of the method calls in dd-trace's tracer.wrap() method, so that all of my calls like await prisma.users.findFirst() become await tracer.wrap('my_query', prisma.users.findFirst()), and then the tracing would work as expected. But ideally Prisma could surface a middlware API instead of end users wrapping their Prisma clients manually.

[joshribakoff-sm]

I tried this approach:

prisma.$use(async (params, next) => {
  return await tracer.trace('prisma.query', async (span) => {
    span?.setTag('model', params.model);
    span?.setTag('action', params.action);
    span?.setTag('runInTransaction', params.runInTransaction);
    logger.debug('Prisma query', {
      model: params.model,
      action: params.action,
      runInTransaction: params.runInTransaction,
    });
    const result = await next(params);
    return result;
  });
});

The spans are also taken out of context of the parent span from where I sent my Prisma query.

  try {
    throw new Error();
  } catch (e) {
    console.log(e);
  }

the above debug logging shows the stack trace lost the context that I called my prisma query from a particular GQL resolver / file:

Error: 
    at /Users/jribakoff/groundwater/dist/apps/api/webpack:/groundwater/apps/api/src/app/db.ts:16:11
    at consumer (/Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:49914:20)
    at /Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:49920:76
    at runInChildSpan (/Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:49133:12)
    at /Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:49920:20
    at AsyncResource.runInAsyncScope (node:async_hooks:199:9)
    at PrismaClient._request (/Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:49919:86)
    at /Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:46474:25
    at _callback (/Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:46233:52)
    at Proxy.then (/Users/jribakoff/groundwater/node_modules/@prisma/client/runtime/index.js:46240:14)

In my opinion the proposal from @matthewmueller in #6882 (comment) doesn't have anything to do with solving this issue. I do not want to manually get the parent span and pass it into every Prisma query. If I was willing to accept that boilerplate, I could just wrap every prisma query callsite in a span manually. What I really want is I just want the middleware to run from within the context where I called my Prisma query.

I also noticed if the middleware throws an error, the query never resolves or rejects and it causes the upstream http request to never respond. Seems like middleware are not useful (for this use case) or production ready (errors will never be surfaced or logged).

[janpio]

or production ready (errors will never be surfaced or logged).

Can you please make sure an issue with more information for this exists? Thanks.

[mziwisky]

i've discovered that if you use the binary query engine instead of the default Node-API based one, then the async context is not lost in the client.$on('query', handler) handler. i don't know why this is, have been reading the LibraryEngine and BinaryEngine code to try to find a difference that might matter, but so far haven't figured it out.

it would be nice if the docs would talk a little more about the differences between those engines. the only thing it really says is "The Node-API library approach is recommended since it reduces the communication overhead between the Prisma Client and the query engine." but that makes me wonder why the binary engine is even an option at this point?

[janpio]

but that makes me wonder why the binary engine is even an option at this point?

Because sometimes the Node-API library gets something wrong, that works fine with the binary engine. Then it is a temporary workaround to use the binary engine. It is not recommended to use in other cases, and might be removed at any time.

[mziwisky]

@janpio would you consider this loss of async context an instance of the Node-API library getting something wrong? if so, can it be fixed? or is there some fundamental limitation with the Node-API approach that will never allow this to work? i still don't really understand why the query event handler gets invoked in a different async context than that which initiated the prisma query (especially since it's only the case with the Node-API engine but not with the binary engine)

[janpio]

Right now we do not give any expectation that the async context would be kept - it is not part of our documented API -, which is why this feature request exists and tracks this expectation (or other solutions to achieve the same outcome). So right now this seems to be undefined to me. If you really need it, you can use the binary to work around that - but be aware that you are off the really recommended path then and might have other negative (or positive) effects that are not documented.

[EladIsraeli]

Right now we do not give any expectation that the async context would be kept - it is not part of our documented API -, which is why this feature request exists and tracks this expectation (or other solutions to achieve the same outcome). So right now this seems to be undefined to me. If you really need it, you can use the binary to work around that - but be aware that you are off the really recommended path then and might have other negative (or positive) effects that are not documented.

I tried to use the binary to work around that but it does not really work.
I use NestJS-CLS package, for saving information on the async context, but when I try to access it on query event.

    this.$on<any>('query', async (e) => {
      this.logger.debug({query: e.query, params: e.params});
      const info = this.clsService.get("info")
    });

The clsService return undefined.

My prisma engine was loaded with binary

✔ Generated Prisma Client (4.15.0 | binary) to ./node_modules/@prisma/client in 553ms

any idea?

[EladIsraeli]

Hi @janpio, I really want to contribute to that. I commented above and the solution you suggested has not worked, how can I contribute to the project, or have a solution for that

[EladIsraeli]

@janpio would you consider this loss of async context an instance of the Node-API library getting something wrong? if so, can it be fixed? or is there some fundamental limitation with the Node-API approach that will never allow this to work? i still don't really understand why the query event handler gets invoked in a different async context than that which initiated the prisma query (especially since it's only the case with the Node-API engine but not with the binary engine)

Have you managed to make it work?

[mziwisky]

Have you managed to make it work?

@EladIsraeli sorry i missed your question until now. i've been away from this problem for long enough now that i don't recall the details, but i recall a few things that might help you here if you're still stuck and still wanting to work around it with the binary engine.

i was using the cls-hooked library, and it includes a bindEmitter function that i know i experimented with, but don't recall whether it was necessary to make my workaround work. but i believe that function exists because EventEmitter handlers don't get fired with the proper async context by default, so that function somehow propagates the context to them. if NestJS-CLS has some similar kind of helper, you might need to apply it to your prisma client.

[exAspArk]

The issue is that since Prisma queries are sent to a rust engine, all of the context ... added with https://nodejs.org/api/async_hooks.html#async-hooks is lost

This is a perfect summary by @joshribakoff-sm.

In short

• The Prisma engine written in Rust loses access to the Node.js context from which a query was triggered, so these Prisma features can't help solve this problem:
  • $on()
  • $use() middlewares
  • $extends() extentensions
• As a result, a request-specific context can't be shared when a database query is being executed. It doesn't work with
  • Native Node.js AsyncLocalStorage
  • cls-hooked
  • continuation-local-storage
  • and similar request-specific storage libraries that return undefined

One workaround I found is using the Prisma preview feature that allows the use of native Node.js database driver adapters to perform queries instead of the Prisma engine. Because these database adapters are executed in Node.js, async_hooks should just work fine.

You can find an example using https://github.com/brianc/node-postgres in @bemi-db/prisma that allows tracking all database changes and stitching them with request-specific context (user ID, API endpoint, etc.) automatically.