search

epicweb-dev / epic-stack

This is a Full Stack app starter with the foundational things setup and configured for you to hit the ground running on your next EPIC idea.
https://www.epicweb.dev/epic-stack
MIT License
4.89k stars 397 forks source link

Deployment fails on 2nd deployment due to Prisma migration error #598

Closed dchadcluff closed 10 months ago

dchadcluff commented 10 months ago

I just created a brand new Epic Stack to show someone how it worked. Ran through the setup following the docs and choosing the defaults. Deployed to Fly.io, which worked, and then setup a GitHub repo per the Deployment doc. Pushed the code and get a Prisma migration error.

Verified this by starting a new Epic Stack and doing it again, ensuring no code changes get made and following the instructions in the documentation. It also fails on the 1st push to GitHub (and the 2nd deployment to fly)

2024-01-17T03:50:11.294 app[***] den [info] level=INFO msg="executing command: npx [prisma migrate deploy]"

2024-01-17T03:50:13.191 app[***] den [info] Prisma schema loaded from prisma/schema.prisma

2024-01-17T03:50:13.209 app[***] den [info] Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"

2024-01-17T03:50:13.358 app[***] den [info] 1 migration found in prisma/migrations

2024-01-17T03:50:13.376 app[***] den [info] Error: P3009

2024-01-17T03:50:13.376 app[***] den [info] migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve

2024-01-17T03:50:13.376 app[***] den [info] The `20230914194400_init` migration started at 2024-01-17 03:29:22.043 UTC failed

Is there potentially some secret that's not getting set in Fly for the database location?

kentcdodds commented 10 months ago

I just tried the whole flow you described myself, and everything worked fine for me until I made a code change and attempted to deploy that.

Here were my steps.

I simply followed the prompts (answering "yes" to everything) when running npx create-epic-app@latest. I got these logs from fly for my new app:

2024-01-17T18:56:45Z runner[e7842095b46758] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCG5CZVHV9SPQMT3DVENYH
2024-01-17T18:56:54Z runner[e7842095b46758] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCG5CZVHV9SPQMT3DVENYH (8.813456925s)
2024-01-17T18:56:56Z runner[e7842095b46758] sjc [info]Configuring firecracker
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info][    0.036926] Spectre V2 : WARNING: Unprivileged eBPF is enabled with eIBRS on, data leaks possible via Spectre v2 BHB attacks!
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info][    0.042336] PCI: Fatal: No config space access function found
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info] INFO Preparing to run: `docker-entrypoint.sh node ./other/sentry-create-release` as root
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info]2024/01/17 18:56:56 listening on [fdaa:0:23df:a7b:247:fed8:b04f:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T18:56:56Z app[e7842095b46758] sjc [info]Missing Sentry environment variables, skipping sourcemap upload.
2024-01-17T18:56:57Z app[e7842095b46758] sjc [info] INFO Main child exited normally with code: 0
2024-01-17T18:56:57Z app[e7842095b46758] sjc [info] INFO Starting clean up.
2024-01-17T18:56:57Z app[e7842095b46758] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T18:56:57Z app[e7842095b46758] sjc [info]2024/01/17 18:56:57 listening on [fdaa:0:23df:a7b:247:fed8:b04f:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T18:56:58Z app[e7842095b46758] sjc [info][    2.285747] reboot: Restarting system
2024-01-17T18:56:58Z runner[e7842095b46758] sjc [info]machine restart policy set to 'no', not restarting
2024-01-17T18:57:03Z runner[4d891263c73228] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCG5CZVHV9SPQMT3DVENYH
2024-01-17T18:57:12Z runner[4d891263c73228] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCG5CZVHV9SPQMT3DVENYH (8.8635961s)
2024-01-17T18:57:13Z runner[4d891263c73228] sjc [info]Setting up volume 'data'
2024-01-17T18:57:13Z runner[4d891263c73228] sjc [info]Uninitialized volume 'data', initializing...
2024-01-17T18:57:13Z runner[4d891263c73228] sjc [info]Encrypting volume
2024-01-17T18:57:23Z runner[4d891263c73228] sjc [info]Opening encrypted volume
2024-01-17T18:57:25Z runner[4d891263c73228] sjc [info]Formatting volume
2024-01-17T18:57:26Z runner[4d891263c73228] sjc [info]Configuring firecracker
2024-01-17T18:57:26Z app[4d891263c73228] sjc [info][    0.046118] PCI: Fatal: No config space access function found
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info]2024/01/17 18:57:27 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T18:57:27Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T18:57:29Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T18:57:29Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T18:57:29Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T18:57:29Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T18:57:29Z app[4d891263c73228] sjc [info]level=INFO msg="ED3F21E451C67AB6: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="set cluster id on \"consul\" lease \"LFSCAB4F5C9336F57DD3\""
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="database file is zero length on initialization: /data/litefs/dbs/sqlite.db/database"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]wal
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="database file is zero length on initialization: /data/litefs/dbs/cache.db/database"
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]wal
2024-01-17T18:57:30Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]Applying migration `20230914194400_init`
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]The following migration have been applied:
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]migrations/
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]  └─ 20230914194400_init/
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]    └─ migration.sql
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]All migrations have been successfully applied.
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]level=INFO msg="starting background subprocess: npm [start]"
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]waiting for signal or subprocess to exit
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]> start
2024-01-17T18:57:32Z app[4d891263c73228] sjc [info]> cross-env NODE_ENV=production node .
2024-01-17T18:57:34Z app[4d891263c73228] sjc [info]🚀  We have liftoff!
2024-01-17T18:57:34Z app[4d891263c73228] sjc [info]Local:            http://localhost:8081
2024-01-17T18:57:34Z app[4d891263c73228] sjc [info]On Your Network:  http://172.19.6.186:8081
2024-01-17T18:57:34Z app[4d891263c73228] sjc [info]Press Ctrl+C to stop
2024-01-17T18:57:38Z app[4d891263c73228] sjc [info]prisma:query - 37ms - SELECT COUNT(*) FROM (SELECT `main`.`User`.`id` FROM `main`.`User` WHERE 1=1 LIMIT ? OFFSET ?) AS `sub`
2024-01-17T18:57:38Z app[4d891263c73228] sjc [info]HEAD / 200 - - 91.467 ms
2024-01-17T18:57:40Z app[4d891263c73228] sjc [info]GET / 200 - - 33.865 ms
2024-01-17T18:57:41Z app[4d891263c73228] sjc [info]GET / 200 - - 54.107 ms
2024-01-17T18:57:48Z app[4d891263c73228] sjc [info]HEAD / 200 - - 42.058 ms

