rolling update of the postgres cluster fails after upgrading spilo

[dududko]

Version 1.5.0

I've tried to upgrade the cluster that runs on spilo-11:1.5-p9 to spilo-12:1.6-p3
Unfortunately the rolling update did not finish successfully. Postgres on a new pod isn't able to start.

/var/run/postgresql:5432 - rejecting connections
2020-05-20 09:01:04,316 INFO: Lock owner: pg-0; I am pg-1
2020-05-20 09:01:04,316 INFO: Still starting up as a standby.
2020-05-20 09:01:04,317 INFO: Lock owner: pg-0; I am pg-1
2020-05-20 09:01:04,317 INFO: does not have lock
2020-05-20 09:01:04,317 INFO: establishing a new patroni connection to the postgres cluster
2020-05-20 09:01:04,446 INFO: establishing a new patroni connection to the postgres cluster
2020-05-20 09:01:04,450 WARNING: Retry got exception: 'connection problems'
2020-05-20 09:01:04,451 INFO: Error communicating with PostgreSQL. Will try again later

looks like the postgres is in the recovery mode

root@pg-1:/home/postgres# psql -d mydb -U postgres
psql: error: could not connect to server: FATAL:  the database system is starting up

What is the recommended way to upgrade spilo ?

[FxKu]

Changing the docker image in the configuration (or postgres manifest) should work. Did you do it this way? I would also check Postgres logs.

[boopathykpm]

Facing the same problem, but my criteria are different one, I created the Postgresql db cluster, which was successful, and to test the failover I have deleted the pod of the master. It's not up normally getting the error

/var/run/postgresql:5432 - rejecting connections
2020-05-26 13:25:53,222 INFO: Lock owner: None; I am test-backup-test-test-postgresql-0
2020-05-26 13:25:53,222 INFO: Still starting up as a standby.
2020-05-26 13:25:53,223 INFO: establishing a new patroni connection to the postgres cluster
2020-05-26 13:25:53,776 INFO: establishing a new patroni connection to the postgres cluster
2020-05-26 13:25:53,821 WARNING: Retry got exception: 'connection problems'
2020-05-26 13:25:53,821 INFO: Error communicating with PostgreSQL. Will try again later
/var/run/postgresql:5432 - rejecting connections
2020-05-26 13:26:03,221 INFO: Lock owner: None; I am test-backup-test-test-postgresql-0
2020-05-26 13:26:03,222 INFO: Still starting up as a standby.
2020-05-26 13:26:03,223 INFO: establishing a new patroni connection to the postgres cluster
2020-05-26 13:26:04,016 INFO: establishing a new patroni connection to the postgres cluster
2020-05-26 13:26:04,017 WARNING: Retry got exception: 'connection problems'
2020-05-26 13:26:04,021 INFO: Error communicating with PostgreSQL. Will try again later
/var/run/postgresql:5432 - rejecting connections
2020-05-26 13:26:13,221 INFO: Lock owner: None; I am test-backup-test-test-postgresql-0
2020-05-26 13:26:13,221 INFO: Still starting up as a standby.
2020-05-26 13:26:13,222 INFO: establishing a new patroni connection to the postgres cluster
2020-05-26 13:26:13,424 INFO: establishing a new patroni connection to the postgres cluster
2020-05-26 13:26:13,426 WARNING: Retry got exception: 'connection problems'
2020-05-26 13:26:13,426 INFO: Error communicating with PostgreSQL. Will try again later

The pod is not getting recovered completely.

[FxKu]

As I said, you should also check Postgres logs. Is Postgres running in the replica? Did the streaming work before? Was there a WAL delay? Can it replay WAL segments? Did something fail on the K8s side? Volume not correctly attached etc. Hard to tell from a distance.

[dududko]

@FxKu here are the logs

