Prisma1: Prisma deploy delay

[ardsh]

Describe the bug
When running prisma deploy, the deploy process handles an error as soon as it is executed, when trying to get the projects list. This causes the deploy process to take at least 60 seconds longer than it should.

The prisma-endpoint, prisma-secret and prisma-management-api-secret are correctly set, and the deploy process proceeds to finish successfully after 80+ seconds.

The error com.prisma.deploy.schema.AuthFailure: No 'Authorization' header provided is shown in the logs, when trying to run the { listProjects { name } } query.

To Reproduce
Steps to reproduce the behavior:

1. Run prisma deploy WITHOUT running prisma login or having a cloud account.
2. Get the logs e.g. docker-compose logs prisma
3. See error that was handled, but causes a delay of 60 seconds.

{"key":"error/handled","requestId":"local:cjujhrg1j003m0840b07ltqpe","payload":{"exception":"com.prisma.deploy.schema.AuthFailure: No 'Authorization' header provided.","query":"{\n        listProjects {\n          name\n        }\n      }","variables":"{}","code":"3015","stack_trace":"com.prisma.deploy.schema.SchemaBuilderImpl.verifyAuthOrThrow(SchemaBuilder.scala:317)\\n com.prisma.deploy.schema.SchemaBuilderImpl.$anonfun$listProjectsField$1(SchemaBuilder.scala:108)\\n sangria.execution.Resolver.resolveField(Resolver.scala:1024)\\n sangria.execution.Resolver.$anonfun$collectActionsPar$1(Resolver.scala:445)\\n scala.collection.TraversableOnce.$anonfun$foldLeft$1(TraversableOnce.scala:156)\\n scala.collection.TraversableOnce.$anonfun$foldLeft$1$adapted(TraversableOnce.scala:156)\\n scala.collection.Iterator.foreach(Iterator.scala:937)\\n scala.collection.Iterator.foreach$(Iterator.scala:937)\\n scala.collection.AbstractIterator.foreach(Iterator.scala:1425)\\n scala.collection.IterableLike.foreach(IterableLike.scala:70)\\n scala.collection.IterableLike.foreach$(IterableLike.scala:69)\\n scala.collection.AbstractIterable.foreach(Iterable.scala:54)\\n scala.collection.TraversableOnce.foldLeft(TraversableOnce.scala:156)\\n scala.collection.TraversableOnce.foldLeft$(TraversableOnce.scala:154)\\n scala.collection.AbstractTraversable.foldLeft(Traversable.scala:104)\\n sangria.execution.Resolver.collectActionsPar(Resolver.scala:439)\\n sangria.execution.Resolver.resolveFieldsPar(Resolver.scala:45)\\n sangria.execution.Executor.executeOperation(Executor.scala:155)\\n sangria.execution.Executor.$anonfun$execute$7(Executor.scala:97)\\n scala.concurrent.Future.$anonfun$flatMap$1(Future.scala:303)\\n scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:37)\\n scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)\\n akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)\\n akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:91)\\n scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)\\n scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:81)\\n akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:91)\\n akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)\\n akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:44)\\n akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)\\n akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)\\n akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)\\n akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)","message":"No 'Authorization' header provided."}}

Expected behavior
There should be no delay when running prisma deploy without being logged in prisma.

Versions (please complete the following information):

• Connector: Postgres
• Prisma Server: 1.30.1
• prisma CLI: prisma/1.30.1 (linux-x64) node-v8.15.1]
• OS: Ubuntu 18.04
• other dependencies: prisma-binding

[pantharshit00]

@ardsh

This has been already fixed in 1.31, please upgrade to that.

Closing as duplicate of #4343

[stevez86]

I'm getting this issue on 1.31

[artemzakharov]

I'm getting this in 1.32 and 1.33-beta, so it's definitely not fixed. In fact, I'm seeing deployment times of several _minutes_ at a time.

[pantharshit00]

@artemzakharov @stevez86

Can you please share your prisma.yml files so that we can try to reproduce this again?

[artemzakharov]

This is my prisma.yml file:

endpoint: ${env:PRISMA_ENDPOINT}

datamodel: datamodel.graphql

generate:
  - generator: graphql-schema
    output: ./../src/generated/prisma.graphql

hooks:
  post-deploy:
    - graphql codegen
    - yarn apollo-generate

this is the environment file I use when deploying to production (where this error actually happens):

PRISMA_STAGE="prod"
PRISMA_ENDPOINT="https://foo.herokuapp.com/foo-server/prod"
PRISMA_MANAGEMENT_API_SECRET="**********************************"
PRISMA_CLUSTER="foo/prod-server"
PRISMA_SECRET="secret"

this bug doesn't occur when deploying to the Prisma development servers, only when deploying to my production server, which is a Postgres database hosted in GCP connected to a Heroku server deployed via the the Heroku integration. (the server was upgraded to the latest version of Prisma, in this case 1.33.0-beta)

[pantharshit00]

cc @divyenduz

[nagman]

Same bug here with 1.32

[nagman]

EDIT:
I made a mistake while trying to export my prisma management api secret.

