Velero Panic on backup - Observed a panic: sync: negative WaitGroup counter

[Gui13]

What steps did you take and what happened:

During a velero backup, we hit a panic (this is not the same as #8657):

time="2025-02-20T09:35:08Z" level=info msg="plugin process exited" backup-storage-location=velero/default cmd=/plugins/velero-plugin-for-microsoft-azure controller=backup-storage-location id=2068 logSource="pkg/plugin/clientmgmt/process/logrus_adapter.go:80" plugin=/plugins/velero-plugin-for-microsoft-azure
time="2025-02-20T09:35:15Z" level=info msg="The request has status 'InProgress', skip." controller=backup-deletion deletebackuprequest=velero/velero-braincube-20250120000012-gt6xm logSource="pkg/controller/backup_deletion_controller.go:145"
time="2025-02-20T09:35:27Z" level=error msg="pod volume backup failed: data path backup canceled: PVB is canceled" backup=velero/manual-velero-braincube-20250220 logSource="pkg/podvolume/backupper.go:382"
time="2025-02-20T09:35:27Z" level=error msg="pod volume backup failed: data path backup canceled: PVB is canceled" backup=velero/manual-velero-braincube-20250220 logSource="pkg/podvolume/backupper.go:382"
E0220 09:35:27.132115       1 runtime.go:77] Observed a panic: sync: negative WaitGroup counter
goroutine 757 [running]:
k8s.io/apimachinery/pkg/util/runtime.logPanic({0x26c8ce0, 0x314da30})
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/runtime/runtime.go:75 +0x85
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc00467f6c0?})
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/runtime/runtime.go:49 +0x6b
panic({0x26c8ce0?, 0x314da30?})
	/usr/local/go/src/runtime/panic.go:770 +0x132
sync.(*WaitGroup).Add(0xc007cec270?, 0x2c4e600?)
	/usr/local/go/src/sync/waitgroup.go:62 +0xd8
sync.(*WaitGroup).Done(...)
	/usr/local/go/src/sync/waitgroup.go:87
github.com/vmware-tanzu/velero/pkg/podvolume.newBackupper.func1({0x40a3d2?, 0xc007cf6060?}, {0x2c4e600?, 0xc00da55208?})
	/go/src/github.com/vmware-tanzu/velero/pkg/podvolume/backupper.go:167 +0x1eb
k8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnUpdate(...)
	/go/pkg/mod/k8s.io/client-go@v0.29.0/tools/cache/controller.go:246
k8s.io/client-go/tools/cache.(*processorListener).run.func1()
	/go/pkg/mod/k8s.io/client-go@v0.29.0/tools/cache/shared_informer.go:970 +0xea
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x30?)
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/backoff.go:226 +0x33
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0xc0030d9f70, {0x3156de0, 0xc008688c60}, 0x1, 0xc0037a0ba0)
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/backoff.go:227 +0xaf
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0xc0006b7770, 0x3b9aca00, 0x0, 0x1, 0xc0037a0ba0)
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/backoff.go:204 +0x7f
k8s.io/apimachinery/pkg/util/wait.Until(...)
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/backoff.go:161
k8s.io/client-go/tools/cache.(*processorListener).run(0xc007ce63f0)
	/go/pkg/mod/k8s.io/client-go@v0.29.0/tools/cache/shared_informer.go:966 +0x69
k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/wait.go:72 +0x52
created by k8s.io/apimachinery/pkg/util/wait.(*Group).Start in goroutine 379
	/go/pkg/mod/k8s.io/apimachinery@v0.29.0/pkg/util/wait/wait.go:70 +0x73
panic: sync: negative WaitGroup counter [recovered]
	panic: sync: negative WaitGroup counter

What did you expect to happen:

No crash :-)

The following information will help us better understand what's going on:

I have collected a bundle, but I would like to send it privately to no disclose too much information.

Anything else you would like to add:

Environment:

• Velero version (use velero version): 1.15.2
• Velero features (use velero client config get features): FSB is used extensively
• Kubernetes version (use kubectl version): 1.31
• Kubernetes installer & version: AKZ Azure
• Cloud provider or hardware configuration:
• OS (e.g. from /etc/os-release): Azure Linux

