Error while restoring a backup - first WAL file not found #2989

ksyblast · 2023-10-04T15:17:49Z

ksyblast
Oct 4, 2023

Hello!

Probably I misunderstand how Barman backup works, would appreciate if anybody clarifies how this could happen:

I have created a backup and configured S3 storage, backup startedAt: "2023-09-29T14:42:03Z"

{"level":"info","ts":"2023-09-29T14:42:01Z","msg":"WAL archiving is working","logging_pod":"cnpg-cluster-pg13-2"}
{"level":"info","ts":"2023-09-29T14:42:01Z","msg":"Backup started","backupName":"backup-example","backupNamespace":"backup-example","logging_pod":"cnpg-cluster-pg13-2","options":["--user","postgres","--cloud-provider","aws-s3","s3://postgres-cnpg/","cnpg-cluster-pg13"]}
{"level":"info","ts":"2023-09-29T14:43:04Z","msg":"Backup completed","backupName":"backup-example","backupNamespace":"backup-example","logging_pod":"cnpg-cluster-pg13-2"}

I tried to restore the cluster from object store and got this error:

{"level":"info","ts":"2023-10-04T14:52:21Z","msg":"Recovering from external cluster","logging_pod":"cnpg-restore-pg13-1-full-recovery","sourceName":"cnpg-cluster-pg13"}
{"level":"info","ts":"2023-10-04T14:52:23Z","msg":"Target backup found","logging_pod":"cnpg-restore-pg13-1-full-recovery","backup":{"backup_label":"'START WAL LOCATION: 1/59ADF6C0 (file 0000003D0000000100000059)\\nCHECKPOINT LOCATION: 1/5B7D2840\\nBACKUP METHOD: streamed\\nBACKUP FROM: standby\\nSTART TIME: 2023-09-29 14:42:03 UTC\\nLABEL: Barman backup cloud 20230929T144203\\nSTART TIMELINE: 61\\n'","begin_time":"Fri Sep 29 14:42:03 2023","end_time":"Fri Sep 29 14:42:56 2023","BeginTime":"2023-09-29T14:42:03Z","EndTime":"2023-09-29T14:42:56Z","begin_wal":"0000003D0000000100000059","end_wal":"0000003D000000010000005C","begin_xlog":"1/59ADF6C0","end_xlog":"1/5C000000","systemid":"7281241487361605658","backup_id":"20230929T144203","error":"","timeline":61}}
{"level":"error","ts":"2023-10-04T14:52:24Z","msg":"Error while restoring a backup","logging_pod":"cnpg-restore-pg13-1-full-recovery","error":"encountered an error while checking the presence of first needed WAL in the archive: file not found 0000003D0000000100000059: WAL not found","stacktrace":"github.com/cloudnative-pg/cloudnative-pg/pkg/management/log.(*logger).Error\n\tpkg/management/log/log.go:128\ngithub.com/cloudnative-pg/cloudnative-pg/pkg/management/log.Error\n\tpkg/management/log/log.go:166\ngithub.com/cloudnative-pg/cloudnative-pg/internal/cmd/manager/instance/restore.restoreSubCommand\n\tinternal/cmd/manager/instance/restore/cmd.go:89\ngithub.com/cloudnative-pg/cloudnative-pg/internal/cmd/manager/instance/restore.NewCmd.func2\n\tinternal/cmd/manager/instance/restore/cmd.go:60\ngithub.com/spf13/cobra.(*Command).execute\n\tpkg/mod/github.com/spf13/cobra@v1.7.0/command.go:940\ngithub.com/spf13/cobra.(*Command).ExecuteC\n\tpkg/mod/github.com/spf13/cobra@v1.7.0/command.go:1068\ngithub.com/spf13/cobra.(*Command).Execute\n\tpkg/mod/github.com/spf13/cobra@v1.7.0/command.go:992\nmain.main\n\tcmd/manager/main.go:64\nruntime.main\n\t/opt/hostedtoolcache/go/1.20.6/x64/src/runtime/proc.go:250"}

