database app suspended

Hi all, my app was working just fine, until yesterday i tried to log in, the website doesn’t log me in (as a user).
I checked the status, the main app is “deployed” but the database app is on “suspended”.
Here are the latest logs :

2023-05-11T22:20:55.515 app[e28657e6fd1508] cdg [info] monitor | Registered members: 1, Active member(s): 1, Inactive member(s): 0, Conflicts detected: 0

2023-05-11T22:21:04.196 app[e28657e6fd1508] cdg [info] repmgrd | [2023-05-11 22:21:04] [INFO] monitoring primary node "fdaa:2:cd6:a7b:126:77c9:c926:2" (ID: 601803615) in normal state

2023-05-11T22:25:55.542 app[e28657e6fd1508] cdg [info] monitor | Registered members: 1, Active member(s): 1, Inactive member(s): 0, Conflicts detected: 0

2023-05-11T22:26:04.579 app[e28657e6fd1508] cdg [info] repmgrd | [2023-05-11 22:26:04] [INFO] monitoring primary node "fdaa:2:cd6:a7b:126:77c9:c926:2" (ID: 601803615) in normal state

2023-05-11T22:30:55.388 app[e28657e6fd1508] cdg [info] Current connection count is 1

2023-05-11T22:30:56.349 app[e28657e6fd1508] cdg [info] Starting clean up.

2023-05-11T22:30:56.349 app[e28657e6fd1508] cdg [info] Umounting /dev/vdb from /data

