Backup failed but no errors

[ariep]

Background: this is an existing velero install that has been working fine for at least half a year, making daily backups to external S3 storage. We needed to swap out the S3 storage though, so I:

1. Changed the config to the new location. Note that the new location doesn't contain any data so I expect to start from a clean slate.
2. Manually kubectl deleted all Backups to remove the references to the old backups which are no longer available in the new location.
3. Started a fresh backup.

At step 3., the backup ends up in Failed state, but there are no errors in either backup logs or logs of the velero pod, only info level lines. Backup description:

velero backup describe $NAME
Name:         $NAME
Namespace:    velero
Labels:       velero.io/storage-location=default
Annotations:  velero.io/source-cluster-k8s-gitversion=v1.30.3+k3s1
              velero.io/source-cluster-k8s-major-version=1
              velero.io/source-cluster-k8s-minor-version=30

Phase:  Failed (run `velero backup logs $NAME` for more information)


Namespaces:
  Included:  *
  Excluded:  <none>

Resources:
  Included:        *
  Excluded:        <none>
  Cluster-scoped:  auto

Label selector:  <none>

Storage Location:  default

Velero-Native Snapshot PVs:  auto

TTL:  720h0m0s

CSISnapshotTimeout:    10m0s
ItemOperationTimeout:  1h0m0s

Hooks:  <none>

Backup Format Version:  1.1.0

Started:    2024-09-05 13:57:37 +0000 UTC
Completed:  <n/a>

Expiration:  2024-10-05 13:57:36 +0000 UTC

Total items to be backed up:  3440
Items backed up:              3440

Velero-Native Snapshots: <none included>

restic Backups (specify --details for more information):
  Completed:  9

The BackupStorageLocation:

apiVersion: velero.io/v1
kind: BackupStorageLocation
metadata:
  creationTimestamp: [...]
  generation: [...]
  labels:
    app.kubernetes.io/instance: velero
    app.kubernetes.io/name: velero
    kustomize.toolkit.fluxcd.io/name: velero-config
    kustomize.toolkit.fluxcd.io/namespace: flux-system
  name: default
  namespace: velero
  resourceVersion: [...]
  uid: [...]
spec:
  accessMode: ReadWrite
  backupSyncPeriod: 0s
  config:
    region: [...]
    s3ForcePathStyle: "true"
    s3Url: [...]
  default: true
  objectStorage:
    bucket: [...]
    prefix: [...]
  provider: aws
  validationFrequency: 1h
status:
  lastValidationTime: "2024-09-06T08:41:53Z"
  phase: Available

Note in particular the backupSyncPeriod of 0s, which disables syncing backup metadata from storage to the cluster. We set this a long time ago to prevent excessive requests from velero to S3 (several per minute while not really doing anything). Maybe I'll try enabling that sync temporarily to help velero know about the current state of the S3 storage 🤔 .

This is with velero 1.11.1 (client and server). I could try upgrading but I'd like to not complicate the situation if possible.

Any hints? I understand this is not the cleanest situation, but I'd always expect some error message if there is a failure. It's hard to debug without any indication what's wrong :).

[ariep]

I set the backupSyncPeriod to 5m and restarted velero, waited until it settled, and created a new backup. Same result though: status of Failed but no errors.

By the way, the last line of the backup logs is:

time="2024-09-06T09:16:00Z" level=info msg="Backed up a total of 3471 items" backup=velero/manual-1 logSource="pkg/backup/backup.go:436" progress=

Which also looks quite healthy by itself.

[ariep]

Hm I really wanted to get this working, so I decided to start with a clean slate: completely uninstalled velero, emptied the S3 bucket, and reinstalled velero. However I still get the same error, well no error really but the Failed state for a new backup :/. So it doesn't seem to be caused by remnants of the previous storage location, as I was assuming.

[ariep]

I increased the log verbosity of the velero process, which gave me this log line:

time="2024-09-06T12:40:05Z" level=debug msg="received EOF, stopping recv loop" backup=velero/clean-slate-2 cmd=/velero err="rpc error: code = Unavailable desc = error reading from serv
er: EOF" logSource="pkg/plugin/clientmgmt/process/logrus_adapter.go:75" pluginName=stdio

