pgo 4.5.0 scheduled backup failing with [UnknownError] remote-0 process on '10.244.140.50' terminated unexpectedly [255]: kex_exchange_identification: Connection closed by remote host\nERROR: [056]: unable to find primary cluster - cannot proceed\n]

[alrooney]

pgo 4.5.0

We are getting an intermittent error on backups as follows:

time="2021-06-07T06:00:15Z" level=info msg="pgo-backrest starts"
time="2021-06-07T06:00:15Z" level=info msg="debug flag set to false"
time="2021-06-07T06:00:15Z" level=info msg="backrest backup command requested"
time="2021-06-07T06:00:15Z" level=info msg="backrest command will be executed for both local and s3 storage"
time="2021-06-07T06:00:15Z" level=info msg="command to execute is [pgbackrest backup --stanza=db --type=full --repo1-retention-full=10 --db-host=10.244.140.50 --db-path=/pgdata/retroelk-prod-kdca && pgbackrest backup --stanza=db --type=full --repo1-retention-full=10 --db-host=10.244.140.50 --db-path=/pgdata/retroelk-prod-kdca --repo1-type=s3 --no-repo1-s3-verify-tls]"
time="2021-06-07T06:00:15Z" level=info msg="command is pgbackrest backup --stanza=db --type=full --repo1-retention-full=10 --db-host=10.244.140.50 --db-path=/pgdata/retroelk-prod-kdca && pgbackrest backup --stanza=db --type=full --repo1-retention-full=10 --db-host=10.244.140.50 --db-path=/pgdata/retroelk-prod-kdca --repo1-type=s3 --no-repo1-s3-verify-tls "
time="2021-06-07T06:22:50Z" level=error msg="command terminated with exit code 56"
time="2021-06-07T06:22:50Z" level=info msg="output=[]"
time="2021-06-07T06:22:50Z" level=info msg="stderr=[WARN: unable to check pg-1: [UnknownError] remote-0 process on '10.244.140.50' terminated unexpectedly [255]: kex_exchange_identification: Connection closed by remote host\nERROR: [056]: unable to find primary cluster - cannot proceed\n]"
time="2021-06-07T06:22:50Z" level=error msg="command terminated with exit code 56"

This is from a scheduled backup job ^

When we run the backup manually it works.

[alrooney]

Seems not intermittent. All scheduled backups are failing. Manual backups work fine for this cluster. On another cluster on same version of pgo and database the scheduled backups work fine.

[sergioisidoro]

Same thing here on V5

kex_exchange_identification: Connection closed by remote host

I have tried to reinitialise everything, but nothing worked. My current situation is that I was testing loss of backups. I cannot get pgbackrest to re-establish connection to the instances to create a new backup.

Running pgbackrest backup --stanza=db on repo backups just fine

[johnswarbrick-napier]

Did anyone find a solution to this issue?

Manual backups with pgbackrest backup --stanza=db seem to work fine, automated backups are not.

Constantly seeing these messages kex_exchange_identification: Connection closed by remote host in the logs from the pgbackrest container.

I assume the incoming SSH connection is coming from the repo-host container?

Running on vanilla Kubernetes v1.23.12 on Azure

[MichaelDBA]

I have a similar issue on my standby try when I first start it up:
I get a bunch of these:

2023-07-26 06:50:37.878 P00   INFO: archive-get:async command begin 2.43: [00000004001BB37300000087, 00000004001BB37300000088, 00000004001BB37300000089, 00000004001BB3730000008A, 00000004001BB3730000008B, 00000004001BB3730000008C, 00000004001BB3730000008D, 00000004001BB3730000008E, 00000004001BB3730000008F, 00000004001BB37300000090, 00000004001BB37300000091, 00000004001BB37300000092, 00000004001BB37300000093, 00000004001BB37300000094, 00000004001BB37300000095, 00000004001BB37300000096, 00000004001BB37300000097, 
...

Then I get this:

2023-07-26 06:50:37.878 P00   INFO: get 6400 WAL file(s) from archive: 00000004001BB37300000087...00000004001BB38C00000086
2023-07-26 06:50:38.963 P11   WARN: [FileReadError] raised from local-11 protocol: unable to get 00000004001BB37300000091:
                                    repo1: 9.6-1/00000004001BB373/00000004001BB37300000091-e3a6cd48052c4bfedee83ed9e3beb005932d0355.zst [UnknownError] remote-11 process on 'nyx-storage' terminated unexpectedly [255]: kex_exchange_identification: read: Connection reset by peer
                                    [FileReadError] on retry after 0ms: unable to get 00000004001BB37300000091:
                                    repo1: 9.6-1/00000004001BB373/00000004001BB37300000091-e3a6cd48052c4bfedee83ed9e3beb005932d0355.zst [UnknownError] remote-11 process on 'nyx-storage' terminated unexpectedly [255]: kex_exchange_identification: Connection closed by remote host
2023-07-26 06:50:38.964 P24   WARN: [FileReadError] raised from local-24 protocol: unable to get 00000004001BB3730000009E:
                                    repo1: 9.6-1/00000004001BB373/00000004001BB3730000009E-7760b57dcb8ae6a22bb58087410fe6ccc95575bc.zst [UnknownError] remote-24 process on 'nyx-storage' terminated unexpectedly [255]: kex_exchange_identification: read: Connection reset by peer
                                    [FileReadError] on retry after 0ms: unable to get 00000004001BB3730000009E:
                                    repo1: 9.6-1/00000004001BB373/00000004001BB3730000009E-7760b57dcb8ae6a22bb58087410fe6ccc95575bc.zst [UnknownError] remote-24 process on 'nyx-storage' terminated unexpectedly [255]: kex_exchange_identification: Connection closed by remote host

Then I start getting good messages like this:

2023-07-26 07:01:13.313 P00   INFO: archive-get:async command end: completed successfully (635438ms)

-------------------PROCESS START-------------------
2023-07-26 07:01:25.853 P00   INFO: archive-get:async command begin 2.43: [00000004001BB37300000036, 00000004001BB37300000037, 00000004001BB37300000038, 00000004001BB37300000039, 00000004001BB3730000003A, 00000004001BB3730000003B, 000000
04001BB3730000003C, 00000004001BB3730000003D, 00000004001BB3730000003E, 00000004001BB3730000003F, 00000004001BB37300000040, 00000004001BB37300000041, 00000004001BB37300000042, 00000004001BB37300000043, 00000004001BB37300000044, 000000040
01BB37300000045, 00000004001BB37300000046, 00000004001BB37300000047, 00000004001BB37300000048, 00000004001BB37300000049, 00000004001BB3730000004A, 00000004001BB3730000004B, 00000004001BB3730000004C, 00000004001BB3730000004D, 00000004001B
B3730000004E, 00000004001BB3730000004F, 00000004001BB37300000050, 00000004001BB37300000051, 00000004001BB37300000052, 00000004001BB37300000053, 00000004001BB37300000054, 00000004001BB37300000055, 00000004001BB37300000056, 00000004001BB37
300000057, 00000004001BB37300000058, 00000004001BB37300000059, 00000004001BB3730000005A, 00000004001BB3730000005B, 00000004001BB3730000005C, 00000004001BB3730000005D, 00000004001BB3730000005E, 00000004001BB3730000005F, 00000004001BB37300
000060, 00000004001BB37300000061, 00000004001BB37300000062, 00000004001BB37300000063, 00000004001BB37300000064, 00000004001BB37300000065, 00000004001BB37300000066, 00000004001BB37300000067, 00000004001BB37300000068, 00000004001BB37300000
069, 00000004001BB3730000006A, 00000004001BB3730000006B, 00000004001BB3730000006C, 00000004001BB3730000006D, 00000004001BB3730000006E, 00000004001BB3730000006F, 00000004001BB37300000070, 00000004001BB37300000071, 00000004001BB37300000072
, 00000004001BB37300000073, 00000004001BB37300000074, 00000004001BB37300000075, 00000004001BB37300000076, 00000004001BB37300000077, 00000004001BB37300000078, 00000004001BB37300000079, 00000004001BB3730000007A, 00000004001BB3730000007B, 0
0000004001BB3730000007C, 00000004001BB3730000007D, 00000004001BB3730000007E, 00000004001BB3730000007F, 00000004001BB37300000080, 00000004001BB37300000081, 00000004001BB37300000082, 00000004001BB37300000083, 00000004001BB37300000084, 0000
0004001BB37300000085, 00000004001BB37300000086, 00000004001BB37300000087, 00000004001BB37300000091, 00000004001BB3730000009E] --archive-async --archive-get-queue-max=100GB --buffer-size=16MiB --exec-id=129930-c9f786f1 --log-level-console
=off --log-level-file=info --log-level-stderr=off --log-path=/var/log/pgbackrest --log-timestamp --pg1-path=/postgres_mnt/nyx-pri_a/postgres_9.6 --process-max=15 --repo1-cipher-pass=<redacted> --repo1-cipher-type=aes-256-cbc --repo1-host
=nyx-storage --repo1-host-user=postgres --repo1-path=/nyx_storage/pgbackrest/repo --repo1-type=posix --spool-path=/postgres_mnt/postgres_wal/spool --stanza=prod_mt
2023-07-26 07:01:25.854 P00   INFO: get 84 WAL file(s) from archive: 00000004001BB37300000036...00000004001BB3730000009E
2023-07-26 07:01:35.001 P00   INFO: archive-get:async command end: completed successfully (9149ms)