2023-05-11T22:30:56.349 app[e28657e6fd1508] cdg [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-11T22:30:57.099 app[e28657e6fd1508] cdg [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-11T22:30:57.851 app[e28657e6fd1508] cdg [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-11T22:30:58.602 app[e28657e6fd1508] cdg [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-11T22:31:00.354 app[e28657e6fd1508] cdg [info] [ 3605.186941] reboot: Restarting system

2023-05-11T22:31:00.737 runner[e28657e6fd1508] cdg [info] machine exited with exit code 0, not restarting

would appreciate any help

2 Likes

Having the same experience, seems that something in the recent scale-to-zero/auto start/auto stop updates is not playing nicely.

Right now our Postgres database that stores website analytics for Umami is down in PRD

See screenshot below -

  • New Postgres DB created on 2nd of May, working great
  • 2023-05-12 09:16:45: App goes down and fails to restart (no notification)
  • 2023-05-14 01:09:01: Discover Postgres is down from failed web requests. After reading logs, increase volume size, restart machine, it lives for ~1 hour.
  • 2023-05-14 03:09:14: Notice Postgres failed to auto-start again on receiving web traffic, restart machine again, lives for another hour, then stops.

Here are the logs that I copied this morning:

2023-05-12T09:09:51.493 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-12T09:10:01.212 app[e286552dce6978] syd [info] repmgrd | [2023-05-12 09:10:01] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-12T09:14:51.378 app[e286552dce6978] syd [info] Current connection count is 1

2023-05-12T09:14:51.409 app[e286552dce6978] syd [info] Starting clean up.

2023-05-12T09:14:51.409 app[e286552dce6978] syd [info] Umounting /dev/vdb from /data

2023-05-12T09:14:51.410 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-12T09:14:52.162 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-12T09:14:52.913 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-12T09:14:53.664 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-12T09:14:55.238 health[e286552dce6978] syd [error] Health check for your postgres vm has failed. Your instance has hit resource limits. Upgrading your instance / volume size or reducing your usage might help.

2023-05-12T09:14:55.418 app[e286552dce6978] syd [info] [ 3604.276496] reboot: Restarting system

2023-05-12T09:14:56.194 runner[e286552dce6978] syd [info] machine exited with exit code 0, not restarting

2023-05-12T09:14:56.238 health[e286552dce6978] syd [error] Health check for your postgres database has failed. Your database is malfunctioning.

2023-05-14T01:17:36.886 app[e286552dce6978] syd [info] Starting init (commit: 15c0f38)...

2023-05-14T01:17:36.899 app[e286552dce6978] syd [info] Mounting /dev/vdb at /data w/ uid: 0, gid: 0 and chmod 0755

2023-05-14T01:17:36.941 app[e286552dce6978] syd [info] Preparing to run: `docker-entrypoint.sh start` as root

2023-05-14T01:17:36.957 app[e286552dce6978] syd [info] 2023/05/14 01:17:36 listening on [fdaa:2:6d9:a7b:f5:939c:7080:2]:22 (DNS: [fdaa::3]:53)

2023-05-14T01:17:37.125 app[e286552dce6978] syd [info] Configured scale to zero with duration of 1h0m0s

2023-05-14T01:17:37.125 app[e286552dce6978] syd [info] postgres | Running...

2023-05-14T01:17:37.127 app[e286552dce6978] syd [info] proxy | Running...

2023-05-14T01:17:37.130 app[e286552dce6978] syd [info] repmgrd | Running...

2023-05-14T01:17:37.130 app[e286552dce6978] syd [info] monitor | Running...

2023-05-14T01:17:37.132 app[e286552dce6978] syd [info] admin | Running...

2023-05-14T01:17:37.177 health[e286552dce6978] syd [warn] Health check for your postgres role is warning. Your cluster's membership might be affected.

2023-05-14T01:17:37.177 health[e286552dce6978] syd [warn] Health check for your postgres database is warning. Your database might be malfunctioning.

2023-05-14T01:17:37.177 health[e286552dce6978] syd [warn] Health check for your postgres vm is warning. Your instance might be hitting resource limits.

2023-05-14T01:17:37.187 app[e286552dce6978] syd [info] exporter | Running...

2023-05-14T01:17:37.277 app[e286552dce6978] syd [info] monitor | Monitoring dead members

2023-05-14T01:17:37.279 app[e286552dce6978] syd [info] monitor | Monitoring cluster state

2023-05-14T01:17:37.279 app[e286552dce6978] syd [info] monitor | Monitoring replication slots

2023-05-14T01:17:37.281 app[e286552dce6978] syd [info] monitor | Pruning every 24h0m0s...

2023-05-14T01:17:37.341 app[e286552dce6978] syd [info] proxy | [NOTICE] (538) : New worker (570) forked

2023-05-14T01:17:37.341 app[e286552dce6978] syd [info] proxy | [NOTICE] (538) : Loading success.

2023-05-14T01:17:37.347 app[e286552dce6978] syd [info] proxy | [WARNING] (570) : bk_db/pg1 changed its IP from (none) to fdaa:2:6d9:a7b:f5:939c:7080:2 by flydns/dns1.

2023-05-14T01:17:37.347 app[e286552dce6978] syd [info] proxy | [WARNING] (570) : Server bk_db/pg1 ('syd.kedyou-umami-prd.internal') is UP/READY (resolves again).

2023-05-14T01:17:37.347 app[e286552dce6978] syd [info] proxy | [WARNING] (570) : Server bk_db/pg1 administratively READY thanks to valid DNS answer.

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 01:17:37] [NOTICE] repmgrd (repmgrd 5.3.3) starting up

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 01:17:37] [INFO] connecting to database "host=fdaa:2:6d9:a7b:f5:939c:7080:2 port=5433 user=repmgr dbname=repmgr connect_timeout=5"

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 01:17:37] [ERROR] connection to database failed

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 01:17:37] [DETAIL]

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | connection to server at "fdaa:2:6d9:a7b:f5:939c:7080:2", port 5433 failed: Connection refused

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | Is the server running on that host and accepting TCP/IP connections?

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd |

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 01:17:37] [DETAIL] attempted to connect using:

2023-05-14T01:17:37.380 app[e286552dce6978] syd [info] repmgrd | user=repmgr connect_timeout=5 dbname=repmgr host=fdaa:2:6d9:a7b:f5:939c:7080:2 port=5433 fallback_application_name=repmgr options=-csearch_path=

2023-05-14T01:17:37.382 app[e286552dce6978] syd [info] repmgrd | exit status 6

2023-05-14T01:17:37.382 app[e286552dce6978] syd [info] repmgrd | restarting in 5s [attempt 1]

2023-05-14T01:17:37.382 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.382 UTC [536] LOG: starting PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit

2023-05-14T01:17:37.382 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.382 UTC [536] LOG: listening on IPv4 address "0.0.0.0", port 5433

2023-05-14T01:17:37.382 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.382 UTC [536] LOG: listening on IPv6 address "::", port 5433

2023-05-14T01:17:37.384 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.384 UTC [536] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"

2023-05-14T01:17:37.387 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.386 UTC [574] LOG: database system was interrupted; last known up at 2023-05-12 08:19:53 UTC

2023-05-14T01:17:37.435 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.435 UTC [574] LOG: database system was not properly shut down; automatic recovery in progress

2023-05-14T01:17:37.436 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.436 UTC [574] LOG: redo starts at 0/29CF928

2023-05-14T01:17:37.437 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.436 UTC [574] LOG: invalid record length at 0/29CFA10: wanted 24, got 0

2023-05-14T01:17:37.437 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.437 UTC [574] LOG: redo done at 0/29CF9D8 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s

2023-05-14T01:17:37.439 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.438 UTC [572] LOG: checkpoint starting: end-of-recovery immediate wait

2023-05-14T01:17:37.440 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.440 UTC [572] LOG: checkpoint complete: wrote 3 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.003 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB

2023-05-14T01:17:37.444 app[e286552dce6978] syd [info] postgres | 2023-05-14 01:17:37.443 UTC [536] LOG: database system is ready to accept connections

2023-05-14T01:17:38.180 app[e286552dce6978] syd [info] Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T01:17:38.267 app[e286552dce6978] syd [info] proxy | [NOTICE] (538) : haproxy version is 2.7.6-1~bpo11+1

2023-05-14T01:17:38.267 app[e286552dce6978] syd [info] proxy | [NOTICE] (538) : path to executable is /usr/sbin/haproxy

2023-05-14T01:17:38.267 app[e286552dce6978] syd [info] proxy | [ALERT] (538) : Current worker (570) exited with code 143 (Terminated)

2023-05-14T01:17:38.267 app[e286552dce6978] syd [info] proxy | [WARNING] (538) : All workers exited. Exiting... (0)

2023-05-14T01:17:38.267 app[e286552dce6978] syd [info] proxy | Process exited 0

2023-05-14T01:17:38.267 app[e286552dce6978] syd [info] proxy | restarting in 1s [attempt 1]

2023-05-14T01:17:39.268 app[e286552dce6978] syd [info] proxy | Running...

2023-05-14T01:17:39.279 app[e286552dce6978] syd [info] proxy | [NOTICE] (595) : New worker (597) forked

2023-05-14T01:17:39.279 app[e286552dce6978] syd [info] proxy | [NOTICE] (595) : Loading success.

2023-05-14T01:17:39.283 app[e286552dce6978] syd [info] proxy | [WARNING] (597) : bk_db/pg1 changed its IP from (none) to fdaa:2:6d9:a7b:f5:939c:7080:2 by flydns/dns1.

2023-05-14T01:17:39.283 app[e286552dce6978] syd [info] proxy | [WARNING] (597) : Server bk_db/pg1 ('syd.kedyou-umami-prd.internal') is UP/READY (resolves again).

2023-05-14T01:17:39.283 app[e286552dce6978] syd [info] proxy | [WARNING] (597) : Server bk_db/pg1 administratively READY thanks to valid DNS answer.

2023-05-14T01:17:42.179 health[e286552dce6978] syd [info] Health check for your postgres database is now passing.

And here are the latest logs:

$ fly logs -a kedyou-umami-prd

Waiting for logs...

2023-05-14T03:09:59.167 app[e286552dce6978] syd [info] postgres | Running...

2023-05-14T03:09:59.200 app[e286552dce6978] syd [info] proxy | Running...

2023-05-14T03:09:59.204 app[e286552dce6978] syd [info] repmgrd | Running...

2023-05-14T03:09:59.204 app[e286552dce6978] syd [info] monitor | Running...

2023-05-14T03:09:59.207 app[e286552dce6978] syd [info] admin | Running...

2023-05-14T03:09:59.258 app[e286552dce6978] syd [info] exporter | Running...