Then I added the FLY_API_TOKEN and pushed to GitHub which triggered this build: https://github.com/kentcdodds/epic-stack-issue-598/actions/runs/7560505565

That deploy worked out fine:

2024-01-17T19:03:38Z runner[4d89666c333787] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCWBNJT7GRRP6G7PRN6M55
2024-01-17T19:03:39Z app[4d891263c73228] sjc [info]HEAD / 200 - - 26.387 ms
2024-01-17T19:03:48Z runner[4d89666c333787] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCWBNJT7GRRP6G7PRN6M55 (9.974991496s)
2024-01-17T19:03:49Z app[4d891263c73228] sjc [info]HEAD / 200 - - 18.170 ms
2024-01-17T19:03:49Z runner[4d89666c333787] sjc [info]Configuring firecracker
2024-01-17T19:03:50Z app[4d89666c333787] sjc [info][    0.039385] PCI: Fatal: No config space access function found
2024-01-17T19:03:50Z app[4d89666c333787] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:03:50Z app[4d89666c333787] sjc [info] INFO Preparing to run: `docker-entrypoint.sh node ./other/sentry-create-release` as root
2024-01-17T19:03:50Z app[4d89666c333787] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:03:50Z app[4d89666c333787] sjc [info]2024/01/17 19:03:50 listening on [fdaa:0:23df:a7b:b385:6c3:c230:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:03:50Z app[4d89666c333787] sjc [info]Missing Sentry environment variables, skipping sourcemap upload.
2024-01-17T19:03:51Z app[4d89666c333787] sjc [info] INFO Main child exited normally with code: 0
2024-01-17T19:03:51Z app[4d89666c333787] sjc [info] INFO Starting clean up.
2024-01-17T19:03:51Z app[4d89666c333787] sjc [info] WARN hallpass exited, pid: 306, status: signal: 15 (SIGTERM)
2024-01-17T19:03:51Z app[4d89666c333787] sjc [info]2024/01/17 19:03:51 listening on [fdaa:0:23df:a7b:b385:6c3:c230:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:03:52Z app[4d89666c333787] sjc [info][    2.326853] reboot: Restarting system
2024-01-17T19:03:52Z runner[4d89666c333787] sjc [info]machine restart policy set to 'no', not restarting
2024-01-17T19:03:54Z runner[4d891263c73228] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCWBNJT7GRRP6G7PRN6M55
2024-01-17T19:03:57Z runner[4d891263c73228] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMCCWBNJT7GRRP6G7PRN6M55 (2.913945449s)
2024-01-17T19:03:57Z runner[4d891263c73228] sjc [info]Setting up volume 'data'
2024-01-17T19:03:57Z runner[4d891263c73228] sjc [info]Opening encrypted volume
2024-01-17T19:03:58Z runner[4d891263c73228] sjc [info]Configuring firecracker
2024-01-17T19:03:58Z app[4d891263c73228] sjc [info] INFO Sending signal SIGINT to main child process w/ PID 313
2024-01-17T19:03:58Z app[4d891263c73228] sjc [info]sending signal to exec process
2024-01-17T19:03:58Z app[4d891263c73228] sjc [info]waiting for exec process to close
2024-01-17T19:03:59Z app[4d891263c73228] sjc [info] INFO Sending signal SIGTERM to main child process w/ PID 313
2024-01-17T19:04:00Z app[4d891263c73228] sjc [info]HEAD / 200 - - 20.342 ms
2024-01-17T19:04:05Z app[4d891263c73228] sjc [warn]Virtual machine exited abruptly
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info][    0.045898] PCI: Fatal: No config space access function found
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]2024/01/17 19:04:05 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: database \"cache.db\" has wal size of 12392 bytes within range of ltx file (@32, 12360 bytes)"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: truncating wal of \"sqlite.db\" from 807552 bytes to 12392 bytes to match ltx"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:04:05Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:04:06Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:06Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:06Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:07Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:07Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:07Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:08Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:08Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:08Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:09Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:09Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:09Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:10Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:10Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:10Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:11Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:11Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:11Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:12Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:12Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:12Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:14Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:14Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:14Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:15Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:15Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:15Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:16Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:16Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:16Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:17Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:17Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:17Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:18Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:18Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:18Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:19Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:19Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:19Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:21Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:04:21Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:04:21Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:04:22Z app[4d891263c73228] sjc [info]level=INFO msg="cannot release consul key: key=test-app-issue-598-3270-j3g8qv20nm01dvxy/epic-stack-litefs/test-app-issue-598-3270 session=2a20ba8b-471b-0c10-6e78-2593992d85d4"
2024-01-17T19:04:22Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: cannot acquire lease or find primary, retrying: no primary"
2024-01-17T19:04:23Z app[4d891263c73228] sjc [info]level=INFO msg="254EFFD1773CD8B6: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:04:23Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:04:23Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:04:23Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:04:23Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:04:23Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:04:24Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]Applying migration `20230914194400_init`
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]The following migration have been applied:
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]migrations/
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]  └─ 20230914194400_init/
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]    └─ migration.sql
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]All migrations have been successfully applied.
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]level=INFO msg="starting background subprocess: npm [start]"
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]waiting for signal or subprocess to exit
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]> start
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]> cross-env NODE_ENV=production node .
2024-01-17T19:04:28Z app[4d891263c73228] sjc [info]🚀  We have liftoff!
2024-01-17T19:04:28Z app[4d891263c73228] sjc [info]Local:            http://localhost:8081
2024-01-17T19:04:28Z app[4d891263c73228] sjc [info]On Your Network:  http://172.19.6.186:8081
2024-01-17T19:04:28Z app[4d891263c73228] sjc [info]Press Ctrl+C to stop
2024-01-17T19:04:30Z app[4d891263c73228] sjc [info]prisma:query - 38ms - SELECT COUNT(*) FROM (SELECT `main`.`User`.`id` FROM `main`.`User` WHERE 1=1 LIMIT ? OFFSET ?) AS `sub`
2024-01-17T19:04:30Z app[4d891263c73228] sjc [info]HEAD / 200 - - 91.225 ms

You'll notice logs from litefs because there's a bit of downtime between deploys (this is not a problem once you add another instance).

Then I made a code change and tried deploying again and that failed: https://github.com/kentcdodds/epic-stack-issue-598/actions/runs/7560580501

With these logs:

2024-01-17T19:08:47Z runner[9080d7da3e7987] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMCD5PRZJJAERQAJFM1A4B91
2024-01-17T19:08:51Z app[4d891263c73228] sjc [info]HEAD / 200 - - 12.685 ms
2024-01-17T19:08:56Z runner[9080d7da3e7987] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMCD5PRZJJAERQAJFM1A4B91 (9.448014779s)
2024-01-17T19:08:58Z runner[9080d7da3e7987] sjc [info]Configuring firecracker
2024-01-17T19:08:58Z app[9080d7da3e7987] sjc [info][    0.038123] PCI: Fatal: No config space access function found
2024-01-17T19:08:58Z app[9080d7da3e7987] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:08:58Z app[9080d7da3e7987] sjc [info] INFO Preparing to run: `docker-entrypoint.sh node ./other/sentry-create-release` as root
2024-01-17T19:08:58Z app[9080d7da3e7987] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:08:58Z app[9080d7da3e7987] sjc [info]2024/01/17 19:08:58 listening on [fdaa:0:23df:a7b:a3:c949:63de:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:08:59Z app[9080d7da3e7987] sjc [info]Missing Sentry environment variables, skipping sourcemap upload.
2024-01-17T19:08:59Z app[9080d7da3e7987] sjc [info] INFO Main child exited normally with code: 0
2024-01-17T19:08:59Z app[9080d7da3e7987] sjc [info] INFO Starting clean up.
2024-01-17T19:08:59Z app[9080d7da3e7987] sjc [info] WARN hallpass exited, pid: 306, status: signal: 15 (SIGTERM)
2024-01-17T19:08:59Z app[9080d7da3e7987] sjc [info]2024/01/17 19:08:59 listening on [fdaa:0:23df:a7b:a3:c949:63de:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:00Z app[9080d7da3e7987] sjc [info][    2.277508] reboot: Restarting system
2024-01-17T19:09:00Z runner[9080d7da3e7987] sjc [info]machine restart policy set to 'no', not restarting
2024-01-17T19:09:01Z app[4d891263c73228] sjc [info]HEAD / 200 - - 15.832 ms
2024-01-17T19:09:01Z runner[4d891263c73228] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMCD5PRZJJAERQAJFM1A4B91
2024-01-17T19:09:05Z runner[4d891263c73228] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMCD5PRZJJAERQAJFM1A4B91 (3.722986899s)
2024-01-17T19:09:05Z runner[4d891263c73228] sjc [info]Setting up volume 'data'
2024-01-17T19:09:05Z runner[4d891263c73228] sjc [info]Opening encrypted volume
2024-01-17T19:09:05Z runner[4d891263c73228] sjc [info]Configuring firecracker
2024-01-17T19:09:05Z app[4d891263c73228] sjc [info] INFO Sending signal SIGINT to main child process w/ PID 313
2024-01-17T19:09:05Z app[4d891263c73228] sjc [info]sending signal to exec process
2024-01-17T19:09:05Z app[4d891263c73228] sjc [info]waiting for exec process to close
2024-01-17T19:09:06Z app[4d891263c73228] sjc [info] INFO Sending signal SIGTERM to main child process w/ PID 313
2024-01-17T19:09:11Z app[4d891263c73228] sjc [warn]Virtual machine exited abruptly
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info][    0.043847] PCI: Fatal: No config space access function found
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info]2024/01/17 19:09:12 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:09:12Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: truncating wal of \"sqlite.db\" from 795192 bytes to 8272 bytes to match ltx"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:13Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:14Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:14Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:14Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:15Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:15Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:15Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:16Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:16Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:16Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:17Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:17Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:17Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:19Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:19Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:19Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:20Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:20Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:20Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:21Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:21Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:21Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:22Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:22Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:22Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:23Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:23Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:23Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:24Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:24Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:24Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:25Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:25Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:25Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:27Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:27Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:27Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:28Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: existing primary found (4d891263c73228), connecting as replica to \"http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202\""
2024-01-17T19:09:28Z app[4d891263c73228] sjc [info]level=INFO msg="http: POST /stream: error: cannot connect to self"
2024-01-17T19:09:28Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: disconnected from primary with error, retrying: connect to primary: invalid response: code=400 ('http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202')"
2024-01-17T19:09:29Z app[4d891263c73228] sjc [info]level=INFO msg="cannot release consul key: key=test-app-issue-598-3270-j3g8qv20nm01dvxy/epic-stack-litefs/test-app-issue-598-3270 session=596dad3c-493b-9cd7-91b2-9f0bf6824a78"
2024-01-17T19:09:29Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: cannot acquire lease or find primary, retrying: no primary"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:31Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]level=INFO msg="1141EFB33C6A67C1: exiting primary, destroying lease"
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]2024/01/17 19:09:33 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:34Z app[4d891263c73228] sjc [info][   22.357065] reboot: Restarting system
2024-01-17T19:09:34Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info][    0.043240] PCI: Fatal: No config space access function found
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]2024/01/17 19:09:35 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="002A70BE8BBD826A: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:09:35Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:36Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:09:37Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:09:37Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]level=INFO msg="002A70BE8BBD826A: exiting primary, destroying lease"
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:09:38Z app[4d891263c73228] sjc [info]2024/01/17 19:09:38 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:39Z app[4d891263c73228] sjc [info][    4.331339] reboot: Restarting system
2024-01-17T19:09:39Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:09:39Z app[4d891263c73228] sjc [info][    0.041840] PCI: Fatal: No config space access function found
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]2024/01/17 19:09:40 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="9DB14AAC3151DF53: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:09:40Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:41Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:09:42Z app[4d891263c73228] sjc [info]level=INFO msg="9DB14AAC3151DF53: exiting primary, destroying lease"
2024-01-17T19:09:43Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:09:43Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:09:43Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:09:43Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:09:43Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:09:43Z app[4d891263c73228] sjc [info]2024/01/17 19:09:43 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:44Z app[4d891263c73228] sjc [info][    4.321441] reboot: Restarting system
2024-01-17T19:09:44Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:09:44Z app[4d891263c73228] sjc [info][    0.042010] PCI: Fatal: No config space access function found
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]2024/01/17 19:09:45 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="722599736DCE4AA2: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:45Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:46Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:46Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:09:47Z app[4d891263c73228] sjc [info]level=INFO msg="722599736DCE4AA2: exiting primary, destroying lease"
2024-01-17T19:09:48Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:09:48Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:09:48Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:09:48Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:09:48Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:09:48Z app[4d891263c73228] sjc [info]2024/01/17 19:09:48 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:49Z app[4d891263c73228] sjc [info][    4.331814] reboot: Restarting system
2024-01-17T19:09:49Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info][    0.042142] PCI: Fatal: No config space access function found
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]2024/01/17 19:09:50 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="6CE54004D47286F8: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:09:50Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:51Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:09:52Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:09:52Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]level=INFO msg="6CE54004D47286F8: exiting primary, destroying lease"
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:09:53Z app[4d891263c73228] sjc [info]2024/01/17 19:09:53 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:54Z app[4d891263c73228] sjc [info][    4.331021] reboot: Restarting system
2024-01-17T19:09:54Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info][    0.043512] PCI: Fatal: No config space access function found
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]2024/01/17 19:09:55 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:09:55Z app[4d891263c73228] sjc [info]level=INFO msg="E45F9FBD7A4B65CA: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:09:56Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]level=INFO msg="E45F9FBD7A4B65CA: exiting primary, destroying lease"
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 389 and signal: SIGTERM, core dumped? false
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:09:58Z app[4d891263c73228] sjc [info]2024/01/17 19:09:58 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:09:59Z app[4d891263c73228] sjc [info][    4.323057] reboot: Restarting system
2024-01-17T19:09:59Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:10:01Z app[4d891263c73228] sjc [info][    0.043633] PCI: Fatal: No config space access function found
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]2024/01/17 19:10:02 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="2D6AF0AF1674E84B: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:10:02Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:10:03Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:10:03Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:03Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:03Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:03Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:03Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:10:04Z app[4d891263c73228] sjc [info]level=INFO msg="2D6AF0AF1674E84B: exiting primary, destroying lease"
2024-01-17T19:10:05Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:10:05Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:10:05Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:10:05Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:10:05Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:10:05Z app[4d891263c73228] sjc [info]2024/01/17 19:10:05 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:06Z app[4d891263c73228] sjc [info][    4.333326] reboot: Restarting system
2024-01-17T19:10:06Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:10:08Z app[4d891263c73228] sjc [info][    0.043118] PCI: Fatal: No config space access function found
2024-01-17T19:10:08Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]2024/01/17 19:10:09 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="938DF268A23421F8: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:10:11Z app[4d891263c73228] sjc [info]level=INFO msg="938DF268A23421F8: exiting primary, destroying lease"
2024-01-17T19:10:12Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:10:12Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 391 and signal: SIGTERM, core dumped? false
2024-01-17T19:10:12Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:10:12Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:10:12Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 315, status: signal: 15 (SIGTERM)
2024-01-17T19:10:12Z app[4d891263c73228] sjc [info]2024/01/17 19:10:12 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:13Z app[4d891263c73228] sjc [info][    4.324401] reboot: Restarting system
2024-01-17T19:10:13Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:10:15Z app[4d891263c73228] sjc [info][    0.042396] PCI: Fatal: No config space access function found
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]2024/01/17 19:10:16 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="3C5D84CB7D062326: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:10:16Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:10:17Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:10:17Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:17Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:17Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:17Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:17Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:10:18Z app[4d891263c73228] sjc [info]level=INFO msg="3C5D84CB7D062326: exiting primary, destroying lease"
2024-01-17T19:10:19Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:10:19Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 391 and signal: SIGTERM, core dumped? false
2024-01-17T19:10:19Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:10:19Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:10:19Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:10:19Z app[4d891263c73228] sjc [info]2024/01/17 19:10:19 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:20Z app[4d891263c73228] sjc [info][    4.328685] reboot: Restarting system
2024-01-17T19:10:20Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info][    0.043750] PCI: Fatal: No config space access function found
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]2024/01/17 19:10:22 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:10:22Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="E1DEF4295F71BA3B: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:10:23Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]level=INFO msg="E1DEF4295F71BA3B: exiting primary, destroying lease"
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:10:25Z app[4d891263c73228] sjc [info]2024/01/17 19:10:25 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:10:26Z app[4d891263c73228] sjc [info][    4.327949] reboot: Restarting system
2024-01-17T19:10:26Z runner[4d891263c73228] sjc [info]machine did not have a restart policy, defaulting to restart
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info][    0.041890] PCI: Fatal: No config space access function found
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh litefs mount` as root
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]2024/01/17 19:11:08 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]config file read from /etc/litefs.yml
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]LiteFS v0.5.8, commit=fd5808d0250cd17ec420225a010ec273971a471b
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="host environment detected" type=fly.io
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="no backup client configured, skipping"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="Using Consul to determine primary"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="initializing consul: key=epic-stack-litefs/test-app-issue-598-3270 url=https://:77bcb87e-7429-7bea-a39b-486f0eacb44e@consul-iad-9.fly-shared.net/test-app-issue-598-3270-j3g8qv20nm01dvxy/ hostname=4d891263c73228 advertise-url=http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: no wal file exists on \"cache.db\", skipping sync with ltx"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="wal-sync: short wal file exists on \"sqlite.db\", skipping sync with ltx"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="using existing cluster id: \"LFSCAB4F5C9336F57DD3\""
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="LiteFS mounted to: /litefs/data"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="http server listening on: http://localhost:20202"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="waiting to connect to cluster"
2024-01-17T19:11:08Z app[4d891263c73228] sjc [info]level=INFO msg="96EC3FA77393AAC5: primary lease acquired, advertising as http://4d891263c73228.vm.test-app-issue-598-3270.internal:20202"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="connected to cluster, ready"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="node is a candidate, automatically promoting to primary"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="node is already primary, skipping promotion"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="proxy server listening on: http://localhost:8080"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: node [./other/setup-swap.js]"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [/litefs/data/sqlite.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: sqlite3 [//litefs/data/cache.db PRAGMA journal_mode = WAL;]"
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]wal
2024-01-17T19:11:09Z app[4d891263c73228] sjc [info]level=INFO msg="executing command: npx [prisma migrate deploy]"
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]Error: P3009
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]The `20230914194400_init` migration started at 2024-01-17 19:04:25.974 UTC failed
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]npm notice
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]ERROR: cannot exec: sync cmd: cannot run command: exit status 1
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]level=INFO msg="96EC3FA77393AAC5: exiting primary, destroying lease"
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info] INFO Main child exited normally with code: 1
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info] WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-17T19:11:11Z app[4d891263c73228] sjc [info]2024/01/17 19:11:11 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-17T19:11:12Z app[4d891263c73228] sjc [info][    4.327238] reboot: Restarting system
2024-01-17T19:11:12Z runner[4d891263c73228] sjc [info]machine has reached its max restart count (10)

I'm not certain what caused the migration to fail, but this is definitely a problem. I'll try to find time to investigate further, but any help is appreciated!

kentcdodds commented 10 months ago

It should be noted that the Epic Stack template project is working fine, so there's probably something funny going on with a new project.

johntheo commented 10 months ago

Same issue with me! Failed in both machines: stagging and prod one.

I found this article here and was about to try: https://community.fly.io/t/issues-with-prisma-migrations/17045

@kentcdodds If I fork the Epic Stack template and create my project from there, is it supposed to work?

kentcdodds commented 10 months ago

Forking it shouldn't make any difference with the migration. Also, I'm not sure this is related because we didn't make any changes to the migration.

kentcdodds commented 10 months ago

What I find is interesting is that the error says:

2024-01-17T19:09:33Z app[4d891263c73228] sjc [info]The 20230914194400_init migration started at 2024-01-17 19:04:25.974 UTC failed

But if you look at the previous logs it says that migration was successful. This seems like a prisma issue to me. But I'm not sure what's going on.

2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-17T19:04:25Z app[4d891263c73228] sjc [info]Applying migration `20230914194400_init`
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]The following migration have been applied:
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]migrations/
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]  └─ 20230914194400_init/
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]    └─ migration.sql
2024-01-17T19:04:26Z app[4d891263c73228] sjc [info]All migrations have been successfully applied.
kentcdodds commented 10 months ago

Perhaps is a bug in the latest prisma. So I've updated all deps and we'll see if the Epic Stack deploy fails: https://github.com/epicweb-dev/epic-stack/commit/97d789f737380be318f57425be9040ce360b12ce

kentcdodds commented 10 months ago

That deploy worked ok. So it's unlikely to be a Prisma regression. But there's definitely something going wrong here. I'm afraid I don't have the resources to look into this right now so any help from anyone else is welcome.

shortjared commented 10 months ago

I did a bit of digging.

Looking at the sqlite database generated on fly.io, the _prisma_migrations does not have a finished_at value for the 20230914194400_init migration, as well as having an applied_steps_count of 0.

In a succesful dev migration copy of the database, these are the finished_at timestamp and 1 respectively.

Still not sure why this happening. Especially with Prisma claiming successful migration on the initial push. Even more odd, it seems that none of the tables actually exist in the fly.io db until after something in the app uses them.

shortjared commented 10 months ago

Alright. This is a wild one folks.

I suspect there is an odd interaction somewhere between Prisma migrations, SQLite and LiteFS at this point.

I realized that the database I was exporting and grabbing would slowly have more of the initial schema in it as I added more notes and played around in the app. After a fresh app, once I got the txnid of LiteFS up to 000000000000004d in LiteFS cloud I was able to see the entire schema as well as the _prisma_migration having a finished_at and applied_steps = 1.

I ran the deploy same base deploy again with no migration and it worked just fine this time.

I am able to consistently reproduce this. Deploy fresh app, create a bunch of actions on the database, second deploy now works. Someone that knows more about LiteFS and/or Prisma may have more of an idea why this happens.

weco-dev commented 10 months ago

Same issue here. Following.

I've created yesterday a fresh new app (and one today with the latest version) and the issue is still there. There is a perfectly working first deploy and then (in my case adding a secret to fly) the deployment process just stop.

I copy and paste the error I can see from the console (hope it helps)

  ...
  ERROR: cannot exec: sync cmd: cannot run command: exit status 1
  level=INFO msg="E6733A2A76EDAA60: exiting primary, destroying lease"
   INFO Main child exited normally with code: 1
   WARN Reaped child process with pid: 390 and signal: SIGTERM, core dumped? false
   INFO Starting clean up.
   INFO Umounting /dev/vdb from /data
   WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
  2024/01/18 10:56:20 listening on [fdaa:5:7167:a7b:251:a1b3:54e6:2]:22 (DNS: [fdaa::3]:53)
  [    4.257885] reboot: Restarting system
  machine did not have a restart policy, defaulting to restart
Error: smoke checks for 28756edb010738 failed: the app appears to be crashing
Error: Process completed with exit code 1.
...

Also, I may ask. Is there any way to bootstrap an old version of the EpicStack (if you think this can solve the current issue, as I'm starting from scratch right now)?

kentcdodds commented 10 months ago

I just removed LiteFS from the equation: https://github.com/kentcdodds/epic-stack-issue-598/commit/ce2e5086accd1f84f04d6efc4200b72c814cc1a7 (https://github.com/kentcdodds/epic-stack-issue-598/actions/runs/7572607626/job/20622905749)

That made a successful deploy:

2024-01-18T16:00:35.224 runner[6e82950c610187] sjc [info] Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMEMRS5R209EFXMTCDTZCKXJ
2024-01-18T16:00:43.477 runner[6e82950c610187] sjc [info] Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMEMRS5R209EFXMTCDTZCKXJ (8.252350125s)
2024-01-18T16:00:44.955 runner[6e82950c610187] sjc [info] Configuring firecracker
2024-01-18T16:00:45.081 app[6e82950c610187] sjc [info] [ 0.031453] PCI: Fatal: No config space access function found
2024-01-18T16:00:45.243 app[6e82950c610187] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-18T16:00:45.259 app[6e82950c610187] sjc [info] INFO Preparing to run: `docker-entrypoint.sh node ./other/sentry-create-release` as root
2024-01-18T16:00:45.267 app[6e82950c610187] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-18T16:00:45.275 app[6e82950c610187] sjc [info] 2024/01/18 16:00:45 listening on [fdaa:0:23df:a7b:a15f:b58:b459:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:00:45.514 app[6e82950c610187] sjc [info] Missing Sentry environment variables, skipping sourcemap upload.
2024-01-18T16:00:46.270 app[6e82950c610187] sjc [info] INFO Main child exited normally with code: 0
2024-01-18T16:00:46.270 app[6e82950c610187] sjc [info] INFO Starting clean up.
2024-01-18T16:00:46.271 app[6e82950c610187] sjc [info] WARN hallpass exited, pid: 306, status: signal: 15 (SIGTERM)
2024-01-18T16:00:46.274 app[6e82950c610187] sjc [info] 2024/01/18 16:00:46 listening on [fdaa:0:23df:a7b:a15f:b58:b459:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:00:47.270 app[6e82950c610187] sjc [info] [ 2.217452] reboot: Restarting system
2024-01-18T16:00:47.352 runner[6e82950c610187] sjc [info] machine restart policy set to 'no', not restarting
2024-01-18T16:00:48.522 runner[4d891263c73228] sjc [info] Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMEMRS5R209EFXMTCDTZCKXJ
2024-01-18T16:00:56.309 runner[4d891263c73228] sjc [info] Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMEMRS5R209EFXMTCDTZCKXJ (7.787589468s)
2024-01-18T16:00:56.331 runner[4d891263c73228] sjc [info] Setting up volume 'data'
2024-01-18T16:00:56.331 runner[4d891263c73228] sjc [info] Opening encrypted volume
2024-01-18T16:00:56.714 runner[4d891263c73228] sjc [info] Configuring firecracker
2024-01-18T16:00:57.106 app[4d891263c73228] sjc [info] [ 0.044550] PCI: Fatal: No config space access function found
2024-01-18T16:00:57.337 app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-18T16:00:57.360 app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-18T16:00:57.363 app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-18T16:00:57.364 app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh ./other/start.sh` as root
2024-01-18T16:00:57.372 app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-18T16:00:57.379 app[4d891263c73228] sjc [info] 2024/01/18 16:00:57 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:00:57.644 app[4d891263c73228] sjc [info] setting up swapfile...
2024-01-18T16:00:57.687 app[4d891263c73228] sjc [info] swapfile setup complete
2024-01-18T16:00:57.713 app[4d891263c73228] sjc [info] Error: unable to open database "/data/not-actually-litefs/data/sqlite.db": unable to open database file
2024-01-18T16:00:57.714 app[4d891263c73228] sjc [info] Error: unable to open database "//data/not-actually-litefs/data/cache.db": unable to open database file
2024-01-18T16:00:59.301 app[4d891263c73228] sjc [info] Prisma schema loaded from prisma/schema.prisma
2024-01-18T16:00:59.313 app[4d891263c73228] sjc [info] Datasource "db": SQLite database "sqlite.db" at "file:/data/not-actually-litefs/data/sqlite.db"
2024-01-18T16:00:59.401 app[4d891263c73228] sjc [info] SQLite database sqlite.db created at file:/data/not-actually-litefs/data/sqlite.db
2024-01-18T16:00:59.413 app[4d891263c73228] sjc [info] 1 migration found in prisma/migrations
2024-01-18T16:00:59.421 app[4d891263c73228] sjc [info] Applying migration `20230914194400_init`
2024-01-18T16:00:59.449 app[4d891263c73228] sjc [info] The following migration have been applied:
2024-01-18T16:00:59.449 app[4d891263c73228] sjc [info] migrations/
2024-01-18T16:00:59.449 app[4d891263c73228] sjc [info] └─ 20230914194400_init/
2024-01-18T16:00:59.449 app[4d891263c73228] sjc [info] └─ migration.sql
2024-01-18T16:00:59.449 app[4d891263c73228] sjc [info] All migrations have been successfully applied.
2024-01-18T16:00:59.513 app[4d891263c73228] sjc [info] npm notice
2024-01-18T16:00:59.513 app[4d891263c73228] sjc [info] npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-18T16:00:59.513 app[4d891263c73228] sjc [info] npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-18T16:00:59.514 app[4d891263c73228] sjc [info] npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-18T16:00:59.514 app[4d891263c73228] sjc [info] npm notice
2024-01-18T16:01:00.019 app[4d891263c73228] sjc [info] > start
2024-01-18T16:01:00.019 app[4d891263c73228] sjc [info] > cross-env NODE_ENV=production node .
2024-01-18T16:01:01.635 app[4d891263c73228] sjc [info] 🚀 We have liftoff!
2024-01-18T16:01:01.636 app[4d891263c73228] sjc [info] Local: http://localhost:8080
2024-01-18T16:01:01.636 app[4d891263c73228] sjc [info] On Your Network: http://172.19.6.186:8080
2024-01-18T16:01:01.636 app[4d891263c73228] sjc [info] Press Ctrl+C to stop
2024-01-18T16:01:06.748 app[4d891263c73228] sjc [info] HEAD / 200 - - 66.990 ms
2024-01-18T16:01:15.855 app[4d891263c73228] sjc [info] GET / 200 - - 27.957 ms