In my .env:

PRISMA_MANAGEMENT_API_SECRET=***************

In my terminal, before running prisma deploy:

export PRISMA_MANAGEMENT_SECRET=***************

I corrected it to:

export PRISMA_MANAGEMENT_API_SECRET=***************

And now it works (with 1.32).

[artemzakharov]

Just wanted to add that I've also tried deployments on both a local docker-compose instance and one hosted remotely (deployed by me, not through Heroku) and also got the error in both of those cases.

[primaryperson]

Same bug here with 1.33

[VRspace4]

1.33 with MySQL, same bug

[pantharshit00]

@primaryperson @VRspace4

Can you please share your prisma.yml files? Also, please make sure that a correct PRISMA_MANAGEMENT_API_SECRET environment variable is available to the CLI.

[JeongHwanMun]

Same bug
Prisma CLI version: prisma/1.34.0 (darwin-x64) node-v11.2.0
Prisma server version: 1.34.0

[marcosfede]

Same behaviour here with prisma docker image 1.34 and cli version 1.34.0, mysql database, node 10
PRISMA_MANAGEMENT_API_SECRET is correctly set

[gihrig]

In my case prisma deploy returns immediately with the message

Deploying servicedefaultto stagedefaultto serverlocal93ms Service is already up to date.

But the hello_prisma database is empty - no tables created

Prisma container log has the message:

"exception":"com.prisma.deploy.schema.AuthFailure: No 'Authorization' header provided."

mysqld.local.err contains:

Aborted connection 29 to db: 'prisma' user: 'root' host: 'localhost' (Got an error reading communication packets)

UPDATE: >>>>> I got things working with these steps:
docker-compose down
DROP DATABASE prisma (in sql client)
docker-compose up -d

prisma deploy builds out the hello_prisma database as expected in a few seconds.

---

Full log detail below.

Prisma CLI version: prisma/1.34.0 (darwin-x64) node-v12.4.0
Prisma server version: 1.34.0
macOS 10.14.5 (Mojave)
echo $PRISMA_MANAGEMENT_API_SECRET xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

Note that if managementApiSecret is commented out in docker-compose.yml there is no error logged to the Docker console and still no tables created in the DB.

docker-compose.yaml

version: '3'
services:
  prisma:
    image: prismagraphql/prisma:1.34
    restart: always
    ports:
    - "4466:4466"
    environment:
      PRISMA_CONFIG: |
        port: 4466
        managementApiSecret: ${PRISMA_MANAGEMENT_API_SECRET}
        databases:
          default:
            connector: mysql
            host: host.docker.internal
            database: hello_prisma
            user: root
            password: xxxxxxxx
            rawAccess: false
            port: '3306'
            migrations: false

prisma.yaml

endpoint: http://localhost:4466
datamodel: datamodel.prisma

generate:
  - generator: javascript-client
    output: ./generated/prisma-client/

datamodel.prisma

type User @db(name: "users") {
  id: ID! @unique @id(strategy: AUTO)
  email: String! @default(value: "")
  userName: String! @db(name: "user_name") @default(value: "")
  posts: [Post!]!
}

type Post @db(name: "posts") {
  id: ID! @unique @id(strategy: AUTO)
  title: String!
  published: Boolean! @default(value: false)
  author: User @relation(link: INLINE)
}

Prisma Container log

$ docker logs hello-prisma_prisma_1
No log level set, defaulting to INFO.
[INFO] {} - Started.
[INFO] {} - Started.
[INFO] {} - Close initiated...
[INFO] {} - Closed.
[INFO] Initializing workers...
[INFO] Obtaining exclusive agent lock...
[INFO] Obtaining exclusive agent lock... Successful.
[INFO] Successfully started 1 workers.
[INFO] Deployment worker initialization complete.
Server running on :4466
{"key":"error/handled","requestId":"local:cjwxxd7jo00020828ik6eyxrp","payload":{"exception":"com.prisma.deploy.schema.AuthFailure: No 'Authorization' header provided.","query":"{
        listProjects {
          name
        }
      }","variables":"{}","code":"3015","stack_trace":"com.prisma.deploy.schema.SchemaBuilderImpl.verifyAuthOrThrow(SchemaBuilder.scala:314)\
 com.prisma.deploy.schema.SchemaBuilderImpl.$anonfun$listProjectsField$1(SchemaBuilder.scala:108)\
 sangria.execution.Resolver.resolveField(Resolver.scala:1024)\
 sangria.execution.Resolver.$anonfun$collectActionsPar$1(Resolver.scala:445)\
 scala.collection.TraversableOnce.$anonfun$foldLeft$1(TraversableOnce.scala:156)\
 scala.collection.TraversableOnce.$anonfun$foldLeft$1$adapted(TraversableOnce.scala:156)\
 scala.collection.Iterator.foreach(Iterator.scala:937)\
 scala.collection.Iterator.foreach$(Iterator.scala:937)\
 scala.collection.AbstractIterator.foreach(Iterator.scala:1425)\
 scala.collection.IterableLike.foreach(IterableLike.scala:70)\
 scala.collection.IterableLike.foreach$(IterableLike.scala:69)\
 scala.collection.AbstractIterable.foreach(Iterable.scala:54)\
 scala.collection.TraversableOnce.foldLeft(TraversableOnce.scala:156)\
 scala.collection.TraversableOnce.foldLeft$(TraversableOnce.scala:154)\
 scala.collection.AbstractTraversable.foldLeft(Traversable.scala:104)\
 sangria.execution.Resolver.collectActionsPar(Resolver.scala:439)\
 sangria.execution.Resolver.resolveFieldsPar(Resolver.scala:45)\
 sangria.execution.Executor.executeOperation(Executor.scala:155)\
 sangria.execution.Executor.$anonfun$execute$7(Executor.scala:97)\
 scala.concurrent.Future.$anonfun$flatMap$1(Future.scala:303)\
 scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:37)\
 scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)\
 akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)\
 akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:91)\
 scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)\
 scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:81)\
 akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:91)\
 akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)\
 akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:44)\
 akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)\
 akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)\
 akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)\
 akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)","message":"No 'Authorization' header provided."}}
