Unexpected 3 retries when using prisma.$transaction after a KnownError in 2.17 and bad error parsing

[Sytten]

Bug description

Given the schema:

model PromoterStaff {
  promoter   Promoter     @relation(fields: [promoterId], references: [id])
  promoterId Int          
  user       User         @relation(fields: [userId], references: [id])
  userId     Int          
  @@id([promoterId, userId])
}

model PromoterStaffInvitation {
  id         Int          @id @default(autoincrement())
  promoter   Promoter     @relation(fields: [promoterId], references: [id])
  promoterId Int          
  email      String
  @@unique([promoterId, email])
}

If you execute:

await ctx.prisma.$transaction([
    ctx.prisma.promoterStaff.create({
      data: {
        user: {
          connect: { id: 1 },
        },
        promoter: {
          connect: { id: 1 },
        },
      },
    }),
    ctx.prisma.promoterStaffInvitation.delete({
      where: { id: 1 },
    }),
  ]);

And the thing happens to violate the unique clause of PromoterStaff, it will throw:

Resolver failure: Error occurred during query execution:
ConnectorError(ConnectorError { user_facing_error: Some(KnownError { message: "Unique constraint failed on the fields: (`promoter_id`,`user_id`)", meta: Object({"target": Array([String("promoter_id"), String("user_id")])}), error_code: "P2002" }), kind: UniqueConstraintViolation { constraint: Fields(["promoter_id", "user_id"]) } }) {"requestId":"1e361c7f-3af4-412a-8b5d-3afa006fa0d7","userId":2,"promoterId":1,"service":"api","error":{"message":"Error occurred during query execution:\nConnectorError(ConnectorError { user_facing_error: Some(KnownError { message: \"Unique constraint failed on the fields: (`promoter_id`,`user_id`)\", meta: Object({\"target\": Array([String(\"promoter_id\"), String(\"user_id\")])}), error_code: \"P2002\" }), kind: UniqueConstraintViolation { constraint: Fields([\"promoter_id\", \"user_id\"]) } })","stack":"Error: Error occurred during query execution:\nConnectorError(ConnectorError { user_facing_error: Some(KnownError { message: \"Unique constraint failed on the fields: (`promoter_id`,`user_id`)\", meta: Object({\"target\": Array([String(\"promoter_id\"), String(\"user_id\")])}), error_code: \"P2002\" }), kind: UniqueConstraintViolation { constraint: Fields([\"promoter_id\", \"user_id\"]) } })\n    at /Users/Sytten/Projects/Tixco/theticketingco-v3/packages/core-api/node_modules/.prisma/client/runtime/index.js:27103:19\n    at processTicksAndRejections (internal/process/task_queues.js:94:5)"}}

Looking at the logs, it seems to retry 3 times before failing:

