flyctl postgres create failed

I followed the guide with the command flyctl postgres create. The cli was stuck at v0 is being deployed but i let it run for about 1 - 2 hours. I am using the lowest spec instance.

Finally it failed with the following log:

Waiting for logs...

2022-10-07T19:14:36.167 app[538ba9ea] sin [info] proxy | [WARNING] 279/191436 (569) : Server bk_db/pg1 is DOWN, reason: Layer7 timeout, check duration: 5001ms. 0 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.

2022-10-07T19:14:36.167 app[538ba9ea] sin [info] proxy | [NOTICE] 279/191436 (569) : haproxy version is 2.2.9-2+deb11u3

2022-10-07T19:14:36.167 app[538ba9ea] sin [info] proxy | [NOTICE] 279/191436 (569) : path to executable is /usr/sbin/haproxy

2022-10-07T19:14:36.167 app[538ba9ea] sin [info] proxy | [ALERT] 279/191436 (569) : backend 'bk_db' has no server available!

2022-10-07T19:14:40.938 app[538ba9ea] sin [info] exporter | INFO[0013] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:14:41.942 app[538ba9ea] sin [info] exporter | ERRO[0014] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:14:55.940 app[538ba9ea] sin [info] exporter | INFO[0028] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:14:56.941 app[538ba9ea] sin [info] exporter | ERRO[0029] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:15:10.940 app[538ba9ea] sin [info] exporter | INFO[0043] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:15:11.941 app[538ba9ea] sin [info] exporter | ERRO[0044] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:15:25.936 app[538ba9ea] sin [info] exporter | INFO[0058] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:15:26.939 app[538ba9ea] sin [info] exporter | ERRO[0059] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] panic: error checking stolon status: cannot create kv store: Put "https://consul-syd.fly-shared.net/v1/catalog/register?wait=5000ms": EOF

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] : exit status 1

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] goroutine 9 [running]:

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] main.main.func2(0xc0000d0000, 0xc000084a80)

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] /go/src/github.com/fly-examples/postgres-ha/cmd/start/main.go:81 +0x72c

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] created by main.main

2022-10-07T19:15:29.309 app[538ba9ea] sin [info] /go/src/github.com/fly-examples/postgres-ha/cmd/start/main.go:72 +0x43b

2022-10-07T19:15:29.989 app[538ba9ea] sin [info] Starting clean up.

2022-10-07T19:15:30.000 app[538ba9ea] sin [info] Umounting /dev/vdc from /data

2022-10-07T19:15:42.006 runner[538ba9ea] sin [info] Starting instance

2022-10-07T19:15:42.031 runner[538ba9ea] sin [info] Configuring virtual machine

2022-10-07T19:15:42.032 runner[538ba9ea] sin [info] Pulling container image

2022-10-07T19:15:44.236 runner[538ba9ea] sin [info] Unpacking image

2022-10-07T19:15:44.250 runner[538ba9ea] sin [info] Preparing kernel init

2022-10-07T19:15:44.395 runner[538ba9ea] sin [info] Setting up volume 'pg_data'

2022-10-07T19:15:44.525 runner[538ba9ea] sin [info] Configuring firecracker

2022-10-07T19:15:44.956 runner[538ba9ea] sin [info] Starting virtual machine

2022-10-07T19:15:45.109 app[538ba9ea] sin [info] Starting init (commit: 249766e)...

2022-10-07T19:15:45.127 app[538ba9ea] sin [info] Mounting /dev/vdc at /data w/ uid: 0, gid: 0 and chmod 0755

2022-10-07T19:15:45.132 app[538ba9ea] sin [info] Preparing to run: `docker-entrypoint.sh start` as root

2022-10-07T19:15:45.150 app[538ba9ea] sin [info] 2022/10/07 19:15:45 listening on [fdaa:0:7866:a7b:82:2:3d7d:2]:22 (DNS: [fdaa::3]:53)

2022-10-07T19:15:45.214 app[538ba9ea] sin [info] cluster spec filename /fly/cluster-spec.json

2022-10-07T19:15:45.214 app[538ba9ea] sin [info] system memory: 256mb vcpu count: 1

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] {

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "initMode": "new",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "existingConfig": {},

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "pgParameters": {

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "archive_command": "if [ $ENABLE_WALG ]; then /usr/local/bin/wal-g wal-push \"%p\"; fi",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "archive_mode": "on",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "archive_timeout": "60",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "effective_cache_size": "192MB",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "effective_io_concurrency": "200",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "maintenance_work_mem": "64MB",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "max_connections": "300",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "max_parallel_workers": "8",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "max_parallel_workers_per_gather": "2",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "max_wal_size": "97MB",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "max_worker_processes": "8",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "min_wal_size": "32MB",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "random_page_cost": "1.1",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "shared_buffers": "64MB",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "wal_compression": "on",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "wal_keep_size": "0",

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "work_mem": "4MB"

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] },

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "maxStandbysPerSender": 50,

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] "deadKeeperRemovalInterval": "1h"

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] }

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] generated new config

2022-10-07T19:15:45.215 app[538ba9ea] sin [info] keeper | Running...

2022-10-07T19:15:45.217 app[538ba9ea] sin [info] sentinel | Running...

2022-10-07T19:15:45.217 app[538ba9ea] sin [info] proxy | Running...

2022-10-07T19:15:45.221 app[538ba9ea] sin [info] exporter | Running...

2022-10-07T19:15:45.361 app[538ba9ea] sin [info] exporter | INFO[0000] Starting Server: :9187 source="postgres_exporter.go:1837"