2023-05-14T03:09:59.347 app[e286552dce6978] syd [info] monitor | Monitoring dead members

2023-05-14T03:09:59.352 app[e286552dce6978] syd [info] monitor | Monitoring cluster state

2023-05-14T03:09:59.352 app[e286552dce6978] syd [info] monitor | Monitoring replication slots

2023-05-14T03:09:59.352 app[e286552dce6978] syd [info] monitor | Pruning every 24h0m0s...

2023-05-14T03:09:59.402 app[e286552dce6978] syd [info] proxy | [NOTICE] (541) : New worker (569) forked

2023-05-14T03:09:59.403 app[e286552dce6978] syd [info] proxy | [NOTICE] (541) : Loading success.

2023-05-14T03:09:59.422 app[e286552dce6978] syd [info] proxy | [WARNING] (569) : bk_db/pg1 changed its IP from (none) to fdaa:2:6d9:a7b:f5:939c:7080:2 by flydns/dns1.

2023-05-14T03:09:59.422 app[e286552dce6978] syd [info] proxy | [WARNING] (569) : Server bk_db/pg1 ('syd.kedyou-umami-prd.internal') is UP/READY (resolves again).

2023-05-14T03:09:59.422 app[e286552dce6978] syd [info] proxy | [WARNING] (569) : Server bk_db/pg1 administratively READY thanks to valid DNS answer.

2023-05-14T03:09:59.436 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.435 UTC [534] LOG: starting PostgreSQL 15.2 (Debian 15.2-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit

2023-05-14T03:09:59.436 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.436 UTC [534] LOG: listening on IPv4 address "0.0.0.0", port 5433

2023-05-14T03:09:59.436 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.436 UTC [534] LOG: listening on IPv6 address "::", port 5433

2023-05-14T03:09:59.436 health[e286552dce6978] syd [warn] Health check for your postgres database is warning. Your database might be malfunctioning.

2023-05-14T03:09:59.436 health[e286552dce6978] syd [warn] Health check for your postgres role is warning. Your cluster's membership might be affected.

2023-05-14T03:09:59.437 health[e286552dce6978] syd [warn] Health check for your postgres vm is warning. Your instance might be hitting resource limits.

2023-05-14T03:09:59.442 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.442 UTC [534] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"

2023-05-14T03:09:59.448 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.445 UTC [573] LOG: database system was interrupted; last known up at 2023-05-14 01:52:39 UTC

2023-05-14T03:09:59.449 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:09:59] [NOTICE] repmgrd (repmgrd 5.3.3) starting up

2023-05-14T03:09:59.449 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:09:59] [INFO] connecting to database "host=fdaa:2:6d9:a7b:f5:939c:7080:2 port=5433 user=repmgr dbname=repmgr connect_timeout=5"

2023-05-14T03:09:59.452 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.452 UTC [574] FATAL: the database system is starting up

2023-05-14T03:09:59.452 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:09:59] [ERROR] connection to database failed

2023-05-14T03:09:59.453 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:09:59] [DETAIL]

2023-05-14T03:09:59.453 app[e286552dce6978] syd [info] repmgrd | connection to server at "fdaa:2:6d9:a7b:f5:939c:7080:2", port 5433 failed: FATAL: the database system is starting up

2023-05-14T03:09:59.453 app[e286552dce6978] syd [info] repmgrd |

2023-05-14T03:09:59.453 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:09:59] [DETAIL] attempted to connect using:

2023-05-14T03:09:59.453 app[e286552dce6978] syd [info] repmgrd | user=repmgr connect_timeout=5 dbname=repmgr host=fdaa:2:6d9:a7b:f5:939c:7080:2 port=5433 fallback_application_name=repmgr options=-csearch_path=

2023-05-14T03:09:59.456 app[e286552dce6978] syd [info] repmgrd | exit status 6

2023-05-14T03:09:59.456 app[e286552dce6978] syd [info] repmgrd | restarting in 5s [attempt 1]

2023-05-14T03:09:59.507 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.507 UTC [573] LOG: database system was not properly shut down; automatic recovery in progress