prisma:query BEGIN
prisma:query SELECT "public"."promoter"."id" FROM "public"."promoter" WHERE "public"."promoter"."id" = $1 OFFSET $2
prisma:query SELECT "public"."user"."id" FROM "public"."user" WHERE "public"."user"."id" = $1 OFFSET $2
prisma:query INSERT INTO "public"."promoter_staff" ("promoter_id","user_id","role","current","created_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6) RETURNING "public"."promoter_staff"."promoter_id", "public"."promoter_staff"."user_id"
prisma:query ROLLBACK
prisma:query BEGIN
prisma:query SELECT "public"."promoter"."id" FROM "public"."promoter" WHERE "public"."promoter"."id" = $1 OFFSET $2
prisma:query SELECT "public"."user"."id" FROM "public"."user" WHERE "public"."user"."id" = $1 OFFSET $2
prisma:query INSERT INTO "public"."promoter_staff" ("promoter_id","user_id","role","current","created_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6) RETURNING "public"."promoter_staff"."promoter_id", "public"."promoter_staff"."user_id"
prisma:query ROLLBACK
prisma:query BEGIN
prisma:query SELECT "public"."promoter"."id" FROM "public"."promoter" WHERE "public"."promoter"."id" = $1 OFFSET $2
prisma:query SELECT "public"."user"."id" FROM "public"."user" WHERE "public"."user"."id" = $1 OFFSET $2
prisma:query INSERT INTO "public"."promoter_staff" ("promoter_id","user_id","role","current","created_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6) RETURNING "public"."promoter_staff"."promoter_id", "public"."promoter_staff"."user_id"
prisma:query ROLLBACK

Expected behavior

1. Don't retry 3 times
2. Throw a proper error with a code P2002

Environment & setup

It is a somewhat old prisma version, I will try again on a newer version if I get the time.

• Database: PostgreSQL
• Prisma version: 2.17

[Sytten]

While debugging #5976, I was able to reliably reproduce the 3 retries.
I am executing the code:

const test2 = async () => {
  await prisma.user.findFirst().then(c => console.log(`Finished 1: ${new Date()}`)).catch(err => console.log(`Err 1: ${new Date()}`)); 
  await sleep(10000)
  await prisma.user.findFirst().then(c => console.log(`Finished 2: ${new Date()}`)).catch(err => console.log(`Err 2: ${new Date()}`));
  await sleep(1000)
  await prisma.user.findFirst().then(c => console.log(`Finished 2: ${new Date()}`)).catch(err => console.log(`Err 2: ${new Date()}`)); 
}

And I am killing the DB connection between the first and second call.

This generates the following logs where we can see the retries:
(note that the engine stdout are not in the master code, I added them myself)

 prisma:client Prisma Client call: +10s
  prisma:client prisma.user.findFirst(undefined) +0ms
  prisma:client Generated request: +0ms
  prisma:client query {
  prisma:client   findFirstUser {
  prisma:client     id
  prisma:client   }
  prisma:client }
  prisma:client  +0ms
  prisma:engine stdout Request received 2021-03-19 00:06:31.564275 UTC +10s
prisma:info Request received 2021-03-19 00:06:31.564275 UTC
  prisma:engine stdout Getting connection 2021-03-19 00:06:31.564909 UTC +1ms
prisma:info Getting connection 2021-03-19 00:06:31.564909 UTC
  prisma:engine {
  prisma:engine   error: PrismaClientUnknownRequestError2 [PrismaClientUnknownRequestError]: Error occurred during query execution:
  prisma:engine   ConnectorError(ConnectorError { user_facing_error: None, kind: QueryError(Error { kind: Closed, cause: None }) })
  prisma:engine       at NodeEngine.graphQLToJSError (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29802:14)
  prisma:engine       at NodeEngine.request (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29698:24)
  prisma:engine       at processTicksAndRejections (internal/process/task_queues.js:93:5)
  prisma:engine       at async cb (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:34747:26)
  prisma:engine       at async test2 (/Users/Sytten/Projects/prisma/test/src/index.js:39:3) {
  prisma:engine     clientVersion: '2.19.0'
  prisma:engine   }
  prisma:engine } +5ms
  prisma:engine stdout Request received 2021-03-19 00:06:31.572478 UTC +2ms
prisma:info Request received 2021-03-19 00:06:31.572478 UTC
  prisma:engine stdout Getting connection 2021-03-19 00:06:31.573057 UTC +1ms
prisma:info Getting connection 2021-03-19 00:06:31.573057 UTC
  prisma:engine {
  prisma:engine   error: PrismaClientUnknownRequestError2 [PrismaClientUnknownRequestError]: Error occurred during query execution:
  prisma:engine   ConnectorError(ConnectorError { user_facing_error: None, kind: QueryError(Error { kind: Closed, cause: None }) })
  prisma:engine       at NodeEngine.graphQLToJSError (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29802:14)
  prisma:engine       at NodeEngine.request (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29698:24)
  prisma:engine       at processTicksAndRejections (internal/process/task_queues.js:93:5)
  prisma:engine       at async cb (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:34747:26)
  prisma:engine       at async test2 (/Users/Sytten/Projects/prisma/test/src/index.js:39:3) {
  prisma:engine     clientVersion: '2.19.0'
  prisma:engine   }
  prisma:engine } +2ms
  prisma:engine stdout Request received 2021-03-19 00:06:31.576454 UTC +1ms
prisma:info Request received 2021-03-19 00:06:31.576454 UTC
  prisma:engine stdout Getting connection 2021-03-19 00:06:31.576921 UTC +1ms
prisma:info Getting connection 2021-03-19 00:06:31.576921 UTC
  prisma:engine {
  prisma:engine   error: PrismaClientUnknownRequestError2 [PrismaClientUnknownRequestError]: Error occurred during query execution:
  prisma:engine   ConnectorError(ConnectorError { user_facing_error: None, kind: QueryError(Error { kind: Closed, cause: None }) })
  prisma:engine       at NodeEngine.graphQLToJSError (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29802:14)
  prisma:engine       at NodeEngine.request (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29698:24)
  prisma:engine       at processTicksAndRejections (internal/process/task_queues.js:93:5)
  prisma:engine       at async cb (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:34747:26)
  prisma:engine       at async test2 (/Users/Sytten/Projects/prisma/test/src/index.js:39:3) {
  prisma:engine     clientVersion: '2.19.0'
  prisma:engine   }
  prisma:engine } +1ms
  prisma:client Error: Error occurred during query execution:
  prisma:client ConnectorError(ConnectorError { user_facing_error: None, kind: QueryError(Error { kind: Closed, cause: None }) })
  prisma:client     at NodeEngine.graphQLToJSError (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29802:14)
  prisma:client     at NodeEngine.request (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:29698:24)
  prisma:client     at processTicksAndRejections (internal/process/task_queues.js:93:5)
  prisma:client     at async cb (/Users/Sytten/Projects/prisma/test/node_modules/@prisma/client/runtime/index.js:34747:26)
  prisma:client     at async test2 (/Users/Sytten/Projects/prisma/test/src/index.js:39:3) +19ms

[pantharshit00]

Hey @Sytten

Since #5976 is patched now, is this still relevant?

[Sytten]

Yes because I am not sure it is the job of the client to automatically retry on unknown errors. The user should at least have the possibility to turn it off since it can have unintended consequences.

[pantharshit00]

Marking this as improvement and candidating it. Behavior should be defined here. It is reproducible.

[matthewmueller]

FWIW, I'm also surprised that we retry here. I would have expected that to be an application-level concern or at most an opt-in option.

[garrensmith]

@Sytten I've tried to reproduce this a few ways with Prisma 3.9.1 and I can't get it to automatically retry. Would you be able to test again with the latest version of Prisma and see if this is still an issue?

[Sytten]

I believe they did a lot of internal changes to how prisma handles errors.so this might very well be the case.
I remember I also had issues when using transactions with middlewares, not sure if that has been fixed (the new transaction system is still not stable I think).
Though until this is documented I would not close the issue. Any system as complex as prisma needs to define clearly how it deals with failures IMO.

[garrensmith]

@Sytten I'm on the prisma team.

I remember I also had issues when using transactions with middlewares, not sure if that has been fixed (the new transaction system is still not stable I think).

The last release had a lot of fixes to stabilize the transaction work. Middleware might still experience a timeout with very long-running operations. This will be fixed in the next release.

Though until this is documented I would not close the issue. Any system as complex as prisma needs to define clearly how it deals with failures IMO.

With failures we aim to always return the error and to never unknowingly retry. If you have time would you be able to see if you still get the 3 retry attempts. I can't find anywhere on the query-engine side where we retry 3 times. And I cannot reproduce it.

[Sytten]

Good to know, you can also ping me on the company slack of prisma (technically still have a contract with prisma as I did QA testing last year).

Cool, this will help a lot I think. One thing that I wasn't exactly pleased with the new implementation is that for people using the "old" way with multiple queries in an array, it would be slower due to fact that it would now do multiple calls to the engine instead of one. Anyway I digress since this is not part of the current issue.

That is no true, look into the connection pooling/quaint and you will find inconsistencies. I have been pushing prisma to rewrite the connection pooling for a long time because it is frankly one of the weak point of the engine right now and constant battle in production:

1. The rust implementation could be lock free
2. The maximum and idle lifetime are only lazily evaluated (Add idle check to connection cleaner and rework when it runs importcjj/mobc#60), meaning it doesn't release connections back to the DB which is problematic for people that do rolling updates or have load spikes.
3. Connection health is not checked on every take from the pool. This means that sometimes you get failures that go back to the client for closed connections, but sometimes you are lucky and the pooler checks the health of the connection, finds that it is bad and take another one. This is one area that prisma should retry.

As for this particular 3 times retry, it was happening from the client side on unexpected errors (like an engine crash) not from the engine side. If it was removed, then yes this particular issue can be closed. I am happy to walk you through the multitude of issues/comments/experiments I did a while ago to find those problems.

[garrensmith]

I've tried to reproduce this and cannot get it this error. We have pushed a lot of fixes that should hopefully resolve this. I'm going to close this. Feel free to re-open if you still get this issue with the latest version of Prisma.