Vote on this issue!

This is an invitation to the Velero community to vote on issues, you can see the project's top voted issues listed here.
Use the "reaction smiley face" up to the right of this comment to vote.

• 👍 for "I would like to see this bug fixed as soon as possible"
• 👎 for "There are more important bugs to focus on right now"

[ywk253100]

This should be caused by the similar reason with #8657:
The PVBs are handled very quickly and WaitGroup.Done() is called multiple times before they are added into the WaitGroup.

Is this issue reproduceble in your environment? Appreciate if you could try the dev build velero/velero:release-1.15-dev with the fix and verify whether it works.

[Gui13]

The issue is not easily reproducible (only 1 hit in last 15 days), and it being a client env, we can't push a dev build easily.
We'll wait until velero 1.16 lands to see if this disappears.

[x0ptr]

We updated yesterday on 1.16. But its not going away.

/go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/wait/wait.go:70 +0x73
| | Apr 23 02:16:11.184 | created by k8s.io/apimachinery/pkg/util/wait.(*Group).Start in goroutine 469
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/wait/wait.go:72 +0x4c
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/client-go@v0.31.3/tools/cache/shared_informer.go:972 +0x5a
| | Apr 23 02:16:11.184 | k8s.io/client-go/tools/cache.(*processorListener).run(0xc000770cf0)
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/wait/backoff.go:161
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/wait.Until(...)
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/wait/backoff.go:204 +0x7f
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/wait.JitterUntil(0xc000fdaf70, 0x3b9aca00, 0x0, 0x1, 0xc001680070)
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/wait/backoff.go:227 +0xaf
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0xc0007d3f70, {0x3d180a0, 0xc0016f9c20}, 0x1, 0xc001680070)
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/wait/backoff.go:226 +0x33
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x30?)
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/client-go@v0.31.3/tools/cache/shared_informer.go:976 +0xea
| | Apr 23 02:16:11.184 | k8s.io/client-go/tools/cache.(*processorListener).run.func1()
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/client-go@v0.31.3/tools/cache/controller.go:253
| | Apr 23 02:16:11.184 | k8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnUpdate(...)
| | Apr 23 02:16:11.184 | /go/src/github.com/vmware-tanzu/velero/pkg/podvolume/backupper.go:180 +0x1eb
| | Apr 23 02:16:11.184 | github.com/vmware-tanzu/velero/pkg/podvolume.newBackupper.func1({0x409af2?, 0xc0011baa80?}, {0x3771780?, 0xc0017146c8?})
| | Apr 23 02:16:11.184 | /usr/local/go/src/sync/waitgroup.go:89
| | Apr 23 02:16:11.184 | sync.(*WaitGroup).Done(...)
| | Apr 23 02:16:11.184 | /usr/local/go/src/sync/waitgroup.go:64 +0xd8
| | Apr 23 02:16:11.184 | sync.(*WaitGroup).Add(0xc000d3fc80?, 0x3771780?)
| | Apr 23 02:16:11.184 | /usr/local/go/src/runtime/panic.go:791 +0x132
| | Apr 23 02:16:11.184 | panic({0x2f99c00?, 0x3d0b7d0?})
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/runtime/runtime.go:59 +0x108
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc00119dc00?})
| | Apr 23 02:16:11.184 | /go/pkg/mod/k8s.io/apimachinery@v0.31.3/pkg/util/runtime/runtime.go:89 +0xee
| | Apr 23 02:16:11.184 | k8s.io/apimachinery/pkg/util/runtime.handleCrash({0x3d5f900, 0x5cce1c0}, {0x2f99c00, 0x3d0b7d0}, {0x5cce1c0, 0x0, 0x43ae05?})
| | Apr 23 02:16:11.184 | goroutine 45231 [running]:
| | Apr 23 02:16:11.184 | panic: sync: negative WaitGroup counter
| | Apr 23 02:16:11.184 | panic: sync: negative WaitGroup counter [recovered]