2023-05-14T03:09:59.509 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.508 UTC [573] LOG: redo starts at 0/29E15F0

2023-05-14T03:09:59.509 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.509 UTC [573] LOG: invalid record length at 0/29E16D8: wanted 24, got 0

2023-05-14T03:09:59.509 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.509 UTC [573] LOG: redo done at 0/29E16A0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s

2023-05-14T03:09:59.511 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.511 UTC [571] LOG: checkpoint starting: end-of-recovery immediate wait

2023-05-14T03:09:59.513 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.513 UTC [571] LOG: checkpoint complete: wrote 3 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.003 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB

2023-05-14T03:09:59.515 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:09:59.515 UTC [534] LOG: database system is ready to accept connections

2023-05-14T03:10:00.265 app[e286552dce6978] syd [info] Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:10:00.442 app[e286552dce6978] syd [info] proxy | [NOTICE] (541) : haproxy version is 2.7.6-1~bpo11+1

2023-05-14T03:10:00.442 app[e286552dce6978] syd [info] proxy | [NOTICE] (541) : path to executable is /usr/sbin/haproxy

2023-05-14T03:10:00.442 app[e286552dce6978] syd [info] proxy | [ALERT] (541) : Current worker (569) exited with code 143 (Terminated)

2023-05-14T03:10:00.442 app[e286552dce6978] syd [info] proxy | [WARNING] (541) : All workers exited. Exiting... (0)

2023-05-14T03:10:00.443 app[e286552dce6978] syd [info] proxy | Process exited 0

2023-05-14T03:10:00.443 app[e286552dce6978] syd [info] proxy | restarting in 1s [attempt 1]

2023-05-14T03:10:01.444 app[e286552dce6978] syd [info] proxy | Running...

2023-05-14T03:10:01.457 app[e286552dce6978] syd [info] proxy | [NOTICE] (599) : New worker (601) forked

2023-05-14T03:10:01.457 app[e286552dce6978] syd [info] proxy | [NOTICE] (599) : Loading success.

2023-05-14T03:10:01.461 app[e286552dce6978] syd [info] proxy | [WARNING] (601) : bk_db/pg1 changed its IP from (none) to fdaa:2:6d9:a7b:f5:939c:7080:2 by flydns/dns1.

2023-05-14T03:10:01.461 app[e286552dce6978] syd [info] proxy | [WARNING] (601) : Server bk_db/pg1 ('syd.kedyou-umami-prd.internal') is UP/READY (resolves again).

2023-05-14T03:10:01.462 app[e286552dce6978] syd [info] proxy | [WARNING] (601) : Server bk_db/pg1 administratively READY thanks to valid DNS answer.

2023-05-14T03:10:04.456 app[e286552dce6978] syd [info] repmgrd | Running...

2023-05-14T03:10:04.483 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:10:04] [NOTICE] repmgrd (repmgrd 5.3.3) starting up

2023-05-14T03:10:04.483 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:10:04] [INFO] connecting to database "host=fdaa:2:6d9:a7b:f5:939c:7080:2 port=5433 user=repmgr dbname=repmgr connect_timeout=5"

2023-05-14T03:10:04.489 app[e286552dce6978] syd [info] repmgrd | INFO: set_repmgrd_pid(): provided pidfile is /tmp/repmgrd.pid

2023-05-14T03:10:04.489 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:10:04] [NOTICE] starting monitoring of node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389)

2023-05-14T03:10:04.489 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:10:04] [INFO] "connection_check_type" set to "ping"

2023-05-14T03:10:04.490 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:10:04] [NOTICE] monitoring cluster primary "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389)

2023-05-14T03:10:05.435 health[e286552dce6978] syd [info] Health check for your postgres vm is now passing.

2023-05-14T03:10:08.436 health[e286552dce6978] syd [info] Health check for your postgres role is now passing.

2023-05-14T03:10:11.436 health[e286552dce6978] syd [info] Health check for your postgres database is now passing.

2023-05-14T03:14:59.444 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:14:59.612 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:14:59.611 UTC [571] LOG: checkpoint starting: time