So I did another deploy to make sure a follow-up deploy works and it did: https://github.com/kentcdodds/epic-stack-issue-598/actions/runs/7572672223/job/20623113200

2024-01-18T16:04:27Z runner[3d8d9e3ec75778] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMEN10FKCJSY8WBWMNJGPRFX
2024-01-18T16:04:36Z runner[3d8d9e3ec75778] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMEN10FKCJSY8WBWMNJGPRFX (9.020982307s)
2024-01-18T16:04:37Z app[4d891263c73228] sjc [info]HEAD / 200 - - 19.980 ms
2024-01-18T16:04:38Z runner[3d8d9e3ec75778] sjc [info]Configuring firecracker
2024-01-18T16:04:38Z app[3d8d9e3ec75778] sjc [info][    0.042989] PCI: Fatal: No config space access function found
2024-01-18T16:04:38Z app[3d8d9e3ec75778] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-18T16:04:38Z app[3d8d9e3ec75778] sjc [info] INFO Preparing to run: `docker-entrypoint.sh node ./other/sentry-create-release` as root
2024-01-18T16:04:38Z app[3d8d9e3ec75778] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-18T16:04:38Z app[3d8d9e3ec75778] sjc [info]2024/01/18 16:04:38 listening on [fdaa:0:23df:a7b:16f:44c6:d11f:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:04:38Z app[3d8d9e3ec75778] sjc [info]Missing Sentry environment variables, skipping sourcemap upload.
2024-01-18T16:04:39Z app[3d8d9e3ec75778] sjc [info] INFO Main child exited normally with code: 0
2024-01-18T16:04:39Z app[3d8d9e3ec75778] sjc [info] INFO Starting clean up.
2024-01-18T16:04:39Z app[3d8d9e3ec75778] sjc [info] WARN hallpass exited, pid: 306, status: signal: 15 (SIGTERM)
2024-01-18T16:04:39Z app[3d8d9e3ec75778] sjc [info]2024/01/18 16:04:39 listening on [fdaa:0:23df:a7b:16f:44c6:d11f:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:04:40Z app[3d8d9e3ec75778] sjc [info][    2.315258] reboot: Restarting system
2024-01-18T16:04:40Z runner[3d8d9e3ec75778] sjc [info]machine restart policy set to 'no', not restarting
2024-01-18T16:04:41Z runner[4d891263c73228] sjc [info]Pulling container image registry.fly.io/test-app-issue-598-3270:deployment-01HMEN10FKCJSY8WBWMNJGPRFX
2024-01-18T16:04:44Z runner[4d891263c73228] sjc [info]Successfully prepared image registry.fly.io/test-app-issue-598-3270:deployment-01HMEN10FKCJSY8WBWMNJGPRFX (2.692441952s)
2024-01-18T16:04:44Z runner[4d891263c73228] sjc [info]Setting up volume 'data'
2024-01-18T16:04:44Z runner[4d891263c73228] sjc [info]Opening encrypted volume
2024-01-18T16:04:44Z runner[4d891263c73228] sjc [info]Configuring firecracker
2024-01-18T16:04:44Z app[4d891263c73228] sjc [info] INFO Sending signal SIGINT to main child process w/ PID 313
2024-01-18T16:04:46Z app[4d891263c73228] sjc [info] INFO Sending signal SIGTERM to main child process w/ PID 313
2024-01-18T16:04:46Z app[4d891263c73228] sjc [info] INFO Main child exited with signal (with signal 'SIGTERM', core dumped? false)
2024-01-18T16:04:46Z app[4d891263c73228] sjc [info] INFO Starting clean up.
2024-01-18T16:04:46Z app[4d891263c73228] sjc [info] INFO Umounting /dev/vdb from /data
2024-01-18T16:04:46Z app[4d891263c73228] sjc [info]ERROR error umounting /data: EBUSY: Device or resource busy, retrying in a bit
2024-01-18T16:04:47Z app[4d891263c73228] sjc [info]ERROR error umounting /data: EBUSY: Device or resource busy, retrying in a bit
2024-01-18T16:04:47Z app[4d891263c73228] sjc [info]HEAD / 200 - - 19.183 ms
2024-01-18T16:04:48Z app[4d891263c73228] sjc [info]ERROR error umounting /data: EBUSY: Device or resource busy, retrying in a bit
2024-01-18T16:04:48Z app[4d891263c73228] sjc [info]ERROR error umounting /data: EBUSY: Device or resource busy, retrying in a bit
2024-01-18T16:04:49Z app[4d891263c73228] sjc [info] WARN hallpass exited, pid: 314, status: signal: 15 (SIGTERM)
2024-01-18T16:04:49Z app[4d891263c73228] sjc [info]2024/01/18 16:04:49 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:04:50Z app[4d891263c73228] sjc [info][  233.593152] reboot: Restarting system
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info][    0.041856] PCI: Fatal: No config space access function found
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info] INFO Starting init (commit: 8995e367)...
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info] INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info] INFO Resized /data to 1056964608 bytes
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info] INFO Preparing to run: `docker-entrypoint.sh ./other/start.sh` as root
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info] INFO [fly api proxy] listening at /.fly/api
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info]2024/01/18 16:04:51 listening on [fdaa:0:23df:a7b:16c:3c5b:796a:2]:22 (DNS: [fdaa::3]:53)
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info]setting up swapfile...
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info]swapfile setup complete
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info]wal
2024-01-18T16:04:51Z app[4d891263c73228] sjc [info]wal
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]Prisma schema loaded from prisma/schema.prisma
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]Datasource "db": SQLite database "sqlite.db" at "file:/data/not-actually-litefs/data/sqlite.db"
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]1 migration found in prisma/migrations
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]No pending migrations to apply.
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]npm notice
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]npm notice New minor version of npm available! 10.2.4 -> 10.3.0
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.3.0>
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]npm notice Run `npm install -g npm@10.3.0` to update!
2024-01-18T16:04:53Z app[4d891263c73228] sjc [info]npm notice
2024-01-18T16:04:54Z app[4d891263c73228] sjc [info]> start
2024-01-18T16:04:54Z app[4d891263c73228] sjc [info]> cross-env NODE_ENV=production node .
2024-01-18T16:04:55Z app[4d891263c73228] sjc [info]🚀  We have liftoff!
2024-01-18T16:04:55Z app[4d891263c73228] sjc [info]Local:            http://localhost:8080
2024-01-18T16:04:55Z app[4d891263c73228] sjc [info]On Your Network:  http://172.19.6.186:8080
2024-01-18T16:04:55Z app[4d891263c73228] sjc [info]Press Ctrl+C to stop
2024-01-18T16:04:57Z app[4d891263c73228] sjc [info]HEAD / 200 - - 68.584 ms