2020-06-02 17:17:12.819 UTC,,,23555,,5ed6889f.5c03,3,,2020-06-02 17:13:03 UTC,,0,LOG,00000,"received fast shutdown request",,,,,,,,,""
2020-06-02 17:17:12.821 UTC,,,23555,,5ed6889f.5c03,4,,2020-06-02 17:13:03 UTC,,0,LOG,00000,"aborting any active transactions",,,,,,,,,""
2020-06-02 17:17:12.824 UTC,,,23885,,5ed688a1.5d4d,2,,2020-06-02 17:13:05 UTC,,0,FATAL,57P01,"terminating walreceiver process due to administrator command",,,,,,,,,""
2020-06-02 17:17:12.824 UTC,"postgres","postgres",23890,"[local]",5ed688a2.5d52,3,"idle",2020-06-02 17:13:06 UTC,2/0,0,FATAL,57P01,"terminating connection due to administrator command",,,,,,,,,"Patroni"
2020-06-02 17:17:12.824 UTC,"postgres","postgres",23890,"[local]",5ed688a2.5d52,4,"idle",2020-06-02 17:13:06 UTC,,0,LOG,00000,"disconnection: session time: 0:04:06.801 user=postgres database=postgres host=[local]",,,,,,,,,"Patroni"
2020-06-02 17:17:12.829 UTC,,,23555,,5ed6889f.5c03,5,,2020-06-02 17:13:03 UTC,,0,LOG,00000,"background worker ""bg_mon"" (PID 23559) exited with exit code 1",,,,,,,,,""
2020-06-02 17:17:12.829 UTC,,,23882,,5ed688a1.5d4a,1,,2020-06-02 17:13:05 UTC,,0,LOG,00000,"shutting down",,,,,,,,,""
2020-06-02 17:17:12.829 UTC,,,23882,,5ed688a1.5d4a,2,,2020-06-02 17:13:05 UTC,,0,LOG,00000,"restartpoint starting: shutdown immediate",,,,,,,,,""
2020-06-02 17:17:12.861 UTC,,,23882,,5ed688a1.5d4a,3,,2020-06-02 17:13:05 UTC,,0,LOG,00000,"restartpoint complete: wrote 178 buffers (1.1%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.017 s, sync=0.003 s, total=0.032 s; sync files=83, longest=0.003 s, average=0.000 s; distance=16384 kB, estimate=16384 kB",,,,,,,,,""
2020-06-02 17:17:12.861 UTC,,,23882,,5ed688a1.5d4a,4,,2020-06-02 17:13:05 UTC,,0,LOG,00000,"recovery restart point at 0/9000028","Last completed transaction was at log time 2020-06-02 17:13:55.76321+00.",,,,,,,,""
2020-06-02 17:17:12.879 UTC,,,23555,,5ed6889f.5c03,6,,2020-06-02 17:13:03 UTC,,0,LOG,00000,"database system is shut down",,,,,,,,,""
2020-06-02 17:17:50.313 UTC,,,70,,5ed689be.46,1,,2020-06-02 17:17:50 UTC,,0,LOG,00000,"ending log output to stderr",,"Future log output will go to log destination ""csvlog"".",,,,,,,""
2020-06-02 17:17:50.401 UTC,,,73,,5ed689be.49,1,,2020-06-02 17:17:50 UTC,,0,LOG,00000,"database system was shut down in recovery at 2020-06-02 17:17:12 UTC",,,,,,,,,""
2020-06-02 17:17:50.409 UTC,,,78,"[local]",5ed689be.4e,1,"",2020-06-02 17:17:50 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-06-02 17:17:50.409 UTC,"postgres","postgres",78,"[local]",5ed689be.4e,2,"",2020-06-02 17:17:50 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-06-02 17:17:50.433 UTC,,,81,"[local]",5ed689be.51,1,"",2020-06-02 17:17:50 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-06-02 17:17:50.433 UTC,"postgres","postgres",81,"[local]",5ed689be.51,2,"",2020-06-02 17:17:50 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-06-02 17:17:51.074 UTC,,,94,"127.0.0.1:50038",5ed689bf.5e,1,"",2020-06-02 17:17:51 UTC,,0,LOG,00000,"connection received: host=127.0.0.1 port=50038",,,,,,,,,""
2020-06-02 17:17:51.074 UTC,"postgres","postgres",94,"127.0.0.1:50038",5ed689bf.5e,2,"",2020-06-02 17:17:51 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-06-02 17:17:51.447 UTC,,,96,"[local]",5ed689bf.60,1,"",2020-06-02 17:17:51 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-06-02 17:17:51.447 UTC,"postgres","postgres",96,"[local]",5ed689bf.60,2,"",2020-06-02 17:17:51 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-06-02 17:17:52.467 UTC,,,98,"[local]",5ed689c0.62,1,"",2020-06-02 17:17:52 UTC,,0,LOG,00000,"connection received: host=[local]",,,,,,,,,""
2020-06-02 17:17:52.467 UTC,"postgres","postgres",98,"[local]",5ed689c0.62,2,"",2020-06-02 17:17:52 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""
2020-06-02 17:17:53.076 UTC,,,99,"127.0.0.1:50048",5ed689c1.63,1,"",2020-06-02 17:17:53 UTC,,0,LOG,00000,"connection received: host=127.0.0.1 port=50048",,,,,,,,,""
2020-06-02 17:17:53.076 UTC,"postgres","postgres",99,"127.0.0.1:50048",5ed689c1.63,2,"",2020-06-02 17:17:53 UTC,,0,FATAL,57P03,"the database system is starting up",,,,,,,,,""

Also I attached the postgres configs before and after rolling update to a new version of spilo.

new.txt
old.txt

[dududko]

I was able to successfully upgrade to spilo-11:1.6-p1 and spilo-12:1.6-p2