$ 

prisma.Migration (DB.Table) last entry roughly at time of starting Docker, status: SUCCESS

projectId   revision    schema  functions   status  applied rolledBack  steps   errors  startedAt   finishedAt  datamodel
default@default 11  {"models":[{"name":"User","stableIdentifier":"cjwvpqd2x000707725dbx9vtk","isEmbedded":false,"fields":[{"name":"id","typeIdentifier":"GraphQLID","isRequired":true,"isList":false,"isUnique":true,"isHidden":false,"isAutoGenerated":false,"behaviour":{"type":"id","strategy":"Auto","sequence":null}},{"name":"email","typeIdentifier":"String","isRequired":true,"isList":false,"isUnique":false,"isHidden":false,"isAutoGenerated":false,"defaultValue":{"gcValueType":"string","isList":false,"value":""}},{"name":"userName","typeIdentifier":"String","isRequired":true,"isList":false,"isUnique":false,"isHidden":false,"isAutoGenerated":false,"defaultValue":{"gcValueType":"string","isList":false,"value":""},"manifestation":{"dbName":"user_name"}},{"name":"posts","typeIdentifier":"Relation","isRequired":false,"isList":true,"isUnique":false,"isHidden":false,"isAutoGenerated":false,"relationName":"PostToUser","relationSide":"B"}],"manifestation":{"dbName":"users"}},{"name":"Post","stableIdentifier":"cjwwzoub50006083598qt7bcd","isEmbedded":false,"fields":[{"name":"id","typeIdentifier":"GraphQLID","isRequired":true,"isList":false,"isUnique":true,"isHidden":false,"isAutoGenerated":false,"behaviour":{"type":"id","strategy":"Auto","sequence":null}},{"name":"title","typeIdentifier":"String","isRequired":true,"isList":false,"isUnique":false,"isHidden":false,"isAutoGenerated":false},{"name":"published","typeIdentifier":"Boolean","isRequired":true,"isList":false,"isUnique":false,"isHidden":false,"isAutoGenerated":false,"defaultValue":{"gcValueType":"bool","isList":false,"value":false}},{"name":"author","typeIdentifier":"Relation","isRequired":false,"isList":false,"isUnique":false,"isHidden":false,"isAutoGenerated":false,"relationName":"PostToUser","relationSide":"A"}],"manifestation":{"dbName":"posts"}}],"relations":[{"name":"PostToUser","modelAId":"Post","modelBId":"User","modelAOnDelete":"SET_NULL","modelBOnDelete":"SET_NULL","manifestation":{"inTableOfModelId":"Post","referencingColumn":"author","relationManifestationType":"inline"}}],"enums":[],"version":"v2"}    []  SUCCESS 8   0   [{"name":"User","newName":"User","discriminator":"UpdateModel"},{"name":"Post","discriminator":"CreateModel"},{"model":"User","name":"posts","discriminator":"CreateField"},{"model":"Post","name":"id","discriminator":"CreateField"},{"model":"Post","name":"title","discriminator":"CreateField"},{"model":"Post","name":"published","discriminator":"CreateField"},{"model":"Post","name":"author","discriminator":"CreateField"},{"name":"PostToUser","discriminator":"CreateRelation"}]   []  2019-06-15 03:56:56 2019-06-15 03:56:56 type User @db(name: "users") {↵  id: ID! @unique @id(strategy: AUTO)↵  email: String! @default(value: "")↵  userName: String! @db(name: "user_name") @default(value: "")↵  posts: [Post!]!↵}↵↵type Post @db(name: "posts") {↵  id: ID! @unique @id(strategy: AUTO)↵  title: String!↵  published: Boolean! @default(value: false)↵  author: User @relation(link: INLINE)↵}↵↵

mysqld.local.err logs nothing when prisma deploy is run. But does log an error when the prisma server is started:

2019-06-15T22:05:22.753612Z 29 [Note] Aborted connection 29 to db: 'prisma' user: 'root' host: 'localhost' (Got an error reading communication packets)

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 10 days if no further activity occurs. Thank you for your contributions.