So I'm pretty confident this is a LiteFS issue.

kentcdodds commented 10 months ago

Ok, @benbjohnson investigated and open an issue on LiteFS: https://github.com/superfly/litefs/issues/425

A fix is to just do migrations before setting up WAL. https://github.com/epicweb-dev/epic-stack/commit/d1947590d2c4604b12c4b83d29fc02e6cd30a4de

I haven't confirmed this solves the problem myself, so if someone else would like to do that, I would appreciate it!

weco-dev commented 10 months ago

@kentcdodds later in the day I'll make a test with the @latest and let you know.

In the meantime, trying to apply your patch didn't work as expected

 2024/01/19 07:45:53 listening on [fdaa:5:7167:a7b:251:a1b3:54e6:2]:22 (DNS: [fdaa::3]:53)
  node:internal/modules/esm/get_format:160
    throw new ERR_UNKNOWN_FILE_EXTENSION(ext, filepath);
          ^
  TypeError [ERR_UNKNOWN_FILE_EXTENSION]: Unknown file extension ".sh" for /myapp/other/start.sh
      at Object.getFileProtocolModuleFormat [as file:] (node:internal/modules/esm/get_format:160:9)
      at defaultGetFormat (node:internal/modules/esm/get_format:203:36)
      at defaultLoad (node:internal/modules/esm/load:143:22)
      at async ModuleLoader.load (node:internal/modules/esm/loader:409:7)
      at async ModuleLoader.moduleProvider (node:internal/modules/esm/loader:291:45)
      at async link (node:internal/modules/esm/module_job:76:21) {
    code: 'ERR_UNKNOWN_FILE_EXTENSION'
  }

