Prisma1: Two executed SQL queries for a single GraphQL query

[tadejstanic]

Bug Report

Current behavior
It seems that with postgres connector Prisma executes two SQL queries for a single GraphQL query.

query getPost {
   post(postId: “cjmln88vt000z0a17d5vha3wq”){
      title
   }
}

Postgres LOGs:

postgres_1  | 2018-09-28 11:45:41.804 GMT [34] LOG:  execute <unnamed>: select
postgres_1  |       “default$default”.“Post”.“id”,
postgres_1  |       “default$default”.“Post”.“title”,
postgres_1  |       “default$default”.“Post”.“published”
postgres_1  |     from “default$default”.“Post”
postgres_1  |     where “default$default”.“Post”.“id” = $1
postgres_1  | 2018-09-28 11:45:41.804 GMT [34] DETAIL:  parameters: $1 = ‘cjmln88vt000z0a17d5vha3wq’
postgres_1  | 2018-09-28 11:45:41.804 GMT [33] LOG:  execute <unnamed>: select
postgres_1  |       “default$default”.“Post”.“id”,
postgres_1  |       “default$default”.“Post”.“title”,
postgres_1  |       “default$default”.“Post”.“published”
postgres_1  |     from “default$default”.“Post”
postgres_1  |     where “default$default”.“Post”.“id” = $1
postgres_1  | 2018-09-28 11:45:41.804 GMT [33] DETAIL:  parameters: $1 = ‘cjmln88vt000z0a17d5vha3wq’

Reproduction
You can reproduce this behaviour by following Prisma Get started section from the docs.

This issue was found on prisma/1.18.0-beta.4 (darwin-x64) node-v10.10.0

Expected behavior?
Postgres should log only one executed SQL query.

[marktani]

How exactly are you sending the GraphQL query to Prisma? Do you use a specific tool for that? Can you reproduce the duplicated query with a cURL statement?

Might be related to #3106

[tadejstanic]

I'm using Playground. The resolver has same definition as the one from the tutorial:

post(root, args, context) {
      return context.prisma.post({ id: args.postId });
    }

So nothing specific is used.

[marktani]

Let's have a look at all of the components in your setup:

1) Postgres DB
2) Prisma Core
3) Prisma Client
4) Server
5) Playground

My goal is to find out which of these components is responsible for the duplicate query.
So, the quickest way to get there is to remove as many components as possible out of the equation, while still being able to reproduce the issue.

My hunch is that the problem is in 3).

It's safe to say that 1) Postgres is not the source of the error.
To remove 5) Playground as a potential source of error: Are you able to reproduce the problem by sending a cURL statement to 4)?

[tadejstanic]

I sent curl statement:

curl 'http://localhost:4000/' -H 'Accept-Encoding: gzip, deflate, br' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'Connection: keep-alive' -H 'DNT: 1' -H 'Origin: http://localhost:4000' --data-binary '{"query":"query getPost {\n  post(postId: \"cjmln88vt000z0a17d5vha3wq\"){\n    title\n  }\n}"}' --compressed

and again got two queries logged.

[tadejstanic]

I created a repo so you can reproduce the issue more easily.

https://github.com/tadejstanic/prisma-test-js

Not quite sure, but it seems that with a typescript version of prisma-client there is only one SQL query executed.

[marktani]

Thanks, here is the full reproduction:

git clone https://github.com/tadejstanic/prisma-test-js.git
cd prisma-test-js
docker-compose up -d
prisma deploy
prisma generate
node index.js

send this curl:

curl 'http://localhost:4000/' -H 'Accept-Encoding: gzip, deflate, br' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'Connection: keep-alive' -H 'DNT: 1' -H 'Origin: http://localhost:4000'  --data-binary '{"query":"query c {\n  getAllUsers {\n    id\n  }\n}"}' --compressed

[marktani]

Super weird, after fiddling around with this, I am after some while not able to reproduce the duplicate query anymore. Then sometimes it is happening again, without changing anything.

This is definitely the same symptoms as #3106.

My current best guess is that one needs this stack, and some other state that I'm not aware of yet to reproduce the problem:

1. Prisma Core
2. Prisma Client
3. Server (graphql-yoga)

[marktani]

I was also able to reproduce the issue at some point with these two adjustments:

- const { prisma } = require("./prisma-client");
+ const { Prisma } = require("./prisma-client");

const server = new GraphQLServer({
  typeDefs: "./schema.graphql",
  resolvers,
  context: {
-    prisma
+    prisma: new Prisma({debug: true})
  },
});

With this, I could see that the Prisma Client was only printing the query once, but the Postgres logs still executed the query twice.

Now, the question is whether Prisma Client has a bug that only prints the query once, but executes it twice, or if Prisma Core has a bug that replicates an incoming query.

Or GraphQL Yoga is somehow executing the resolver code path for the query twice. This looks like the least likely case to me.

[marktani]

Next try to gain more insight into this will be to log incoming queries to Prisma. I will do so by adding these env vars to the docker-compose.yml:

SLOW_QUERIES_LOGGING: "true"
SLOW_QUERIES_LOGGING_THRESHOLD: "0"
PRISMA_CONFIG: |
        port: 4466

[marktani]

Indeed, using the above configuration for the Prisma server, I can boil this issue down to the Prisma server!

1. I send one query using this curl

curl 'http://localhost:4000/' -H 'Accept-Encoding: gzip, deflate, br' -H 'Content-Type: application/json' -H 'Accept: application/json' -H 'Connection: keep-alive' -H 'DNT: 1' -H 'Origin: http://localhost:4000'  --data-binary '{"query":"query c {\n  getAllUsers {\n    id\n  }\n}"}' --compressed

1. Prisma server logs one slow query

SLOW QUERY - DURATION: 17
QUERY: [{"query":"{\n  users {\n    id\n    email\n    name\n  }\n}\n","variables":{}},{"query":"{\n  users {\n    id\n    email\n
   name\n  }\n}\n","variables":{}}]

1. Postgres logs two queries

2018-10-01 10:48:01.981 GMT [113] LOG:  execute <unnamed>: select
          "Alias"."id",
          "Alias"."email",
          "Alias"."name"
        from "default$default"."User" as "Alias"
        order by "Alias"."id" asc
        offset $1
2018-10-01 10:48:01.981 GMT [113] DETAIL:  parameters: $1 = '0'
2018-10-01 10:48:01.981 GMT [112] LOG:  execute <unnamed>: select
          "Alias"."id",
          "Alias"."email",
          "Alias"."name"
        from "default$default"."User" as "Alias"
        order by "Alias"."id" asc
        offset $1
2018-10-01 10:48:01.981 GMT [112] DETAIL:  parameters: $1 = '0'

[tadejstanic]

I made an additional test regarding this issue but this time by using a different framework NestJS. Using this framework had two objectives.

The first one was to remove graphql-yoga from the stack, which might be the reason for generating two queries. Nest.js framework is actually using apollo-server-express. It turned out that even with this setting I'm able to log two SQL queries for a single GraphQL query.

The second goal with integrating Prisma and Nest.js was to see, how well both pieces are playing together. The main benefit of this integration is that we can get quite maintainable and readable code structure for a GraphQL server.

However, one thing poped-up while doing the integration, which might be somehow related to the issue we dealt with.

I set this data model:

type User {
  id: ID! @unique
  name: String!
  courses: [Course!]!
}

type Course {
  id: ID! @unique
  title: String!
  owner: User!
}

Then I inserted two users and one course that was linked to one of the users. After that I made this query:

query getAllUsers {
  getAllUsers{
    name courses{
      title
    }
  }
}

Based on my experiences with batching SQL queries with dataloader or joinmonster I expected Prisma server would also generate at most two SQL queries for the mentioned GraphQL query. But DB logs shows that Prisma server executed 5 SQL queries.

nest-prisma-db | 2018-10-02 07:28:56.683 GMT [264] LOG:  execute <unnamed>: select
nest-prisma-db |      "Alias"."id",
nest-prisma-db |      "Alias"."name"
nest-prisma-db |    from "default$default"."User" as "Alias"
nest-prisma-db |    order by "Alias"."id" asc
nest-prisma-db |    offset $1
nest-prisma-db | 2018-10-02 07:28:56.683 GMT [264] DETAIL:  parameters: $1 = '0'
nest-prisma-db | 2018-10-02 07:28:56.723 GMT [264] LOG:  execute <unnamed>: select "default$default"."User"."id"
nest-prisma-db |    from "default$default"."User"
nest-prisma-db |    where "default$default"."User"."id" = $1
nest-prisma-db | 2018-10-02 07:28:56.723 GMT [264] DETAIL:  parameters: $1 = 'cjmqbyb8k000l0a34zy9m55wb'
nest-prisma-db | 2018-10-02 07:28:56.724 GMT [266] LOG:  execute <unnamed>: select "default$default"."User"."id"
nest-prisma-db |    from "default$default"."User"
nest-prisma-db |    where "default$default"."User"."id" = $1
nest-prisma-db | 2018-10-02 07:28:56.724 GMT [266] DETAIL:  parameters: $1 = 'cjmqbxjg8000i0a34qsluv5x9'
nest-prisma-db | 2018-10-02 07:28:56.731 GMT [264] LOG:  execute <unnamed>: select
nest-prisma-db |      "Alias"."id",
nest-prisma-db |      "Alias"."title",
nest-prisma-db |      "RelationTable"."A" as "__RelatedModel__",
nest-prisma-db |      "RelationTable"."B" as "__ParentModel__"
nest-prisma-db |    from "default$default"."Course" as "Alias"
nest-prisma-db |      join "default$default"."_CourseToUser" as "RelationTable"
nest-prisma-db |      on "Alias"."id" = "RelationTable"."A"
nest-prisma-db |    where "RelationTable"."B" in ($1)
nest-prisma-db |    order by "RelationTable"."A" asc
nest-prisma-db | 2018-10-02 07:28:56.731 GMT [264] DETAIL:  parameters: $1 = 'cjmqbxjg8000i0a34qsluv5x9'
nest-prisma-db | 2018-10-02 07:28:56.734 GMT [264] LOG:  execute <unnamed>: select
nest-prisma-db |      "Alias"."id",
nest-prisma-db |      "Alias"."title",
nest-prisma-db |      "RelationTable"."A" as "__RelatedModel__",
nest-prisma-db |      "RelationTable"."B" as "__ParentModel__"
nest-prisma-db |    from "default$default"."Course" as "Alias"
nest-prisma-db |      join "default$default"."_CourseToUser" as "RelationTable"
nest-prisma-db |      on "Alias"."id" = "RelationTable"."A"
nest-prisma-db |    where "RelationTable"."B" in ($1)
nest-prisma-db |    order by "RelationTable"."A" asc
nest-prisma-db | 2018-10-02 07:28:56.734 GMT [264] DETAIL:  parameters: $1 = 'cjmqbyb8k000l0a34zy9m55wb'