2023-05-14T03:15:00.016 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:15:00.015 UTC [571] LOG: checkpoint complete: wrote 5 buffers (0.2%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.402 s, sync=0.001 s, total=0.405 s; sync files=5, longest=0.001 s, average=0.001 s; distance=3 kB, estimate=3 kB

2023-05-14T03:15:04.952 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:15:04] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:19:59.444 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:20:05.325 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:20:05] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:24:59.448 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:25:05.844 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:25:05] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:29:59.453 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:30:06.346 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:30:06] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:34:59.472 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:35:06.791 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:35:06] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:39:59.471 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:40:07.265 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:40:07] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:44:59.468 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:45:07.700 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:45:07] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:49:59.472 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:50:08.160 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:50:08] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:54:59.485 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T03:54:59.690 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:54:59.689 UTC [571] LOG: checkpoint starting: time

2023-05-14T03:55:00.897 app[e286552dce6978] syd [info] postgres | 2023-05-14 03:55:00.897 UTC [571] LOG: checkpoint complete: wrote 13 buffers (0.4%); 0 WAL file(s) added, 0 removed, 0 recycled; write=1.205 s, sync=0.001 s, total=1.208 s; sync files=13, longest=0.001 s, average=0.001 s; distance=35 kB, estimate=35 kB

2023-05-14T03:55:08.607 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 03:55:08] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T03:59:59.479 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T04:00:09.021 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 04:00:09] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T04:04:59.483 app[e286552dce6978] syd [info] monitor | Voting member(s): 1, Active: 1, Inactive: 0, Conflicts: 0

2023-05-14T04:05:09.421 app[e286552dce6978] syd [info] repmgrd | [2023-05-14 04:05:09] [INFO] monitoring primary node "fdaa:2:6d9:a7b:f5:939c:7080:2" (ID: 826295389) in normal state

2023-05-14T04:09:59.229 app[e286552dce6978] syd [info] Current connection count is 1

2023-05-14T04:10:00.157 app[e286552dce6978] syd [info] Starting clean up.

2023-05-14T04:10:00.157 app[e286552dce6978] syd [info] Umounting /dev/vdb from /data

2023-05-14T04:10:00.157 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-14T04:10:00.442 health[e286552dce6978] syd [error] Health check for your postgres database has failed. Your database is malfunctioning.

2023-05-14T04:10:00.907 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-14T04:10:01.660 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-14T04:10:02.411 app[e286552dce6978] syd [info] error umounting /data: EBUSY: Device or resource busy, retrying in a bit

2023-05-14T04:10:04.164 app[e286552dce6978] syd [info] [ 3605.222328] reboot: Restarting system

2023-05-14T04:10:04.924 runner[e286552dce6978] syd [info] machine exited with exit code 0, not restarting

And the current machine status

Machine ID: e286552dce6978
Instance ID: 01GZBPZA5FVCSWB2NXZ56VYXHY
State: stopped

VM
  ID            = e286552dce6978                      
  Instance ID   = 01GZBPZA5FVCSWB2NXZ56VYXHY          
  State         = stopped                             
  Image         = flyio/postgres-flex:15.2 (v0.0.40)  
  Name          = lingering-glitter-9209              
  Private IP    = fdaa:2:6d9:a7b:f5:939c:7080:2       
  Region        = syd                                 
  Process Group =                                     
  CPU Kind      = shared                              
  vCPUs         = 1                                   
  Memory        = 256                                 
  Created       = 2023-05-01T13:10:31Z                
  Updated       = 2023-05-14T04:10:05Z                
  Command       =                                     
  Volume        = vol_nylzre2z6norqmkp                

Event Logs
STATE           EVENT   SOURCE  TIMESTAMP                       INFO                                              
stopped         exit    flyd    2023-05-14T12:10:05.074+08:00   exit_code=0,oom_killed=false,requested_stop=false
started         start   flyd    2023-05-14T11:09:59.054+08:00
starting        start   user    2023-05-14T11:09:58.734+08:00
stopped         exit    flyd    2023-05-14T10:17:42.998+08:00   exit_code=0,oom_killed=false,requested_stop=false
started         start   flyd    2023-05-14T09:17:36.96+08:00
1 Like