I'm gonna investigate also on this later on. Thanks for time and support, it really helps

weco-dev commented 10 months ago

Temporary solved issue on .sh extension making a start.js file.

import { execSync } from 'child_process'

execSync("node ./other/setup-swap.js")
execSync("sqlite3 $DATABASE_PATH 'PRAGMA journal_mode = WAL;'")
execSync("sqlite3 $CACHE_DATABASE_PATH 'PRAGMA journal_mode = WAL;'")
execSync("npx prisma migrate deploy")
execSync("npm start")

Still, having some troubles finding the DB.

   INFO Starting init (commit: 8995e367)...
   INFO Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755
   INFO Resized /data to 1056964608 bytes
   INFO Preparing to run: `docker-entrypoint.sh ./other/start.js` as root
   INFO [fly api proxy] listening at /.fly/api
  2024/01/19 08:12:37 listening on [fdaa:5:7167:a7b:251:a1b3:54e6:2]:22 (DNS: [fdaa::3]:53)
  Error: unable to open database "/data/not-actually-litefs/data/sqlite.db": unable to open database file
  node:internal/errors:932
    const err = new Error(message);
                ^
  Error: Command failed: sqlite3 $DATABASE_PATH 'PRAGMA journal_mode = WAL;'
  Error: unable to open database "/data/not-actually-litefs/data/sqlite.db": unable to open database file
      at checkExecSyncError (node:child_process:890:11)
      at execSync (node:child_process:962:15)
      at file:///myapp/other/start.js:4:1
      at ModuleJob.run (node:internal/modules/esm/module_job:218:25)
      at async ModuleLoader.import (node:internal/modules/esm/loader:329:24)
      at async loadESM (node:internal/process/esm_loader:28:7)
      at async handleMainPromise (node:internal/modules/run_main:113:12) {

In a couple of hours I'll continue the debug with @latest

Yonatani commented 10 months ago

Hey guys, for some reason this issue is closed, are we sure its liteFS? im also having these errors in the past few days (tried to open several projects), trying to figure out whats wrong, will follow this topic as well 🙏

weco-dev commented 10 months ago

@kentcdodds the fix to do migrations before setting up WAL worked. I deployed for the second time on a new app created with epic-stack@latest and worked well.

dchadcluff commented 10 months ago

Applied the fix and it worked for me as well. I was able to submit several commits with successful deployments. And then I tried to modify the prisma schema and generate a new migration file. I end up getting the same error as before, failed migration. P3009

2024-01-22T03:03:02.731 app[3d8d111a537389] den [info] Prisma schema loaded from prisma/schema.prisma

2024-01-22T03:03:02.755 app[3d8d111a537389] den [info] Datasource "db": SQLite database "sqlite.db" at "file:/litefs/data/sqlite.db"

2024-01-22T03:03:02.841 app[3d8d111a537389] den [info] 2 migrations found in prisma/migrations

2024-01-22T03:03:02.852 app[3d8d111a537389] den [info] Error: P3009

2024-01-22T03:03:02.852 app[3d8d111a537389] den [info] migrate found failed migrations in the target database, new migrations will not be applied. Read more about how to resolve migration issues in a production database: https://pris.ly/d/migrate-resolve
paolotiu commented 10 months ago

For those following this is now fixed on v.0.5.11 with the pr https://github.com/superfly/litefs/pull/426

kentcdodds commented 10 months ago

Can someone confirm this actually fixes the issue of using WAL mode? I was under the impression that this doesn't fix WAL mode and instead just improves the error message, but I could be reading this wrong...

benbjohnson commented 10 months ago

@kentcdodds The change prevents WAL mode writes from being used with exclusive locking mode which will show as an error in the LiteFS logs. I posted an issue against the prisma-engines repository to see if they'd consider removing exclusive locking mode or making it optional. https://github.com/prisma/prisma-engines/issues/4675

kentcdodds commented 10 months ago

Good issue to up-vote everyone! Thanks Ben!

kennymcginnis commented 10 months ago

Can I still make comments on a Closed issue? I cannot deploy to fly - I have deployed once, but I am unable to redeploy a second time.

I have tried to move npx prisma migrate deploy before the WAL in my litefs.yml I have also tried updating flyio flyio/litefs:0.5.11 in my Dockerfile

Here is the error that I see...

 => [internal] load build definition from Dockerfile                                                                                                                                                                           0.3s
 => => transferring dockerfile: 2.17kB                                                                                                                                                                                         0.3s 
 => [internal] load .dockerignore                                                                                                                                                                                              0.2s 
 => => transferring context: 35B                                                                                                                                                                                               0.2s 
 => [internal] load metadata for docker.io/library/node:20-bookworm-slim                                                                                                                                                       0.4s
 => FROM docker.io/flyio/litefs:0.5.11                                                                                                                                                                                         0.1s
 => => resolve docker.io/flyio/litefs:0.5.11                                                                                                                                                                                   0.1s 
 => [base 1/2] FROM docker.io/library/node:20-bookworm-slim@sha256:b54988ddece70caaeb64f8952212bbbb3026ed58e5308f421fbee60a90717a74                                                                                            0.0s 
 => [internal] load build context                                                                                                                                                                                              0.9s 
 => => transferring context: 103.74kB                                                                                                                                                                                          0.9s 
 => CACHED [base 2/2] RUN apt-get update && apt-get install -y fuse3 openssl sqlite3 ca-certificates                                                                                                                           0.0s 
 => CACHED [stage-4  1/14] RUN echo "#!/bin/sh\nset -x\nsqlite3 $DATABASE_URL" > /usr/local/bin/database-cli && chmod +x /usr/local/bin/database-cli                                                                           0.0s 
 => CACHED [stage-4  2/14] WORKDIR /myapp                                                                                                                                                                                      0.0s 
 => CACHED [build 1/6] WORKDIR /myapp                                                                                                                                                                                          0.0s
 => [deps 2/3] ADD package.json package-lock.json .npmrc ./                                                                                                                                                                    0.0s 
 => [deps 3/3] RUN npm install --include=dev                                                                                                                                                                                  43.3s 
 => CACHED [build 2/6] COPY --from=deps /myapp/node_modules /myapp/node_modules                                                                                                                                                0.0s
 => [production-deps 3/4] ADD package.json package-lock.json .npmrc ./                                                                                                                                                         0.5s
 => [build 3/6] ADD prisma .                                                                                                                                                                                                   1.7s
 => CANCELED [production-deps 4/4] RUN npm prune --omit=dev                                                                                                                                                                    5.6s
 => ERROR [build 4/6] RUN npx prisma generate                                                                                                                                                                                  4.4s
------
 > [build 4/6] RUN npx prisma generate:
#0 1.528 Prisma schema loaded from schema.prisma
#0 4.276 Error:
#0 4.276 ✔ Generated Prisma Client (v5.8.1) to ./node_modules/@prisma/client in 408ms
#0 4.276
#0 4.276 Command failed: "/myapp/node_modules/.bin/mmdc" -i "/tmp/prisma-erd-NRnimi/prisma.mmd" -o "/myapp/ERD.svg" -c "/tmp/prisma-erd-NRnimi/config.json" -p "/tmp/prisma-erd-NRnimi/puppeteerConfig.json"
#0 4.276
#0 4.276
#0 4.308 npm notice
#0 4.308 npm notice New minor version of npm available! 10.2.4 -> 10.4.0
#0 4.308 npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.4.0>
#0 4.309 npm notice Run `npm install -g npm@10.4.0` to update!
#0 4.310 npm notice
------
Error: failed to fetch an image or build from source: error building: failed to solve: executor failed running [/bin/sh -c npx prisma generate]: exit code: 1
kentcdodds commented 10 months ago

Based on the error it looks like it's completely unrelated to anything in the Epic Stack. My guess is it's something wrong with this package that I'm guessing you added: https://www.npmjs.com/package/prisma-erd-generator

You'll have to try and understand the requirements for that package and make sure you update your dockerfile to satisfy those system requirements.

Or just remove the package because it looks like it's only necessary for development.

kennymcginnis commented 10 months ago

Thanks so much, @kentcdodds! And thanks for the quick response! I did not connect the dots between -erd- and the error message! I removed the package and was able to progress (finally)! phew!