its only on one kubernetes cluster. Its like a 80% chance this happens.

[ywk253100]

@genjudev When did the panic happen? Did it happen when backing up a specific namespace?
Could you provide the complete log of Velero server and node-agent when panic happened?

[x0ptr]

Name:         daily-backup-20250423000020
Namespace:    velero
Labels:       velero.io/schedule-name=daily-backup
              velero.io/storage-location=default
Annotations:  velero.io/resource-timeout=10m0s
              velero.io/source-cluster-k8s-gitversion=v1.31.1
              velero.io/source-cluster-k8s-major-version=1
              velero.io/source-cluster-k8s-minor-version=31
 
Phase:  Failed (run `velero backup logs daily-backup-20250423000020` for more information)
 
 
Namespaces:
  Included:  *
  Excluded:  velero
 
Resources:
  Included:        *
  Excluded:        <none>
  Cluster-scoped:  auto
 
Label selector:  <none>
 
Or label selector:  <none>
 
Storage Location:  default
 
Velero-Native Snapshot PVs:  auto
Snapshot Move Data:          false
Data Mover:                  velero
 
TTL:  720h0m0s
 
CSISnapshotTimeout:    10m0s
ItemOperationTimeout:  4h0m0s
 
Hooks:  <none>
 
Backup Format Version:  1.1.0
 
Started:    2025-04-23 02:00:20 +0200 CEST
Completed:  2025-04-23 02:16:13 +0200 CEST
 
Expiration:  2025-05-23 02:00:20 +0200 CEST
 
Total items to be backed up:  1758
Items backed up:              36
 
Resource List:  <backup resource list not found>
 
Backup Volumes:
  Velero-Native Snapshots: <none included>
 
  CSI Snapshots: <none included or not detectable>
 
  Pod Volume Backups - kopia:
    Completed:
      datadog/datadog-4g2xm: auth-token, config, logdatadog, sysprobe-socket-dir, tmpdir
      datadog/datadog-7pkrs: auth-token, config, logdatadog, sysprobe-socket-dir, tmpdir
      datadog/datadog-cluster-agent-d6d757585-j464q: config, datadogrun, tmpdir, varlog
      datadog/datadog-cluster-agent-d6d757585-pdqdw: config, datadogrun, tmpdir, varlog
      datadog/datadog-xvhq6: auth-token, config, logdatadog, sysprobe-socket-dir, tmpdir
      default/nfs-server-provisioner-0: data
      kube-system/metrics-server-66bc5cc58-rm2pq: tmp-dir
      live/api-6fbbf8c7cf-5kx2h: <comp>-nfs-storage-vol

We have no logs for this job.

We changed the start time to 10.pm and now its working and also:

we had also an additional problem with the pre hook timeout. It was not working at all.

Our database has a timeout of 40m
pre.hook.backup.velero.io/timeout: 40m
its running a dump which takes 41m. When we run it at 2.am timeout will not trigger. When we run at 10.pm its working.

As you can see the 2.am backup job was finished in 16min. the dump was still running and the timeout does not cancel it.
The dump also finished after 41m. So after the timeout.

We see that the velereo container is exited when completed. It looks like the process is not waiting for the timeout. And I assume when the job is for some reason completed, velero will not cancel the pre hook job.

I hope this helps somehow...

[ywk253100]

@genjudev Could you reproduce the panic issue in your environment? Panic is critical and it's better to resolve it in our next patch release if possible. Appreciate if you can reproduce it and provide us more information to debug the root cause.

For the pre-hook timeout issue, could you open another issue with the debug bundle?
Generate the debug bundle with command velero debug ...

[x0ptr]

After changing the time, it's about 50/50 whether the panic happens. So it’s not really fixed.
Can you point out what exactly could be causing this? We only have the panic stack at the moment. But if I know what to watch for, I can try to get more detailed info. Maybe…

[ywk253100]

To be honest, I didn't figure out why panic happened, so the Velero server log is important to narrow down the possible causes.

[ywk253100]

Fixed by #8940