Bug(qe): errors don't get logged

[miguelff]

Supersedes #14933

Background

Prisma can be configured to log events to stdout or emit logging events. Those events can be categorized into four levels which do not have a hierarchical relationship with each other. (A logging level does not include events from any other level)

One of these levels is error, but the reference doesn't specify what is eligible to be logged using this level.

Given that the reference has a section on errors users might have the reasonable expectation that, when any of those happen, an event is logged to the console or emitted for subscription depending on the configuration.

This is manifested in past issues like #14933, but given the reproduction scenarios below, the problem is not restricted to findFirstOrThrow and findUniqueOrThrow NotFound errors, but to all the errors happening in Prisma

Reproduction

I created two reproduction scenarios, using the libray engine and the binary engine (As they exercise two different code paths for dispatching requests coming from the prisma client)

Both resulted on the error not being logged.

Premise: the engine was tricked to through a panic when dispatching a query

diff --git a/query-engine/core/src/interpreter/query_interpreters/read.rs b/query-engine/core/src/interpreter/query_interpreters/read.rs
index 6916f78fcc..878f876c5e 100644
--- a/query-engine/core/src/interpreter/query_interpreters/read.rs
+++ b/query-engine/core/src/interpreter/query_interpreters/read.rs
@@ -16,6 +16,10 @@ pub fn execute<'conn>(
     trace_id: Option<String>,
 ) -> BoxFuture<'conn, InterpretationResult<QueryResult>> {
     let fut = async move {
+        if 1 < 2 {
+            panic!("Damn that's a panic");
+        }
+
         match query {
             ReadQuery::RecordQuery(q) => read_one(tx, q, trace_id).await,
             ReadQuery::ManyRecordsQuery(q) => read_many(tx, q, trace_id).await,

Scenario 1 - Binary engine

index.ts

import { PrismaClient, Prisma } from '.prisma/client'
​
async function main() {
  const prisma = new PrismaClient({
    log: [
      {
        emit: 'event',
        level: 'error',
      },    
    ],
    __internal: {
      engine: {
        endpoint: "http://127.0.0.1:57581",
      },
    },
  } as any);
​
  (prisma as PrismaClient<Prisma.PrismaClientOptions, 'error'>).$on("error", (e) => {
    console.log("WORKS WELL")
    process.exit(1)
  })
​
  const email = `user.${Date.now()}@prisma.io`
​
  const res = await prisma.user.findFirst({
    where: {
      email,
    }
  })
​
  console.log(res)
}
​
void main().catch((e) => {
  console.log("NOOOO!")
  console.log(e)
  process.exit(1)
})

prisma.schema

generator client {
  provider        = "prisma-client-js"
  output          = "../node_modules/.prisma/client"
  engineType      = "binary"
  previewFeatures = []
}
datasource db {
  provider = "postgresql"
  url      = "postgresql://postgres:prisma@localhost:5432"
}
model User {
  id    String @id @default(cuid())
  email String @unique
  posts Post[]
}
model Post {
  id       String @id @default(cuid())
  title    String
  author   User   @relation(fields: [authorId], references: [id])
  authorId String
}

Result:

Scenario 2 - Library engine

index.ts

import { PrismaClient, Prisma } from '.prisma/client'

async function main() {
  const prisma = new PrismaClient({
    log: [
      {
        emit: 'event',
        level: 'error',
      },
    ],
  });

  prisma.$on("error", (e) => {
    console.log("WORKS WELL")
    process.exit(1)
  })

  const email = `user.${Date.now()}@prisma.io`

  const res = await prisma.user.findFirst({
    where: {
      email,
    }
  })

  console.log(res)
}

void main().catch((e) => {
  console.log("NOOOO!")
  console.log(e)
  process.exit(1)
})

prisma.schema

generator client {
  provider        = "prisma-client-js"
  output          = "../node_modules/.prisma/client"
  previewFeatures = []
}
datasource db {
  provider = "postgresql"
  url      = "postgresql://postgres:prisma@localhost:5432"
}
model User {
  id    String @id @default(cuid())
  email String @unique
  posts Post[]
}
model Post {
  id       String @id @default(cuid())
  title    String
  author   User   @relation(fields: [authorId], references: [id])
  authorId String
}

Result

Expected behavior

The specifics have to be determined. There's no previous record in the codebase to determine the correct behavior. And the reference of what constitutes an error is vague enough as to require a specification of how this should behave.

My proposal is to log with the error level what is said to constitute an error in the error reference thus following the principle of least astonishment. But I'd like to count with @janpio's take on how this should behave before jumping into implementation.

Definition of done

• Expected behavior clarified
• Implementation and tests ensuring expected behavior
• Docs on the log levels clarify the expected behavior

[ricardolpd]

We just upgraded prisma and found that the client logger was logging query errors. We found this a bit baffling as this should be handled by the service where the queries run from, and they should be logged or not depending on the business requirements.

I would have expected that the client errors listener would log connection errors, internal errors from prisma, and other parts related to the query engine/pools and internals. Not query errors.

[janpio]

What would the "service where the queries run from" be in your interpretation? In my understanding there is only one component for Prisma Client users, which is Prisma Client - where you can configure the logging in certain ways.

[ricardolpd]

@janpio we use insert as means to create idempontent requests, knowing that duplicate inserts will result in an error:

since the upgrade we see these Unique constraint failed on the fields: (transactionId), target: transaction.create.
being logged, however this is in a implementation choice from us, and it is an application error, not a prisma client error.

What i mean by this, is that service implementation caused the error, not the prisma client in some unrelated way from the application.
The result of this design decision is that we are now filtering these messages through string comparisons (which is quite undesirable), when for me the application should choose if such errors are logged or not. Not the prisma client itself, as it removes control from the application, and generates quite a bit of undesired noise.

Hope my reply makes more sense.

[janpio]

Yeah I think I follow. What logging do you have enabled in Prisma Client?

[ricardolpd]

Probably easier to show it:

Query/Info are disabled in prod. I am not sure why the community wants this feature. But for us we would like to be able to exclude these errors.

prismaClient.$on('query' as any, (e: Prisma.QueryEvent) => {
  logger.trace(e, `[DB-Prisma] query: ${e.query}; duration: ${e.duration} ms.`);
});

prismaClient.$on('info' as any, (e: Prisma.LogEvent) => {
  logger.info(e, `[DB-Prisma] message: ${e.message}, target: ${e.target}.`);
});

prismaClient.$on('warn' as any, (e: Prisma.LogEvent) => {
  logger.warn(e, `[DB-Prisma] message: ${e.message}, target: ${e.target}.`);
});

const ignoredMessages = ['Unique constraint failed on the fields'];

const shouldLogEvent = (e: Prisma.LogEvent) => {
  if (
    ignoredMessages.some((ignoredMessage) => e.message.includes(ignoredMessage))
  ) {
    return false;
  }
  return true;
};

prismaClient.$on('error' as any, (e: Prisma.LogEvent) => {
  if (shouldLogEvent(e)) {
    logger.error(e, `[DB-Prisma] message: ${e.message}, target: ${e.target}.`);
  }
});

prismaClient.$on('beforeExit', async () => {
  await shutdownPromise;
  console.warn('[DB-Prisma] Prisma process is about to shutdown');
});

[janpio]

And via which of those are errors now unexpectedly logged?

[ricardolpd]

The error callback. (You can see the filtering done in the if statement)

prismaClient.$on('error' as any, (e: Prisma.LogEvent) => {
  if (shouldLogEvent(e)) {
    logger.error(e, `[DB-Prisma] message: ${e.message}, target: ${e.target}.`);
  }
});

[janpio]

Ok, if you do not want the error caused by queries to be logged there, which would you then want to have logged? I am still trying to build a complete picture here.

[ricardolpd]

I will refer to my original comment:

I would have expected that the client errors listener would log connection errors, internal errors from prisma, and other parts related to the query engine/pools and internals. Not query errors.

We didnt had this behavior in prisma in older versions. what caused the change to encompass this?

[janpio]

See from above:

Given that the reference has a section on errors users might have the reasonable expectation that, when any of those happen, an event is logged to the console or emitted for subscription depending on the configuration.

This is manifested in past issues like #14933, but given the reproduction scenarios below, the problem is not restricted to findFirstOrThrow and findUniqueOrThrow NotFound errors, but to all the errors happening in Prisma

[koutaro-masaki]

I am facing this same problem as @ricardolpd.

I updated my Prisma version from 3.15 to the latest and was baffled by the large amount of log output from tests that expect an exception. I tried to suppress it by passing { log: []} or { log: [ { 'level': 'error', 'emit': 'event' } ] } to the constructor, but the log continued to output.

It looks very strange that the error log is output even when an exception is caught. Is there any way to prevent the error log from being output?