I'd like to know is this expected from Prisma server or is related to the issue we're already delaing with it?

The repo of the integration is here - https://github.com/tadejstanic/prisma-nestjs

[marktani]

Looking at my previous message again with a closer look, we can see that in step 2, there are actually two queries already!

SLOW QUERY - DURATION: 17
QUERY: [{"query":"{\n  users {\n    id\n    email\n    name\n  }\n}\n","variables":{}},{"query":"{\n  users {\n    id\n    email\n
   name\n  }\n}\n","variables":{}}]

The incoming object has this structure: [{"query":...}, {"query":...}]. So, this actually suggests that the error is in Prisma Client. Prisma Client takes in one query, and, using Apollo style Query Batching, duplicates the query and batches it up into one HTTP request.

[tadejstanic]

Great to hear that you've located the issue. Hope we can get the fix soon.

[zebapy]

I'm getting the same problem with this basic set up https://github.com/zebapy/fs-prisma

[will-hart]

As per #3106 using async / await in my mutation fixes this for me.

[tadejstanic]

@marktani do you have any updates on this issue? I've updated prisma to version 1.18.1 as well as prisma-client-lib 1.18.1, but two queries still exist.

[marktani]

Hey @tadejstanic, we are still struggling to reliably reproduce this, which makes fixing this bug very difficult. Unfortunatly, there are no further news yet!

[martinseanhunt]

I'm experiencing this same issue. It only seems to happen when I deploy the server and only happens on some deploys. If it is of any help, here is the repo for my very simple Yoga server: https://github.com/martinseanhunt/padgey-nation-backend

[divyenduz]

We tried to reproduce this with Prisma CLI version
divyendusingh [prisma]$ prisma version
prisma/1.20.0-alpha.33 (darwin-x64) node-v10.4.0

and Prisma server 1.17 and we were not able to reproduce this.

If there are any reliable reproductions, that would help. Thanks!

[arielschiavoni]

I am having the same issue with duplicated entries on my database (using mysql).

$ prisma version
prisma/1.19.0 (darwin-x64) node-v10.13.0

prisma container logs (I formatted the queries to show them more clearly)

SLOW QUERY - DURATION: 66
QUERY: 
[
  {
    "query": "mutation ($data: UserCreateInput!) {\n  createUser(data: $data) {\n    id\n    name\n    email\n    newsletter\n    currency\n    lang\n    createdAt\n    updatedAt\n  }\n}\n",
    "variables": { "data": { "name": "Ariel", "email": "[email protected]", "lang": "EN", "currency": "EUR" } }
  },
  {
    "query": "mutation ($data: UserCreateInput!) {\n  createUser(data: $data) {\n    id\n    name\n    email\n    newsletter\n    currency\n    lang\n    createdAt\n    updatedAt\n  }\n}\n",
    "variables": { "data": { "name": "Ariel", "email": "[email protected]", "lang": "EN", "currency": "EUR" } }
  }
]

The mutation and the model definition are quite simple.

export const Mutation = {
  createUser: (parent: any, args: any, ctx: Context) => {
    return ctx.db.createUser({ name, email });
  }
};

model

type User {
  id: ID! @unique
  name: String
  email: String
  newsletter: Boolean! @default(value: "false")
  currency: Currency
  lang: Lang
  projects: [Project!]!
  createdAt: DateTime!
  updatedAt: DateTime!
}

type Project {
  id: ID! @unique
  name: String
  user: User!
  createdAt: DateTime!
  updatedAt: DateTime!
}

[madhavpandey33]

@marktani I am relatively new to Prisma and GraphQL, have been getting this same issue for last couple days. I am not really sure how to get this to work correctly.
Is there any update available on this?

[mxstbr]

Can confirm that I'm also running into this, it's especially annoying with mutations as everything is created twice!

I can also confirm that @addstar34 workaround of using async/await fixes it, which is even stranger.