Prisma build error:

[remihuigen]

In general, I'm running into a lot of issues when trying to use prisma migrate when deploying to digitalocean app platform. I have a production app (and some staging/test apps) running on the app platform for a couple of months now, and guess that about 2/3 of the builds that contain pending migrations fail for some reason.

Usually after repeating the build process 3 or 4 times, the build eventually passes and deploys. However, it's still extremely frustrating when half of the pending migrations are applied during the build, and then halfway through the list of pending migrations the build fails. This results in a (live) DB that is out of sync with the keystone app (which causes fatal errors in both front and backend production apps)

How to reproduce

1. Create a postgres DB on digital ocean (it doesn't really matter if you use a connection pool or not)
2. Create an app on digitalocean (app platform), and supply DB_URL of the newly created postgres db
3. Deploy a keystone app with some lists and fields
4. Delete some fields in a local environment, run the app locally to update the migration history.
5. Deploy the updated app on digitalocean (incl. the migration history)

Usually, the process as described above will fail for some reason. Below, you'll find the three most regularly occurring errors (you'll also find more complete build logs further down):

1. Error: db error: ERROR: prepared statement "s..." does not exist
2. Error: Error in migration engine: db error: ERROR: prepared statement "s..." already exists
3. The database server at:was reached but timed out. Context: Timed out trying to acquire a postgres advisory lock (SELECT pg_advisory_lock(72707369)). Elapsed: 10000ms. See https://pris.ly/d/migrate-advisory-locking for details.

What did I expect

I expected Prisma to behave the way it's intended to behave

No screenshots, but I do have build logs for the errors mentioned above. They are not complete build logs, just the part where the errors occur (during prisma migrate):

BUILD LOGS EXAMPLE 1

[2022-02-23 11:19:02] Prisma schema loaded from schema.prisma
[2022-02-23 11:19:02] Datasource "postgresql": PostgreSQL database "<DBNAME>", schema "public" at "<DBHOST>:<DBPORT>"
[2022-02-23 11:19:03] 
[2022-02-23 11:19:03] 65 migrations found in prisma/migrations
[2022-02-23 11:19:03] 
[2022-02-23 11:19:03] Applying migration `20220215070924_add_membership_sorting`
[2022-02-23 11:19:03] Applying migration `20220215071456_add_gallery_to_places`
[2022-02-23 11:19:04] Applying migration `20220215073745_add_amenities`
[2022-02-23 11:19:04] Applying migration `20220215074909_add_local_hero`
[2022-02-23 11:19:04] Error: db error: ERROR: prepared statement "s22" does not exist
[2022-02-23 11:19:04]    0: migration_core::api::ApplyMigrations
[2022-02-23 11:19:04]              at migration-engine/core/src/api.rs:84
[2022-02-23 11:19:04] 
[2022-02-23 11:19:04] npm ERR! code ELIFECYCLE
[2022-02-23 11:19:04] npm ERR! errno 1
[2022-02-23 11:19:04] npm ERR! keystone@1.0.0 build: `keystone build && keystone prisma migrate deploy`
[2022-02-23 11:19:04] npm ERR! Exit status 1
[2022-02-23 11:19:04] npm ERR! 
[2022-02-23 11:19:04] npm ERR! Failed at the keystone@1.0.0 build script.
[2022-02-23 11:19:04] npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
[2022-02-23 11:19:04] 
[2022-02-23 11:19:04] npm ERR! A complete log of this run can be found in:
[2022-02-23 11:19:04] npm ERR!     /home/apps/.npm/_logs/2022-02-23T11_19_04_237Z-debug.log
[2022-02-23 11:19:04] building: exit status 1
[2022-02-23 11:19:04] ERROR: failed to build: exit status 1
[2022-02-23 11:19:17] 
[2022-02-23 11:19:17] For documentation on the buildpacks used to build your app, please see:
[2022-02-23 11:19:17]    Node.js: https://do.co/apps-buildpack-node
[2022-02-23 11:19:17] 
[2022-02-23 11:19:17]  ! Build failed (145)

BUILD LOGS EXAMPLE 2