There is still an issue wit rolling upgrade on spilo-12:1.6-p3, but it is possible to start a new cluster.

[dududko]

just in case

mydb=# select version();
                                                              version
-----------------------------------------------------------------------------------------------------------------------------------
 PostgreSQL 11.7 (Ubuntu 11.7-1.pgdg18.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 7.4.0-1ubuntu1~18.04.1) 7.4.0, 64-bit

[CyberDem0n]

@dududko during start postgres needs to apply WAL-s, which takes time. Your snippet contains less than 3 seconds of logs after the start. If there was a lot of activity on the cluster it could easily take up to a few minutes to replay WALs and reach recovery ending location and during that time postgres will refuse connections.

Also please have a look at postgresql-?.log files, maybe restore_command is failing?

[dududko]

@CyberDem0n I managed to reproduce this bug with empty database. Log statements look the same, there is only fatal log event that says the database system is starting up.

Here is the minimal reproduction config

apiVersion: "acid.zalan.do/v1"
kind: postgresql
metadata:
  name: dudko-alexey-postgresql
spec:
  teamId: "dudko-alexey"
  volume:
    size: 4Gi
  numberOfInstances: 2

  dockerImage: <docker image>

  postgresql:
    parameters:
      default_transaction_isolation: repeatable read
      log_statement: all
      max_connections: "16"
      shared_buffers: 128MB
    version: "11"

  resources:
    limits:
      cpu: 2000m
      memory: 512Mi
    requests:
      cpu: 200m
      memory: 128Mi

First apply it with dockerImage: registry.opensource.zalan.do/acid/spilo-12:1.6-p2, w8 till master and stand-by will start, then apply dockerImage: registry.opensource.zalan.do/acid/spilo-12:1.6-p3. The standby will rollout, but the database will be stuck in the infinite starting up state.

[CyberDem0n]

@dududko just posting manifests and configs here won't help you to solve the issue. You really have to check log files:

Also please have a look at postgresql-?.log files, maybe restore_command is failing?

[dududko]

There is literally nothing in logs, nothing that would give any hint to the cause of the problem.

root@dudko-alexey-postgresql-1:/home/postgres# cat pgdata/pgroot/pg_log/postgresql-2.log
2020-06-30 15:16:02 UTC [255]: [8-1] 5efb5732.ff 0     LOG:  ending log output to stderr
2020-06-30 15:16:02 UTC [255]: [9-1] 5efb5732.ff 0     HINT:  Future log output will go to log destination "csvlog".
ERROR: 2020/06/30 15:16:02.702066 Archive '00000002.history' does not exist.
ERROR: 2020/06/30 15:16:04.704941 Archive '000000010000000000000005' does not exist.
2020-06-30 15:16:53 UTC [70]: [8-1] 5efb5765.46 0     LOG:  ending log output to stderr
2020-06-30 15:16:53 UTC [70]: [9-1] 5efb5765.46 0     HINT:  Future log output will go to log destination "csvlog".
request expired, resigning
2020-06-30 15:27:02 UTC [70]: [8-1] 5efb59c6.46 0     LOG:  ending log output to stderr
2020-06-30 15:27:02 UTC [70]: [9-1] 5efb59c6.46 0     HINT:  Future log output will go to log destination "csvlog".

I also attached pgdata/pgroot/pg_log/postgresql-2.csv
postgresql-2.csv.txt

[CyberDem0n]

ERROR: 2020/06/30 15:16:04.704941 Archive '000000010000000000000005' does not exist.

And that you call nothing?

[dududko]

I'm a purblind....
Any ideas why this archive does not exist ? Why it is not copied from master ?

Btw, after several restarts it only prints the ERROR about a missing 00000002.history Archive.

[CyberDem0n]

If you didn't configured backup and log archiving that's sort of expected outcome. While replica was down the primary managed to recycle WALs.

[dududko]

ERROR: 2020/06/30 15:16:04.704941 Archive '000000010000000000000005' does not exist.

This morning I also found out that this error appears on the stand-by node after the first initialization of the postgres cluster (spilo-1.6p2), which means that this error is logged before I do the rolling upgrade to spilo-1.6p3. Also I found out that this log appears on each repeated restart of corrupted postgres worker.

ERROR: 2020/06/30 15:16:02.702066 Archive '00000002.history' does not exist.

But people say that it should not be the issue.

I have pvc, working replication, backups to s3, I have a working failover and switchover, also in the last setup I did not have any write operations to database (LSN almost does not change), the error log event, which is potentially related to this issue, is printed before the rolling update.

I feel confused. With all given information I do no know why after the rolling update to spilo-1.6p3 the revocery does not work. I will wait until someone else will report the same bug or reproduce it in their environment with the instruction I posted. Or maybe I am the only one who can't upgrade existing postgres cluster to spilo-1.6p3 ? Hope someone from the users community can share his experience.