As a temporary work-around, I have overriden the default environment variable that enables scale to zero.

fly secrets set -a my-postgres-app-name FLY_SCALE_TO_ZERO=

The postgres app is now always online - it’s not ideal, but at least it’s not stuck in a suspended state.

2 Likes

I tried to do redeploy, without changing anything in the code. I get these error logs :

image: registry.fly.io/cycle:deployment-01H0DA09Q12FZ0X189SR9CAHHB
image size: 586 MB
Running cycle release_command: bin/rails db:prepare
  Waiting for 3d8d46db2d6538 to get exit event
Error release_command failed running on machine 3d8d46db2d6538 with exit code 1.
Check its logs: here's the last 100 lines below, or run 'fly logs -i 3d8d46db2d6538':
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/postgresql_adapter.rb:87:in `rescue in new_client'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/postgresql_adapter.rb:77:in `new_client'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/postgresql_adapter.rb:37:in `postgresql_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:656:in `public_send'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:656:in `new_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:700:in `checkout_new_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:679:in `try_to_checkout_new_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:640:in `acquire_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:341:in `checkout'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_handler.rb:211:in `retrieve_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_handling.rb:313:in `retrieve_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_handling.rb:280:in `connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:262:in `migrate'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:196:in `block in prepare_all'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:557:in `block (2 levels) in each_current_configuration'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:554:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:554:in `block in each_current_configuration'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:553:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:553:in `each_current_configuration'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:191:in `prepare_all'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/railties/databases.rake:391:in `block (2 levels) in <main>'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands/rake/rake_command.rb:24:in `block (2 levels) in perform'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands/rake/rake_command.rb:24:in `block in perform'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/rake_module.rb:59:in `with_application'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands/rake/rake_command.rb:18:in `perform'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/command.rb:51:in `invoke'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands.rb:18:in `<main>'
  /app/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.13.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
  /app/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.13.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
  Caused by:
  PG::ConnectionBad: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
  /app/vendor/bundle/ruby/3.2.0/gems/pg-1.4.4/lib/pg/connection.rb:632:in `async_connect_or_reset'
  /app/vendor/bundle/ruby/3.2.0/gems/pg-1.4.4/lib/pg/connection.rb:759:in `connect_to_hosts'
  /app/vendor/bundle/ruby/3.2.0/gems/pg-1.4.4/lib/pg/connection.rb:695:in `new'
  /app/vendor/bundle/ruby/3.2.0/gems/pg-1.4.4/lib/pg.rb:69:in `connect'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/postgresql_adapter.rb:78:in `new_client'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/postgresql_adapter.rb:37:in `postgresql_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:656:in `public_send'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:656:in `new_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:700:in `checkout_new_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:679:in `try_to_checkout_new_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:640:in `acquire_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:341:in `checkout'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_adapters/abstract/connection_handler.rb:211:in `retrieve_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_handling.rb:313:in `retrieve_connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/connection_handling.rb:280:in `connection'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:262:in `migrate'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:196:in `block in prepare_all'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:557:in `block (2 levels) in each_current_configuration'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:554:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:554:in `block in each_current_configuration'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:553:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:553:in `each_current_configuration'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/tasks/database_tasks.rb:191:in `prepare_all'
  /app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.0.4/lib/active_record/railties/databases.rake:391:in `block (2 levels) in <main>'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `each'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands/rake/rake_command.rb:24:in `block (2 levels) in perform'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands/rake/rake_command.rb:24:in `block in perform'
  /app/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/rake_module.rb:59:in `with_application'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands/rake/rake_command.rb:18:in `perform'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/command.rb:51:in `invoke'
  /app/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4/lib/rails/commands.rb:18:in `<main>'
  /app/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.13.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
  /app/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.13.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
  Tasks: TOP => db:prepare
  (See full trace by running task with --trace)
  Starting clean up.
  [   64.189034] reboot: Restarting system
  machine restart policy set to 'no', not restarting
Error: release command failed - aborting deployment. error release_command machine 3d8d46db2d6538 exited with non-zero status of 1

1 Like

this worked for me too !

1 Like

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.