I’m not able to reliably reproduce this and as far as I can tell everything with the database is running correctly. I’ve seen a couple other posts on here with similar issues, but it doesn’t seem like there was any resolution. Are there any good debugging steps I should try?
I don’t have any experience with Prisma or Node applications, so I can’t speak to the specific details. However, I wonder if the command being executed in the release_command is not blocking until completed. Like if the Node app was performing the database operation async and the release_command completed/returned before the async operation was done.
I can imagine that creating a “sometimes” race condition issue.
An option is to have it execute some code explicitly under your control where you could log out different steps. Then you might be able to observe any async behavior.
I created the script below and set that as the release_command and I’m still seeing the same issue. The logs are also really difficult to parse. It seems like some logs are being duplicated or are showing up in the wrong order. If you look at some of the output below you can see the line Preparing to run: 'launcher bin/migrate-db.sh' as heroku and then right afterwards the line $ /workspace/node_modules/.bin/prisma migrate deploy. That doesn’t make sense, because I’d expect to see + env 'DEBUG=*' yarn prisma migrate deploy before that. There are also multiple copies of Preparing to run: 'launcher bin/migrate-db.sh' as heroku.
Any help would be greatly appreciated.
#!/usr/bin/env bash
set -o errexit # Fail on errors
set -o pipefail # Fail on errors in a pipeline
set -o nounset # Error when accessing an unset variable
set -o xtrace # Print each command before execution
# Leaving DEBUG=* in for now to help debug future issues. It doesn't produce
# that much output.
env 'DEBUG=*' yarn prisma migrate deploy &
sleep 60
wait
--> This release will not be available until the release command succeeds.
Starting instance
Configuring virtual machine
Pulling container image
Unpacking image
Preparing kernel init
Configuring firecracker
Starting virtual machine
Setting up swapspace version 1, size = 512 MiB (536866816 bytes)
no label, UUID=ebb8889a-db8a-4716-a95b-1cce796a802d
Preparing to run: `launcher bin/migrate-db.sh` as heroku
yarn run v1.22.19
$ /workspace/node_modules/.bin/prisma migrate deploy
2022-09-08T13:56:03.556Z prisma:engines binaries to download libquery-engine, migration-engine, introspection-engine, prisma-fmt
2022-09-08T13:56:03.835Z prisma:tryLoadEnv Environment variables not found at null
2022-09-08T13:56:03.836Z prisma:tryLoadEnv Environment variables not found at undefined
2022-09-08T13:56:03.862Z prisma:getConfig Using CLI Query Engine (Node-API Library) at: /workspace/node_modules/@prisma/engines/libquery_engine-debian-openssl-1.1.x.so.node
2022-09-08T13:56:03.914Z prisma:tryLoadEnv Environment variables not found at null
2022-09-08T13:56:03.915Z prisma:tryLoadEnv No Environment variables loaded
Prisma schema loaded from prisma/schema.prisma
2022-09-08T13:56:03.944Z prisma:getConfig Using CLI Query Engine (Node-API Library) at: /workspace/node_modules/@prisma/engines/libquery_engine-debian-openssl-1.1.x.so.node
2022-09-08T13:56:03.944Z prisma:getConfig Loaded Node-API Library
2022-09-08T13:56:03.971Z prisma:getConfig Using CLI Query Engine (Node-API Library) at: /workspace/node_modules/@prisma/engines/libquery_engine-debian-openssl-1.1.x.so.node
2022-09-08T13:56:03.971Z prisma:getConfig Loaded Node-API Library
2022-09-08T13:56:03.972Z prisma:getConfig config data retrieved without errors in getConfigNodeAPI
Starting instance
Configuring virtual machine
Pulling container image
Unpacking image
Preparing kernel init
Configuring firecracker
Starting virtual machine
Starting init (commit: 249766e)...
Setting up swapspace version 1, size = 512 MiB (536866816 bytes)
no label, UUID=ebb8889a-db8a-4716-a95b-1cce796a802d
Preparing to run: `launcher bin/migrate-db.sh` as heroku
2022/09/08 13:56:02 listening on [fdaa:0:72c9:a7b:9d34:83b5:29b0:2]:22 (DNS: [fdaa::3]:53)
+ sleep 60
+ env 'DEBUG=*' yarn prisma migrate deploy
yarn run v1.22.19
$ /workspace/node_modules/.bin/prisma migrate deploy
2022-09-08T13:56:03.556Z prisma:engines binaries to download libquery-engine, migration-engine, introspection-engine, prisma-fmt
2022-09-08T13:56:03.833Z prisma:loadEnv project root found at /workspace/package.json
2022-09-08T13:56:03.835Z prisma:tryLoadEnv Environment variables not found at null
2022-09-08T13:56:03.836Z prisma:tryLoadEnv Environment variables not found at undefined
2022-09-08T13:56:03.836Z prisma:tryLoadEnv No Environment variables loaded
2022-09-08T13:56:03.862Z prisma:getConfig Using CLI Query Engine (Node-API Library) at: /workspace/node_modules/@prisma/engines/libquery_engine-debian-openssl-1.1.x.so.node
2022-09-08T13:56:03.897Z prisma:getConfig Loaded Node-API Library
2022-09-08T13:56:03.913Z prisma:getConfig config data retrieved without errors in getConfigNodeAPI
2022-09-08T13:56:03.913Z prisma:loadEnv project root found at /workspace/package.json
2022-09-08T13:56:03.914Z prisma:tryLoadEnv Environment variables not found at null
Strange. This initial portion of the logs appears to be duplicated. It has the same timestamps. However, it diverges from that point on.
This makes me wonder if it is being run twice. Does the buildpack try to execute the migrations itself? If so, then the script is executing it explicitly and the buildpack (used to run the server) is doing it as well. If you don’t include the release_command for running the migrations, do they still show up in the logs?
I tend to use a Dockerfile instead of Heroku build packs for my own applications. I say that because in a Dockerfile I have more control (and knowledge) of what it’s doing. I’m out of my depth on particular issue.