Prisma Promises not transferring context like Promises?
A typical pattern in software is
asyncLocalStorage.run(new Map(), () => {
const store = asyncLocalStorage.getStore();
//Generate our own txId for every request
const requestId = generateShortUUID();
store.set('txId', requestId);
//many other setttings like email if exist, clientId from http header if exist
//call controller next(); } Now, in the controller, and business logic and even libraries, this.log.info("some log") spits out all that same information. this information is captured through Promises. It seems prisma promises breaks that though so all my prisma logs that get logged are missing this info. I cannot tell which SQL queries are running against which requestId or email or client id. I filter in GCP the logs frequently on these things and the SQL logs all dissapear. is something missing from PrismaPromises to transfer the asyncLocalStorage context? how to get prisma logging "SQL log" so the underlying logger which calls asyncLocalStorage.getStore().get("txId") will work and get the txId for that request? (yes, this works with many clients as asyncLocalStorage is isolated to the context of each run).
In scala, the Promise has to propogate the context manually. In java, I have a reference to a CompletableFuture that does something similiar. Any reason this breaks in prisma?
//call controller next(); } Now, in the controller, and business logic and even libraries, this.log.info("some log") spits out all that same information. this information is captured through Promises. It seems prisma promises breaks that though so all my prisma logs that get logged are missing this info. I cannot tell which SQL queries are running against which requestId or email or client id. I filter in GCP the logs frequently on these things and the SQL logs all dissapear. is something missing from PrismaPromises to transfer the asyncLocalStorage context? how to get prisma logging "SQL log" so the underlying logger which calls asyncLocalStorage.getStore().get("txId") will work and get the txId for that request? (yes, this works with many clients as asyncLocalStorage is isolated to the context of each run).
In scala, the Promise has to propogate the context manually. In java, I have a reference to a CompletableFuture that does something similiar. Any reason this breaks in prisma?
5 Replies
Hi @deanStealth
Thanks for raising this question. I have shared it with engineering team and will provide a response as soon as i have one.
hey @deanStealth, the Prisma Promise is much less sophisticated than you're assuming. All it does is defer executing the query until you call
.then(). You can read the implementation here https://github.com/prisma/prisma/blob/e6ef63ba0cde4eb838c88a8203321cd8428f53f4/packages/client/src/runtime/core/request/createPrismaPromise.ts
I'm a bit confused about your question since your example doesn't appear to involve Prisma and I don't know what information you're referring to when you say "this.log.info("some log") spits out all that same information"
but I hope the source of Prisma Promise helps 🙂Hi @deanStealth, Prisma promises work fine with AsyncLocalStorage — otherwise tracing wouldn’t be able to function. As @wmadden wrote above, they don't do anything too fancy and "just work" like any other async operation, modulo deferring the execution until a
then handler is attached. The actual problem here is that you assume that SQL log events are emitted in the same async context as the Prisma query itself, which is unfortunately not the case. They are emitted independently, and may even be emitted after the Prisma operation had already been finished.@aqrln oh, oh!! ouch! I am very used to there being a request context (scala twitter promises as example) so that any code until request is done is on the same context such that very easy to debug performance issues and tie which SQL was running for which request due to the async context. After all, my request cannot complete without the data from the db which means as long as they do logger.info() on that same context before returning back to the client, we should be all good. can't we move the SQL Query Duration log to be done in that context? This seems like critical help in operations. I have confusion on "may even be emitted after the Prisma operation had already been finished" -> This is only true for logs, yes, as my client requires the transaction to be complete before I return to client OR even requires that I have the data which means the log could be on the request context and that would be ideal.
or perhaps we could have a configuration option to log on the request context? currently, my SQL logs """[INFO ] 11T10:05:08.588 [,,,]: SQL Query Duration:""" vs. all my other logs """[INFO ] 11T10:08:26.29 [573647,[email protected],OURS-1fc96,c6ac139]""" BASICALLY in GCP when I filter by [email protected], all my SQL logs dissapear and I want to see what SQL was being run for that user since he ran into an error and there is tons of SQL logs and I can't map which user ran that SQL.
@wmadden I think @aqrln is correct in the log is not running in the same request context as the SQL and I wonder, can we have a log there (OR AT LEAST a config option so I can turn on logging on the SQL request context thread so the context of the SQL run is available in the log)
A simple testcase is this asyncLocalStorage.run(new Map(), () => {
const store = asyncLocalStorage.getStore();
store.set("test", "myvalue");
const userDbo: CustomerWithCompany | null = await this._prisma.customerDbo.findUnique({
where: {
id: userDbId
},
include: {
roles: true,
company: true
},
});
}); and then after that passing a logger with a public info(msg: string): void { asyncLocalStorage.getStore().get("test") and basically if that works, we get to thread reqId through all the SQL logs which is great for filtering in devops work.
@RaphaelEtim it sounds like they only need to move the log statement for SQL to just after the SQL so it runs in the same context. Can that be done. very useful for devops logging and tracing.
@RaphaelEtim now way to get them to move this log then to the context of where SQL was run for ease of devops people? (wanting to see the request id the SQL ran with).
Hi @deanStealth
I'll ask the team.