[2022-02-18 17:14:18] Prisma schema loaded from schema.prisma
[2022-02-18 17:14:19] Datasource "postgresql": PostgreSQL database "<DBNAME>", schema "public" at "<DBHOST>:<DBPORT>"
[2022-02-18 17:14:19] Error: Error in migration engine: db error: ERROR: prepared statement "s1" already exists
[2022-02-18 17:14:19]    0: sql_migration_connector::flavour::postgres::ensure_connection_validity
[2022-02-18 17:14:19]            with self=PostgresFlavour { url: "<REDACTED>" } connection=Connection(Postgres((PostgreSql { client: PostgresClient, pg_bouncer: true, socket_timeout: None, statement_cache: Mutex { is_locked: false, has_waiters: false }, is_healthy: true }, PostgresUrl { url: Url { scheme: "postgresql", cannot_be_a_base: false, username: "<REDACTED>", password: Some("<REDACTED>"), host: Some(Domain("<REDACTED>")), port: Some(<REDACTED>), path: <REDACTED>l", query: Some("sslmode=require&connection_limit=3&pgbouncer=true&prepareThreshold=0&connection_timeout=30&pool_timeout=30&statement_cache_size=0"), fragment: None }, query_params: PostgresUrlQueryParams { ssl_params: SslParams { certificate_file: None, identity_file: None, identity_password: <HIDDEN>, ssl_accept_mode: AcceptInvalidCerts }, connection_limit: Some(3), schema: None, ssl_mode: Require, pg_bouncer: true, host: None, socket_timeout: None, connect_timeout: Some(5s), pool_timeout: Some(30s), statement_cache_size: 0, max_connection_lifetime: None, max_idle_connection_lifetime: Some(300s), application_name: None } })), Postgres(PostgresUrl { url: Url { scheme: "postgresql", cannot_be_a_base: false, username: "<REDACTED>", password: Some("<REDACTED>"), host: Some(Domain("<REDACTED>")), port: Some(<REDACTED>), path: "<REDACTED>", query: Some("sslmode=require&connection_limit=3&pgbouncer=true&prepareThreshold=0&connection_timeout=30&pool_timeout=30&statement_cache_size=0"), fragment: None }, query_params: PostgresUrlQueryParams { ssl_params: SslParams { certificate_file: None, identity_file: None, identity_password: <HIDDEN>, ssl_accept_mode: AcceptInvalidCerts }, connection_limit: Some(3), schema: None, ssl_mode: Require, pg_bouncer: true, host: None, socket_timeout: None, connect_timeout: Some(5s), pool_timeout: Some(30s), statement_cache_size: 0, max_connection_lifetime: None, max_idle_connection_lifetime: Some(300s), application_name: None } }))
[2022-02-18 17:14:19]              at migration-engine/connectors/sql-migration-connector/src/flavour/postgres.rs:282
[2022-02-18 17:14:19] npm ERR! code ELIFECYCLE
[2022-02-18 17:14:19] npm ERR! errno 1
[2022-02-18 17:14:19] npm ERR! keystone@1.0.0 build: `keystone build && keystone prisma migrate deploy`
[2022-02-18 17:14:19] npm ERR! Exit status 1
[2022-02-18 17:14:19] npm ERR! 
[2022-02-18 17:14:19] npm ERR! Failed at the keystone@1.0.0 build script.
[2022-02-18 17:14:19] npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
[2022-02-18 17:14:19] 
[2022-02-18 17:14:19] npm ERR! A complete log of this run can be found in:
[2022-02-18 17:14:19] npm ERR!     /home/apps/.npm/_logs/2022-02-18T17_14_19_836Z-debug.log
[2022-02-18 17:14:19] building: exit status 1
[2022-02-18 17:14:19] ERROR: failed to build: exit status 1
[2022-02-18 17:14:31] 
[2022-02-18 17:14:31] For documentation on the buildpacks used to build your app, please see:
[2022-02-18 17:14:31]    Node.js: https://do.co/apps-buildpack-node
[2022-02-18 17:14:31] 
[2022-02-18 17:14:31]  ! Build failed (145)

BUILD LOGS EXAMPLE 3

[2022-02-23 11:25:04] Prisma schema loaded from schema.prisma
[2022-02-23 11:25:04] Datasource "postgresql": PostgreSQL database ""<DBNAME>", schema "public" at ""<DBHOST>:"<DBPORT>"
[2022-02-23 11:25:05] 
[2022-02-23 11:25:05] 65 migrations found in prisma/migrations
[2022-02-23 11:25:05] 
[2022-02-23 11:25:15] Error: P1002
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] The database server at `"<DBHOST>`:`"<DBPORT>` was reached but timed out.
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] Please try again.
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] Please make sure your database server is running at `"<DBHOST>`:`"<DBPORT>`.
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] Context: Timed out trying to acquire a postgres advisory lock (SELECT pg_advisory_lock(72707369)). Elapsed: 10000ms. See https://pris.ly/d/migrate-advisory-locking for details.
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] npm ERR! code ELIFECYCLE
[2022-02-23 11:25:15] npm ERR! errno 1
[2022-02-23 11:25:15] npm ERR! keystone@1.0.0 build: `keystone build && keystone prisma migrate deploy`
[2022-02-23 11:25:15] npm ERR! Exit status 1
[2022-02-23 11:25:15] npm ERR! 
[2022-02-23 11:25:15] npm ERR! Failed at the keystone@1.0.0 build script.
[2022-02-23 11:25:15] npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
[2022-02-23 11:25:15] 
[2022-02-23 11:25:15] npm ERR! A complete log of this run can be found in:
[2022-02-23 11:25:15] npm ERR!     /home/apps/.npm/_logs/2022-02-23T11_25_15_603Z-debug.log
[2022-02-23 11:25:15] building: exit status 1
[2022-02-23 11:25:15] ERROR: failed to build: exit status 1
[2022-02-23 11:25:23] 
[2022-02-23 11:25:23] For documentation on the buildpacks used to build your app, please see:
[2022-02-23 11:25:23]    Node.js: https://do.co/apps-buildpack-node
[2022-02-23 11:25:23] 
[2022-02-23 11:25:23]  ! Build failed (145)