2022-10-07T19:15:45.388 app[538ba9ea] sin [info] proxy | [WARNING] 279/191545 (545) : parsing [/fly/haproxy.cfg:38]: Missing LF on last line, file might have been truncated at position 96. This will become a hard error in HAProxy 2.3.

2022-10-07T19:15:45.411 app[538ba9ea] sin [info] proxy | [NOTICE] 279/191545 (545) : New worker #1 (569) forked

2022-10-07T19:15:46.215 app[538ba9ea] sin [info] checking stolon status

2022-10-07T19:15:47.473 app[538ba9ea] sin [info] proxy | [WARNING] 279/191547 (569) : bk_db/pg1 changed its IP from (none) to fdaa:0:7866:a7b:82:2:3d7d:2 by flydns/dns1.

2022-10-07T19:15:47.473 app[538ba9ea] sin [info] proxy | [WARNING] 279/191547 (569) : Server bk_db/pg1 ('sin.sp-api-db.internal') is UP/READY (resolves again).

2022-10-07T19:15:47.473 app[538ba9ea] sin [info] proxy | [WARNING] 279/191547 (569) : Server bk_db/pg1 administratively READY thanks to valid DNS answer.

2022-10-07T19:15:48.088 app[538ba9ea] sin [info] exporter | INFO[0002] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:15:49.092 app[538ba9ea] sin [info] exporter | ERRO[0003] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:15:52.209 app[538ba9ea] sin [info] proxy | [WARNING] 279/191552 (569) : Backup Server bk_db/pg is DOWN, reason: Layer7 timeout, check duration: 5001ms. 1 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.

2022-10-07T19:15:54.391 app[538ba9ea] sin [info] proxy | [WARNING] 279/191554 (569) : Server bk_db/pg1 is DOWN, reason: Layer7 timeout, check duration: 5000ms. 0 active and 0 backup servers left. 0 sessions active, 0 requeued, 0 remaining in queue.

2022-10-07T19:15:54.391 app[538ba9ea] sin [info] proxy | [NOTICE] 279/191554 (569) : haproxy version is 2.2.9-2+deb11u3

2022-10-07T19:15:54.391 app[538ba9ea] sin [info] proxy | [NOTICE] 279/191554 (569) : path to executable is /usr/sbin/haproxy

2022-10-07T19:15:54.391 app[538ba9ea] sin [info] proxy | [ALERT] 279/191554 (569) : backend 'bk_db' has no server available!

2022-10-07T19:15:55.941 app[538ba9ea] sin [info] exporter | INFO[0010] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:15:56.943 app[538ba9ea] sin [info] exporter | ERRO[0011] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:16:30.069 app[538ba9ea] sin [info] exporter | INFO[0044] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:16:31.071 app[538ba9ea] sin [info] exporter | ERRO[0045] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:16:45.072 app[538ba9ea] sin [info] exporter | INFO[0059] Established new database connection to "fdaa:0:7866:a7b:82:2:3d7d:2:5433". source="postgres_exporter.go:970"

2022-10-07T19:16:46.073 app[538ba9ea] sin [info] exporter | ERRO[0060] Error opening connection to database (postgresql://flypgadmin:PASSWORD_REMOVED@[fdaa:0:7866:a7b:82:2:3d7d:2]:5433/postgres?sslmode=disable): dial tcp [fdaa:0:7866:a7b:82:2:3d7d:2]:5433: connect: connection refused source="postgres_exporter.go:1658"

2022-10-07T19:16:47.539 app[538ba9ea] sin [info] keeper | 2022-10-07T19:16:47.538Z FATAL cmd/keeper.go:2118 cannot create keeper: cannot create store: cannot create kv store: Put "https://consul-syd.fly-shared.net/v1/catalog/register?wait=5000ms": EOF

2022-10-07T19:16:47.542 app[538ba9ea] sin [info] sentinel | 2022-10-07T19:16:47.540Z FATAL cmd/sentinel.go:2030 cannot create sentinel: cannot create store: cannot create kv store: Put "https://consul-syd.fly-shared.net/v1/catalog/register?wait=5000ms": EOF

2022-10-07T19:16:47.543 app[538ba9ea] sin [info] sentinel | exit status 1

2022-10-07T19:16:47.543 app[538ba9ea] sin [info] sentinel | restarting in 3s [attempt 1]

2022-10-07T19:16:47.543 app[538ba9ea] sin [info] keeper | exit status 1

2022-10-07T19:16:47.543 app[538ba9ea] sin [info] keeper | restarting in 5s [attempt 1]

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] panic: error checking stolon status: cannot create kv store: Put "https://consul-syd.fly-shared.net/v1/catalog/register?wait=5000ms": EOF

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] : exit status 1

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] goroutine 9 [running]:

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] main.main.func2(0xc0000d0000, 0xc000084a80)

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] /go/src/github.com/fly-examples/postgres-ha/cmd/start/main.go:81 +0x72c

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] created by main.main

2022-10-07T19:16:47.546 app[538ba9ea] sin [info] /go/src/github.com/fly-examples/postgres-ha/cmd/start/main.go:72 +0x43b

2022-10-07T19:16:48.211 app[538ba9ea] sin [info] Starting clean up.

2022-10-07T19:16:48.222 app[538ba9ea] sin [info] Umounting /dev/vdc from /data

Hey @karg,

That’s strange, mind giving it another try?

Sure, i try again tomorrow. Another thing to add, i am using singapore region, not sure if that is anything to do with the problem.

1 Like

All regions should behave the same in this case.

I am in the process to change how DATABASE_URL is set by flyctl, see Pass sslmode=disable in postgres DSN by dangra · Pull Request #1435 · superfly/flyctl · GitHub. That will be part of v0.0.427 for sure ready when you come back tomorrow :slight_smile:

1 Like