I tried to find this WAL file name in the logs and I see:

 {"level":"info","ts":"2023-09-29T13:47:50Z","logger":"wal-archive","msg":"Backup not configured, skip WAL archiving","logging_pod":"cnpg-cluster-pg13-1","walName":"pg_wal/0000003D0000000100000059","currentPrimary":"cnpg-cluster-pg13-1","targetPrimary":"cnpg-cluster-pg13-1"}

And indeed this file is missing at S3. How could that happen that barman starts with an unexisting WAL file?
Recovery config:

  bootstrap:
    recovery:
      source: cnpg-cluster-pg13
      recoveryTarget:
        targetTime: "2023-10-01 15:22:00.00000+00"


  externalClusters:
  - name: cnpg-cluster-pg13
    barmanObjectStore:
      destinationPath: "s3://postgres-cnpg/"
...

Backup config:

apiVersion: postgresql.cnpg.io/v1
kind: Backup
metadata:
  name: backup-example
  namespace: cnpg-cluster
spec:
  cluster:
    name: cnpg-cluster-pg13
status:
  backupId: 20230929T144203
  beginLSN: 1/59ADF6C0
  beginWal: 0000003D0000000100000059
  destinationPath: s3://postgres-cnpg/
  endLSN: 1/5C000000
  endWal: 0000003D000000010000005C
  instanceID:
    ContainerID: containerd://e3e933f390dd64c9fd0a2442eca78e20b0a4b41707704bb6102f085d2f462dc1
    podName: cnpg-cluster-pg13-2
  phase: completed
  s3Credentials:
    accessKeyId:
      key: ACCESS_KEY_ID
      name: aws-creds
    inheritFromIAMRole: false
    secretAccessKey:
      key: ACCESS_SECRET_KEY
      name: aws-creds
  serverName: cnpg-cluster-pg13
  startedAt: "2023-09-29T14:42:03Z"
  stoppedAt: "2023-09-29T14:42:56Z"

Answered by gbartolini

Oct 9, 2023

Thanks for your work here. It looks like you are taking - as per default - a backup from a standby. In such a case, we cannot force the switch of the WAL file. This is explained in this page: https://cloudnative-pg.io/documentation/current/backup_recovery/#backup-from-a-standby

This might produce unexpected results in the short term (before archive_timeout kicks in) in deployments with low write activity.

Can you confirm this might be related?

View full answer

ksyblast · 2023-10-04T15:35:15Z

ksyblast
Oct 4, 2023
Author

Update: Looks like the date was already later than base backup end WAL. Without recoverytarget it works well. Do I always need a "fresh" base backup to restore?

1 reply

ksyblast Oct 4, 2023
Author

Update: without recovery target it took another base backup that I created today, that's why it worked:

{"level":"info","ts":"2023-10-04T15:37:39Z","msg":"Target backup found","logging_pod":"cnpg-restore-pg13-1-full-recovery","backup":{"backup_label":"'START WAL LOCATION: 1/8F004558 (file 00000045000000010000008F)\\nCHECKPOINT LOCATION: 1/90000060\\nBACKUP METHOD: streamed\\nBACKUP FROM: standby\\nSTART TIME: 2023-10-04 12:25:10 UTC\\nLABEL: Barman backup cloud 20231004T122510\\nSTART TIMELINE: 69\\n'","begin_time":"Wed Oct  4 12:25:10 2023","end_time":"Wed Oct  4 12:26:09 2023","BeginTime":"2023-10-04T12:25:10Z","EndTime":"2023-10-04T12:26:09Z","begin_wal":"00000045000000010000008F","end_wal":"000000450000000100000091","begin_xlog":"1/8F004558","end_xlog":"1/91000000","systemid":"7281241487361605658","backup_id":"20231004T122510","error":"","timeline":69}}

ksyblast · 2023-10-05T10:20:52Z

ksyblast
Oct 5, 2023
Author

I could reproduce it.

Steps to reproduce:

create a new cluster without backup (I used postgres 13)
insert some data (in my case I used pgbench: pgbench -h <host> -p 5432 -U postgres -i --foreign-keys -s 20 app)
you will see in the logs messages that WAL archiving is not confugired

{"level":"info","ts":"2023-10-05T10:04:27Z","logger":"wal-archive","msg":"Backup not configured, skip WAL archiving","logging_pod":"cnpg-restore-test-pg13-1","walName":"pg_wal/000000010000000000000003","currentPrimary":"cnpg-restore-test-pg13-1","targetPrimary":"cnpg-restore-test-pg13-1"}

don't wait for the another archive timeout!!! and configure backup config for the cluster and a backup object; backup object must be created before the next archive round
wait for the backup to finish

kubectl get backups.postgresql.cnpg.io -n cnpg-restore-test -o yaml
apiVersion: v1
items:
- apiVersion: postgresql.cnpg.io/v1
  kind: Backup
  metadata:
    name: backup-20231005-1
    namespace: cnpg-restore-test
  spec:
    cluster:
      name: cnpg-restore-test-pg13
  status:
    backupId: 20231005T100548
    beginLSN: 0/301A600
    beginWal: "000000010000000000000003"
    destinationPath: s3://cnpg-restore-test/
    endLSN: 0/1360E080
    endWal: "000000010000000000000013"
    instanceID:
      ContainerID: containerd://e5b4763338e6192222d4c76a2d9e0ed65b0175c35023e0107babdd5168591ae0
      podName: cnpg-restore-test-pg13-2
    phase: completed
    s3Credentials:
...
    serverName: cnpg-restore-test-pg13
    startedAt: "2023-10-05T10:05:48Z"
    stoppedAt: "2023-10-05T10:06:14Z"
kind: List
metadata:
  resourceVersion: ""

Notice beginWal: "000000010000000000000003" - it's not in S3
Next archiving produces logs:

{"level":"info","ts":"2023-10-05T10:09:56Z","logger":"wal-archive","msg":"barman-cloud-check-wal-archive checking the first wal","logging_pod":"cnpg-restore-test-pg13-1"}
{"level":"info","ts":"2023-10-05T10:10:00Z","logger":"wal-archive","msg":"Archived WAL file","logging_pod":"cnpg-restore-test-pg13-1","walName":"pg_wal/000000010000000000000013","startTime":"2023-10-05T10:09:57Z","endTime":"2023-10-05T10:10:00Z","elapsedWalTime":2.758389877}

S3 wal/ directory starts with 000000010000000000000013
The backup we have made is missing WAL files in the archive

2 replies

gbartolini Oct 9, 2023
Maintainer

Thanks for your work here. It looks like you are taking - as per default - a backup from a standby. In such a case, we cannot force the switch of the WAL file. This is explained in this page: https://cloudnative-pg.io/documentation/current/backup_recovery/#backup-from-a-standby

This might produce unexpected results in the short term (before archive_timeout kicks in) in deployments with low write activity.

Can you confirm this might be related?

Answer selected by ksyblast

ksyblast Oct 10, 2023
Author

Thanks @gbartolini! Yes, I already thought that it's something like that but I missed it in the docs somehow, that's exactly the case

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error while restoring a backup - first WAL file not found #2989

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments 3 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Error while restoring a backup - first WAL file not found #2989

ksyblast Oct 4, 2023

Replies: 2 comments · 3 replies

ksyblast Oct 4, 2023 Author

ksyblast Oct 4, 2023 Author

ksyblast Oct 5, 2023 Author

gbartolini Oct 9, 2023 Maintainer

ksyblast Oct 10, 2023 Author

ksyblast
Oct 4, 2023

Replies: 2 comments 3 replies

ksyblast
Oct 4, 2023
Author

ksyblast Oct 4, 2023
Author

ksyblast
Oct 5, 2023
Author

gbartolini Oct 9, 2023
Maintainer

ksyblast Oct 10, 2023
Author