Some context:

• Container size or app plan on digitalocean doesn't make a difference
• Errors occur both with and without connection pooling (pgbouncer). (Connection pooling has it's own issues though, with pgbouncer and prisma not working well together. But that's a bug report for another time :) )
• I'm running postgres 13
• running on Node v12.22.10
• the DB URL query i'm using is (with a connection pool): ?sslmode=require&connection_limit=5&pgbouncer=true&prepareThreshold=0&connection_timeout=30&pool_timeout=30

I think the errors I mentioned above are related to the following issues: https://github.com/prisma/prisma/issues/4752 https://github.com/prisma/prisma/issues/6053

I must say: in general I really love working with Keystone! But the issues as mentioned are really frustrating when working on a production app... I'm not sure if it's a problem with digitalocean or with Keystone and the way it implements Prisma.

If any additional info is required, please let me know! Remi

[moselhy]

The advisory lock issue also happens with me on an Ubuntu VM hosted on Oracle, running Postgres 12.9, but seems to work fine on a Heroku app with a Postgres add-on

[henkvanderspek]

I'm having the same issue when developing on macOS with Postgres.app installed. First it couldn't connect because it seems to need user and password in the connection string, despite not being mentioned anywhere. Now I'm running into the advisory lock issue.

[remihuigen]

Okay, I did some more research and testing for the issues mentioned above, and came up with a workaround that seems to do the trick (at least partially). I'm not sure how this relates to local development, or any other cloudhosting than digital ocean (DO) w/ Postgres.

Anyway, the implementation discussed below seems to resolve the issues when deploying keystone to DO's app platform with Postgres 13.

First up, when running keystone in production, it is essential to use a connection pool (e.g PgBouncer). Otherwise, Prisma will just gobble up any available DB connection, and your gonna get a Error: P1001: Can't reach database server at .... See https://docs.digitalocean.com/products/databases/postgresql/how-to/manage-connection-pools/ for more info on how to set up connection pools for DO's managed databases. Make sure that you're using transaction mode and you add the flag pgbouncer=true to your connection string, so Prisma knows you're using a connection pool.

However, using a connection pool will result in new issues, namely not being able to use Prisma Migrate as part of the build process (which Keystone kinda forces you to do...). Here, you're gonna run into errors like: ERROR: prepared statement "s..." already exists. The only way to fix this (as far as I know) is to NOT use the connection pool when running prisma migrate command, but a direct connection to the DB. See https://www.prisma.io/docs/guides/performance-and-optimization/connection-management/configure-pg-bouncer for more context.

To summarize: you need to make sure the prisma migrate command uses a different connection string than the rest of the build proces. Since you can only use one variable in your keystone.ts file for the connection string that is used, my solution is to add extra env vars to track which part of the build process you're in:

in your .env / app-spec.yml

DATABASE_URL_MIGRATE=postgresql://{username}:{password}@{hostname}:25060/{DBNAME}?sslmode=require&connection_limit=1
DATABASE_URL_POOL=postgresql://{username}:{password}@{hostname}:25061/{POOLNAME}?sslmode=require&connection_limit=5&pgbouncer=true&prepareThreshold=0&connection_timeout=30&pool_timeout=30

Note: for direct DB connection, use port 25060. For connection pools, use port 25061. Note: At least the following flags are needed in DATABASE_URL_POOL:

• sslmode=require
• connection_limit= {depends on pool size}
• pgbouncer=true

in your package.json

"scripts": {
    "dev": "keystone dev",
    "postinstall": "cross-env STAGE=postinstall keystone postinstall",
    "build": "cross-env STAGE=build keystone build && cross-env STAGE=migrate keystone prisma migrate deploy && cross-env STAGE=build",
    "start": "cross-env STAGE=run keystone start"
  },
"devDependencies": {
    "cross-env": "^7.0.3"
  }

in your keystone.ts

export default config({
  db: {
      provider: 'postgresql',
      url: process.env.STAGE === 'migrate' ? process.env.DATABASE_URL_MIGRATE : process.env.DATABASE_URL_POOL,
      useMigrations: true,
    },
    // All other config stuff...
});

Lastly, I'm not sure if this also fixes the advisory lock issue, but I haven't seen this error since implementing the fix. If it does still show up, I'll give another update.