Closed btxbtx closed 11 months ago
btxbtx
commented
1 year ago This seems related to a fix that @mikewallace1979 implemented in 3.4.1: https://github.com/EnterpriseDB/barman/releases/tag/release%2F3.4.1
I didn't mention in the original post, but this is happening with barman 3.5.0.
mikewallace1979
commented
1 year ago Hi @btxbtx - I've created a local cnpg cluster using the 0.18.0 chart to reproduce this issue but so far my backups to a local minio container are working as expected.
Are you able to get a shell on one of the PostgreSQL pods via kubectl exec? If so, could you please run the following commands and post the output here?
AWS_ACCESS_KEY_ID=<access key id> AWS_SECRET_ACCESS_KEY=<secret access key> barman-cloud-backup-list <my s3 destination> my-cluster --endpoint-url=<my s3 compatible storage>
AWS_ACCESS_KEY_ID=<access key id> AWS_SECRET_ACCESS_KEY=<secret access key> barman-cloud-backup-show <my s3 destination> my-cluster backup-1690362727 --endpoint-url=<my s3 compatible storage>If either of the above commands fail please retry them with the -vv option and post the output.
If you can't get a shell on the pods, could you list the backup IDs saved in your object store? They should be available under my-cluster/base prefix.
Also, which s3-compatible object store are you using?
Thanks.
btxbtx
commented
1 year ago Hi @mikewallace1979 thank you for the instructions.
I am using Linode Object Storage.
I've tested using the 0.18.0 chart on KinD, and on a managed linode cluster.
Output of barman-cloud-backup-list -vv, with region, endpoint URL, and credentials redacted.:
Output of barman-cloud-backup-show -vv, with region, endpoint URL, and credentials redacted.
Here are the logs from that run, if they are relevant. I have only redacted the endpoint URL in this case.
mikewallace1979
commented
1 year ago Thanks for providing the additional information. The fact that the operator logs Backup completed while the barman-cloud-backup-list command shows no backups is particularly concerning.
I tried reproducing this issue using linode object storage this morning but have still not had any success.
Can you try taking a manual backup in a shell on one of the pods? You will need to export TMPDIR so that a writable filesystem is used for temporary files - something like this should work:
TMPDIR=/controller AWS_ACCESS_KEY_ID=<access key id> AWS_SECRET_ACCESS_KEY=<secret access key> barman-cloud-backup --user=postgres --name=backup-test s3://barmantest --endpoint-url=https://<my-endpoint>.linodeobjects.com --cloud-provider=aws-s3 cnpg-cluster -vvRedacting the same things as last time should be fine.
It would definitely be helpful at this point to see a list of the objects present in the linode object store after the backup has completed - can you include that in some form, preferably with the full object keys? Even if the backups aren't being written there should still be archived WALs present and it would be good to just verify that things are ending up where they should be.
btxbtx
commented
1 year ago @mikewallace1979 would my cnpg manifests be at all helpful, or are they out of scope? There's nothing special about my network, so I am not sure what else could be different between your test on linode and mine.
I've additionally tried to get the objects for you programmatically, via
aws s3 ls s3://barmantest/ --endpoint-url=https://<my-endpoint>.linodeobjects.com --profile linodebut the response is empty, as if there were no objects. However, navigating to that end point/bucket in the linode UI, I can see that it is not empty.
barmantest/cnpg-cluster/base:
20230823T032123
20230823T032223
20230823T032323
20230823T032423
20230823T032523
20230823T032623
20230823T033032
20230824T033440
20230824T033954Each of which contains tiny backup.info and data.tar files.
Additionally, there is a barmantest/cnpg-cluster/wals/0000000100000000/ directory, with these contents:
000000010000000000000005
000000010000000000000006
000000010000000000000006.00000028.backupApologies if that's not the information you were asking for.
mikewallace1979
commented
1 year ago @btxbtx thanks - this was exactly the information I wanted because I hoped to verify:
Both of these things are true which is good but unfortunately means we're no closer to understanding why the barman-cloud-backup-show command fails.
The fact that both barman-cloud-backup-list and aws s3 ls both act as if running against an empty bucket feels significant but I can't think of any obvious reasons why this would happen - I'll read through the logs in more detail give it some more thought.
btxbtx
commented
1 year ago Thank you for the help. Just to rule one more thing out--
Given that list and ls are failing, I thought it might be a credential issue (somehow granting write access without granting read access) but the permissions look good to me.
From the Linode dash:
This key has unlimited access to all buckets on your account.Thanks for ruling out permissions - I forgot to say in my last response but yes, the cnpg manifest files would also be useful.
mikewallace1979
commented
1 year ago I can see something which might be significant:
In the output for barman-cloud-backup we can see a POST request being made to /barmantest/cnpg-cluster/base/20230824T033954/data.tar - this matches the location of the backups listed by the linode UI: barmantest/cnpg-cluster/base.
However, in the output for both barman-cloud-backup-list and barman-cloud-backup-show there are GET requests to /barmantest which are providing a path of cnpg-cluster-1, e.g.:
GET
/barmantest
delimiter=%2F&encoding-type=url&list-type=2&prefix=cnpg-cluster-1%2Fbase%2Fcnpt-cluster-1 is the pod name rather than the cluster name so if the operator is also running those commands with the pod name instead of the cluster name then that would explain why it can't find the backups, however I also realise this ouput is from manual commands rather than those run by the operator so we can't make that conclusion just yet.
Can you check the options for the Can't extract backup id log line for a recent failed backup and check the cluster name definitely matches the cluster name in the options of the Backup started log line for that same backup?
btxbtx
commented
1 year ago Here are the manifests, starting with the resources I've created. I've changed the s3 destination path from barmantest to barman, otherwise the config is the same as before.
The schedule has an arbitrary value in it right now.
Including the non-CRD manifests generated by the template command, in case they are useful.
Not included are a role and rolebinding I had to make for the service account to read the secrets.
Great catch re: the pod name (rather than cluster name) being used, I indeed used the wrong arguments. I am trying to re-create the issue but now running into a loop of still waiting for all required WAL segments to be archived; logs given below.
And the manual backup attempts are failing with a brand-new 403:
Here is another attempt at the list, this time using cnpg-cluster over cnpg-cluster-1. I used the barmantest in this case since I can't seem to backup to my new barman destination.
I will have to do some debugging to see why the 403s are appearing on manual backups, and why my WAL archiving seems to have stopped working (both on my previous test cluster and a fresh one).
However, given the manifests, I think it is safe to say the operator is using cnpg-cluster rather than cnpg-cluster-1, and the latter was just a user error when I ran the manual commands. I will try and get proof of this as a sanity check, after debugging further.
mikewallace1979
commented
1 year ago I have just reproduced this 🎉 :
The issue turned out to be the endpointURL value - if I use https://us-east-1.linodeobjects.com instead of https://barman.us-east-1.linodeobjects.com then everything works as expected.
Hopefully if you make the same change to your endpointURL that will resolve the original issue.
I don't quite understand why using the bucket URL as the endpoint URL works, or why it behaves differently between the barman-cloud-backup and barman-cloud-backup-show commands - presumably there's some undefined behaviour somewhere which means that PUT requests via the multipart API will still end up in the right place but GET and HEAD requests won't. I'll do a bit more digging there.
btxbtx
commented
1 year ago Nice! 👏 I can now successfully upload backups, when done manually after exec'ing into one of the cnpg cluster pods and running barman-cloud-backup myself:
Backup ID End Time Begin Wal Archival Status Name
20230825T105554 2023-08-25 10:55:55 000000010000000000000009 backup-1692960953
20230825T110022 2023-08-25 11:00:23 000000010000000000000014 backup-test
20230825T110609 2023-08-25 11:06:10 000000010000000000000017 backup-1692961567
20230825T110810 2023-08-25 11:08:11 00000001000000000000001B backup-1692961687
20230825T110908 2023-08-25 11:09:09 00000001000000000000001E backup-1692961747backup-test exists as expected! The other backups I believe are from my ScheduledBackup tests, which are still failing.
I think it's safe to say the can't extract backup id issue is resolved. However, my scheduled backups still fail due to continuously waiting on the WAL segments to be archived. I've included a full log here (nothing needed to be redacted), though it might be better suited as part of a separate issue. If you agree, please feel free to close this issue as resolved.
Thank you for the time you've spent on this issue, it was a huge help.
mikewallace1979
commented
1 year ago We can keep debugging in this issue for now since the WAL archiving may be related somehow.
Observations from the latest logs:
00000001000000000000002A through to 00000001000000000000002F have been archived while these backups were ongoing.Connection was closed before we received a valid response from endpoint URL. The ID of that backup was 20230825T111717 which maps, via epoch time, to the second backup started in the logs: cnpg-backup-1692962236. The URL contains partNumber=1 which suggests the backup upload had not completed, even though this log line was at 11:22:56, some five minutes after the start of the backup.It would be useful to know the current wal segment - can you run the following command on the primary pod:
psql -c 'SELECT pg_walfile_name(pg_current_wal_lsn());'It would also be useful to know the most recent WAL segment in the linode object store - can you list the contents of the barmannewtest bucket under the cnpg-cluster/wals prefix?
btxbtx
commented
1 year ago I've modified the cron schedule to run once an hour and then re-ran the scheduled backup. I'll attach its logs to this post. Hopefully this has not affected the data you were looking for.
psql -c 'SELECT pg_walfile_name(pg_current_wal_lsn());'
pg_walfile_name
--------------------------
000000010000000000000004
(1 row)And the contents of barmannewtest/cnpg-cluster/wals/:
barmannewtest/
└── cnpg-cluster/
└── wals/
└── 0000000100000000/
├── 000000010000000000000002 16 MB 2023-08-25 10:56
├── 000000010000000000000003 16 MB 2023-08-25 10:56
├── 000000010000000000000003.00000028.backup 348 bytes 2023-08-25 10:56
├── 000000010000000000000004 16 MB 2023-08-25 10:59
├── 000000010000000000000016 16 MB 2023-08-25 11:06
├── 000000010000000000000017 16 MB 2023-08-25 11:08
├── 000000010000000000000017.00000028.backup 351 bytes 2023-08-25 11:08
├── 000000010000000000000018 16 MB 2023-08-25 11:11
├── 000000010000000000000019 16 MB 2023-08-25 11:12
├── 00000001000000000000002A 16 MB 2023-08-25 11:16
├── 00000001000000000000002B 16 MB 2023-08-25 11:18
├── 00000001000000000000002C 16 MB 2023-08-25 11:20
├── 00000001000000000000002C.00000028.backup 351 bytes 2023-08-25 11:20
├── 00000001000000000000002D 16 MB 2023-08-25 11:20
├── 00000001000000000000002D.00000028.backup 351 bytes 2023-08-25 11:20
├── 00000001000000000000002E 16 MB 2023-08-25 11:21
├── 00000001000000000000002F 16 MB 2023-08-25 11:22
└── 000000010000000000000049 16 MB 2023-08-25 15:04
I haven't had a chance to look through the latest logs in detail but the following line suggests you're trying to start a new cnpg cluster but you're pointing to a bucket which already contains WALs:
}
cnpg-cluster-1 postgres {
"level": "info",
"ts": "2023-08-25T15:23:04Z",
"logger": "barman-cloud-check-wal-archive",
"msg": "2023-08-25 15:23:04,790 [334] ERROR: WAL archive check failed for server cnpg-cluster: Expected empty archive",
"pipe": "stderr",
"logging_pod": "cnpg-cluster-1"
}This check is supposed to fail if there are WALs already present to prevent a WAL archive from containing WAL segments from different clusters - such a WAL archive would not be useful at recovery time.
I wonder if the following WAL archiving errors is related - it could be that PostgreSQL is trying to archive a WAL segment which has the same name as a WAL archived by an earlier instance of the cluster:
cnpg-cluster-1 postgres {
"level": "error",
"ts": "2023-08-25T15:23:04Z",
"logger": "wal-archive",
"msg": "failed to run wal-archive command",
"logging_pod": "cnpg-cluster-1",
"error": "unexpected failure invoking barman-cloud-wal-archive: exit status 1",
"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/internal/cmd/manager/walarchive.NewCmd.func1\n\tinternal/cmd/manager/walarchive/cmd.go:83\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.3/x64/src/runtime/proc.go:250"
}It's probably worth starting over with an empty bucket at this point and seeing what the logs look like after that.
btxbtx
commented
1 year ago @mikewallace1979 it looks like the backup completed without issue in the new bucket. 🥳
mikewallace1979
commented
1 year ago Excellent news!
gaetancollaud
commented
3 months ago For those using Digital Ocean Spaces Object Storage and have the same issue, just configure your bucket like this:
destinationPath: "s3://{BUCKET_NAME}/{FOLDER_NAME}/"
endpointURL: "https://{REGION}.digitaloceanspaces.com"ex
destinationPath: "s3://backup-test/test-db/"
endpointURL: "https://fra1.digitaloceanspaces.com"
I am running barman within the context of cloudnative-pg (pg-operator chart version
0.18.0). I've not changed anything about the default barman config they use. I noticed that my backups are performing, at least partially, before eventually failing withcan't extract backup id.The logs:
Happy to provide more config if it is helpful, just let me know what is needed.