Searching for that error message led me to the openshift documentation, which states:

Velero plugins are started as separate processes. After the Velero operation has completed, either successfully or not, they exit. Receiving a received EOF, stopping recv loop message in the debug logs indicates that a plugin operation has completed. It does not mean that an error has occurred.

Is it possible that velero wrongly believes that the EOF indicates an error?

[sseago]

@ariep that's a debug log, so it's not a backup failure reason. Are there no "level=error" logs in the pod log?

[ariep]

No, only info and lower, that's the weird thing. I see there's an error level log line in my paste here, I did not see that before when grepping for some reason. It still doesn't say much though.

[...]
time="2024-09-06T12:40:05Z" level=info msg="Backup completed" backup=velero/clean-slate-2 logSource="pkg/controller/backup_controller.go:785"
time="2024-09-06T12:40:05Z" level=debug msg="received EOF, stopping recv loop" backup=velero/clean-slate-2 cmd=/velero err="rpc error: code = Unavailable desc = error reading from serv
er: EOF" logSource="pkg/plugin/clientmgmt/process/logrus_adapter.go:75" pluginName=stdio
time="2024-09-06T12:40:05Z" level=debug msg="plugin process exited" backup=velero/clean-slate-2 cmd=/velero logSource="pkg/plugin/clientmgmt/process/logrus_adapter.go:75" path=/velero 
pid=91
time="2024-09-06T12:40:05Z" level=debug msg="plugin exited" backup=velero/clean-slate-2 cmd=/velero logSource="pkg/plugin/clientmgmt/process/logrus_adapter.go:75"
time="2024-09-06T12:40:05Z" level=debug msg="plugin process exited" backup=velero/clean-slate-2 cmd=/plugins/velero-plugin-for-aws logSource="pkg/plugin/clientmgmt/process/logrus_adapt
er.go:75" path=/plugins/velero-plugin-for-aws pid=102
time="2024-09-06T12:40:05Z" level=debug msg="plugin exited" backup=velero/clean-slate-2 cmd=/plugins/velero-plugin-for-aws logSource="pkg/plugin/clientmgmt/process/logrus_adapter.go:75
"
time="2024-09-06T12:40:05Z" level=error msg="backup failed" backuprequest=velero/clean-slate-2 controller=backup error="rpc error: code = Unknown desc = EOF" logSource="pkg/controller/
backup_controller.go:290"
[...]

[draghuram]

Do you see any restarts for Velero pods?

[ariep]

No, no restarts. Also no OOMs.

[sseago]

If the backup is "Failed" rather than "PartiallyFailed", that means the backup didn't even start processing, so I wouldn't expect anything to show up in the backup error list. But there should be some message in the logs indicating why Velero moved the backup to the "Failed" phase.

[ariep]

Do you have any plugins registered other than the object store plugin?

Not knowingly, I just have aws for the object storage. Actually, could that be the problem? I have a whole fleet of clusters with this setup working flawlessly with ceph S3 storage, and this problem appeared when I switched one of them to Openshift as S3 storage. Could it be that their S3 implementation is slightly different in a way that the aws plugin doesn't handle?

What object store plugin version are you using?

That's the one under initContainers no? That's velero/velero-plugin-for-aws:v1.1.0. It's likely that that hasn't been increased for a long time.

[sseago]

velero/velero-plugin-for-aws:v1.1.0 -- that could be your problem. See https://github.com/vmware-tanzu/velero-plugin-for-aws?tab=readme-ov-file#compatibility

For Velero 1.11, you need to be using v1.7.x

[ariep]

I went ahead and increased that to v1.7.1 which I understand is latest compatible with velero 1.11. However creating a new backup with that new version gets the same error.

[kaovilai]

Start fresh IMO. New/Clean bucket, matching latest velero + plugins

[ariep]

I did a full reset (completely removing velero and emptying the bucket) twice, once to retry with velero 1.11 + plugin 1.7.1, once with velero 1.14.1 (latest) + plugin 1.10.1 (latest). Both times same result: good backup but status of Failed. Anything else I can try from my side?