node-agent: PVB gets stuck indefinitely after the data path pod completes successfully

[NicoJDE]

What steps did you take and what happened:

A filesystem backup (PVB) was created. The backup subprocess started successfully and
reported Running data path service, but the node-agent never completed the gRPC Init
handshake. The PVB stayed in Prepared phase indefinitely.

The node-agent logs showed a tight 5-second loop — reaching "Exposed PVB is ready" on
every iteration but never "Init cancelable PVB":

time="2026-04-13T12:28:00Z" level=info msg="PVB is prepared and should be processed by ()" controller=podvolumebackup logSource="pkg/controller/pod_volume_backup_controller.go:278"
podvolumebackup=velero/daily-filesystembackup-20260413121426-m9wwc
time="2026-04-13T12:28:00Z" level=info msg="Hosting pod is in running state in node " logSource="pkg/exposer/pod_volume.go:253"
time="2026-04-13T12:28:00Z" level=info msg="Exposed PVB is ready and creating data path routine" controller=podvolumebackup logSource="pkg/controller/pod_volume_backup_controller.go:303"
podvolumebackup=velero/daily-filesystembackup-20260413121426-m9wwc
time="2026-04-13T12:28:05Z" level=info msg="PVB is prepared and should be processed by ()" ...
time="2026-04-13T12:28:05Z" level=info msg="Hosting pod is in running state in node " ...
time="2026-04-13T12:28:05Z" level=info msg="Exposed PVB is ready and creating data path routine" ...
(repeating every 5s — "Init cancelable PVB" is never logged)

The backup subprocess had been running since 12:15:55 and was waiting for the gRPC Init
call the entire time:

time="2026-04-13T12:15:55Z" level=info msg="Starting Velero pod volume backup v1.18.0 (6adcf06-dirty)" logSource="pkg/cmd/cli/podvolume/backup.go:75"
time="2026-04-13T12:15:55Z" level=info msg="Starting micro service in node for PVB daily-filesystembackup-20260413121426-m9wwc" logSource="pkg/cmd/cli/podvolume/backup.go:219"
time="2026-04-13T12:16:14Z" level=info msg="Starting data path service daily-filesystembackup-20260413121426-m9wwc" logSource="pkg/cmd/cli/podvolume/backup.go:228"
time="2026-04-13T12:16:14Z" level=info msg="Running data path service daily-filesystembackup-20260413121426-m9wwc" logSource="pkg/cmd/cli/podvolume/backup.go:238"

No further output from the subprocess until the node-agent was restarted at 12:32:22 —
16 minutes later — after which the gRPC Init succeeded immediately:

time="2026-04-13T12:32:37Z" level=info msg="Init cancelable PVB" controller=podvolumebackup logSource="pkg/controller/pod_volume_backup_controller.go:500"
podvolumebackup=velero/daily-filesystembackup-20260413121426-m9wwc
time="2026-04-13T12:32:38Z" level=info msg="MicroServiceBR is initialized" controller=podvolumebackup logSource="pkg/datapath/micro_service_watcher.go:176"
podvolumebackup=velero/daily-filesystembackup-20260413121426-m9wwc
time="2026-04-13T12:32:44Z" level=info msg="PVB completed" controller=PodVolumeBackup logSource="pkg/controller/pod_volume_backup_controller.go:572"

--resource-timeout does not apply to this state — the PVB never times out on its own.

What did you expect to happen:

The PVB should either complete the gRPC handshake and proceed with the backup, or fail
with a clear error and allow the backup to be retried. Instead it loops silently every
5 seconds with no timeout and no error surfaced to the user.

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

The node had ~25% CPU but ~73% memory utilization at the time of the failure. Memory
pressure appears to cause sufficient scheduling latency to consistently time out the
(hardcoded) gRPC Init call, even at low CPU.

Root cause: initCancelableDataPath failure → closeDataPath() removes asyncBR from
dataPathMgr → PVB stays in Prepared → PeriodicalEnqueueSource requeues every 5s
→ asyncBR == nil → recreate watcher → Init timeout → loop.

Anything else you would like to add:

Workaround: Restart the node-agent pod on the affected node after load decreases:

kubectl delete pod -n velero -l role=node-agent \
  --field-selector spec.nodeName=<node-name>

The existing subprocess is still running and responds to the gRPC Init call immediately
after node-agent restart — no data loss occurs.

Suggested fix: Either expose the gRPC timeout as a configurable flag, or have the
node-agent detect and terminate the stale subprocess instead of looping indefinitely.

Environment:

- Velero version: v1.18.0
- Kubernetes version: 1.35.3
- Kubernetes installer & version: helm
- Cloud provider or hardware configuration: OpenStack
- OS: ubuntu 24.04

[Lyndon-Li]

It is not because of the memory pressure, but because you have other running data movers in the same node, and the node concurrency (either by default 1 or a value you set through https://velero.io/docs/v1.18/node-agent-concurrency/) is blocking a new data mover to run.

[NicoJDE]

Thats not exactly true. Look at this backup as an example:

 velero backup describe daily-filesystembackup-20260414040040 --details
Name:         daily-filesystembackup-20260414040040
Namespace:    velero
Labels:       kustomize.toolkit.fluxcd.io/name=infra-crd
              kustomize.toolkit.fluxcd.io/namespace=flux-system
              velero.io/schedule-name=daily-filesystembackup
              velero.io/storage-location=openstack-s3
Annotations:  velero.io/resource-timeout=10m0s
              velero.io/source-cluster-k8s-gitversion=v1.35.3+k3s1
              velero.io/source-cluster-k8s-major-version=1
              velero.io/source-cluster-k8s-minor-version=35

Phase:  InProgress


Namespaces:
  Included:  *
  Excluded:  kube-system, kyverno, metallb-system, flux-system, velero, kube-node-lease, default, kube-public, trivy, falco, prometheus, gitlab-runner

Resources:
  Included cluster-scoped:    <none>
  Excluded cluster-scoped:    volumesnapshotcontents.snapshot.storage.k8s.io
  Included namespace-scoped:  *
  Excluded namespace-scoped:  volumesnapshots.snapshot.storage.k8s.io

Label selector:  <none>

Or label selector:  <none>

Storage Location:  openstack-s3

Velero-Native Snapshot PVs:    auto
File System Backup (Default):  true
Snapshot Move Data:            false
Data Mover:                    velero

TTL:  2160h0m0s

CSISnapshotTimeout:    10m0s
ItemOperationTimeout:  4h0m0s

Hooks:  <none>

Backup Format Version:  1.1.0

Started:    2026-04-14 06:00:40 +0200 CEST
Completed:  <n/a>

Expiration:  2026-07-13 06:00:40 +0200 CEST

Estimated total items to be backed up:  83853
Items backed up so far:                 17

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:
      apps-backend/apps-backend-695b94545d-ctllh: tmp-volume (size: 32768, incremental size: 32768)
      apps-frontend/apps-frontend-58dcb47d7f-5gr9w: tmp-volume
      apps-frontend/apps-frontend-58dcb47d7f-d6xkb: tmp-volume
      apps-mariadb/apps-mariadb-0: data (size: 131150307), empty-dir (size: 14)
    In Progress:
      bzs/bzs-pg-1: scratch-data (100.00%)
    Prepared:
      bzs/bzs-pg-1: pgdata, shm



 kubectl get podvolumebackups -n velero -l velero.io/backup-name=daily-filesystembackup-20260414040040
NAME                                          STATUS       STARTED   BYTES DONE   TOTAL BYTES   STORAGE LOCATION   AGE    NODE   UPLOADER
daily-filesystembackup-20260414040040-6thhm   InProgress   122m      61406526     61406526      openstack-s3       122m          kopia
daily-filesystembackup-20260414040040-6xrjt   Prepared                                          openstack-s3       122m          kopia
daily-filesystembackup-20260414040040-7cwwj   Completed    125m      32768        32768         openstack-s3       125m          kopia
daily-filesystembackup-20260414040040-b5z9v   Completed    123m                                 openstack-s3       124m          kopia
daily-filesystembackup-20260414040040-c4vrf   Completed    124m                                 openstack-s3       124m          kopia
daily-filesystembackup-20260414040040-gqzks   Prepared                                          openstack-s3       122m          kopia
daily-filesystembackup-20260414040040-shcr2   Completed    123m      131150307    131150307     openstack-s3       123m          kopia
daily-filesystembackup-20260414040040-zznlb   Completed    123m      14           14            openstack-s3       123m          kopia



kubectl get pods -n velero
....
daily-filesystembackup-20260414040040-6thhm                       0/1     Completed   0          124m
daily-filesystembackup-20260414040040-6xrjt                       1/1     Running     0          124m
daily-filesystembackup-20260414040040-gqzks                       1/1     Running     0          124m
...


k describe podvolumebackup daily-filesystembackup-20260414040040-6thhm -n velero
Name:         daily-filesystembackup-20260414040040-6thhm
Namespace:    velero
Labels:       velero.io/backup-name=daily-filesystembackup-20260414040040
              velero.io/backup-uid=f865ab9b-0a3f-4453-a37c-2ae4396dd1da
Annotations:  <none>
API Version:  velero.io/v1
Kind:         PodVolumeBackup
Metadata:
  Creation Timestamp:  2026-04-14T04:04:15Z
  Finalizers:
    velero.io/pod-volume-finalizer
  Generate Name:  daily-filesystembackup-20260414040040-
  Generation:     6
  Owner References:
    API Version:     velero.io/v1
    Controller:      true
    Kind:            Backup
    Name:            daily-filesystembackup-20260414040040
    UID:             f865ab9b-0a3f-4453-a37c-2ae4396dd1da
  Resource Version:  1329756982
  UID:               b2bb96c6-48ae-4472-9aa7-ef991b8287f6
Spec:
  Backup Storage Location:  openstack-s3
  Node:                     inovex-prod-daidalos-ias-prod-node-pool-02-4-d2b6081e
  Pod:
    Kind:           Pod
    Name:           bzs-pg-1
    Namespace:      bzs
    UID:            7b3e4ac7-3408-4f29-afdb-e565363796dd
  Repo Identifier:
  Tags:
    Backup:        daily-filesystembackup-20260414040040
    Backup - UID:  f865ab9b-0a3f-4453-a37c-2ae4396dd1da
    Ns:            bzs
    Pod:           bzs-pg-1
    Pod - UID:     7b3e4ac7-3408-4f29-afdb-e565363796dd
    Volume:        scratch-data
  Uploader Type:   kopia
  Volume:          scratch-data
Status:
  Accepted Timestamp:  2026-04-14T04:04:15Z
  Phase:               InProgress
  Progress:
    Bytes Done:     61406526
    Total Bytes:    61406526
  Start Timestamp:  2026-04-14T04:04:17Z
Events:             <none>

The Logs from the node-agent and the data mover

[Logs-2026-04-14 08_20_18.json](https://github.com/user-attachments/files/26698950/Logs-2026-04-14.08_20_18.json)

[NicoJDE]

The question for me is why the Pod daily-filesystembackup-20260414040040-6thhm in completed state. but the Podvolumebackup in state InProgress.
My concurrency is set a the default value.

[NicoJDE]

@Lyndon-Li i debugged the problem.

Symptom: PVB gets stuck indefinitely after the data path pod completes successfully (phase Succeeded). The backup never transitions to Completed.

Logs from node-agent:

  msg="Finish waiting data path pod, phase Succeeded, message {...}"
  msg="Recording data path pod logs"
  msg="Starting to collect data mover pod log for <pod>"
  msg="Created log file /tmp/4110851590"
  ← hangs here indefinitely, no further output

Root cause: After the pod succeeds, redirectDataMoverLogs calls kube.CollectPodLogs, which calls the Kubernetes API (GetLogs) to stream logs from the pod.
This call contacts the kubelet on the node. If the kubelet is unresponsive (e.g. node under pressure, network issue), the API call blocks indefinitely —
there is no timeout on this call.

The "begin pod logs" indicator that CollectPodLogs writes is never reached, meaning the block happens at the GetLogs API call itself, before any log
streaming starts.

Since log collection errors are only treated as warnings (not fatal), the fix should be simple: wrap the funcRedirectLog call in a context with timeout:

  logCtx, logCancel := context.WithTimeout(ms.ctx, 30*time.Second)
  defer logCancel()
  if err := funcRedirectLog(logCtx, ms.kubeClient, ms.namespace,
      lastPod.Name, ms.thisContainer, ms.log); err != nil {
      logger.WithError(err).Warn("Failed to collect data mover logs")
  }

This ensures that an unresponsive kubelet can no longer block the backup controller from calling OnCompleted.

Relevant code: pkg/datapath/micro_service_watcher.go (call site of funcRedirectLog) and pkg/util/kube/pod.go:CollectPodLogs

[Lyndon-Li]

This call contacts the kubelet on the node. If the kubelet is unresponsive (e.g. node under pressure, network issue), the API call blocks indefinitely —

I am not sure if it is a good idea to set a timeout in this case. As you mentioned, it may be due to node pressure, network issue, etc. which may be transient problem, it's better that node-agent could wait there until the call is recovered. Otherwise, e.g., the backup may have run for hours and actually completed, but it is marked as failed and unusable just for this log collection problem.
On the other hand, once this transient problem happens, why not wait it there because users would need to fix the problem anyway.

[NicoJDE]

Thanks for the explanation! I understand the concern about marking a completed backup as failed — that would definitely be worse than the current behavior.

However, I want to share what we observed in practice: once the GetLogs call blocks, the node-agent does not recover on its own. The goroutine waits indefinitely with no retry, no timeout, and no watchdog. The node-agent process stays alive and appears healthy, but makes no further progress — no new PVBs are processed, no status updates happen. The only way out is a manual pod restart by the operator.

So in practice the behavior isn't "wait until the transient problem resolves" but rather "hang silently until someone notices and intervenes." That's what makes this feel like more than a transient hiccup.

I think the key insight is that log collection is a best-effort, non-critical operation — it shouldn't be on the critical path for backup state transitions at all. Two approaches that would preserve the backup result while fixing the hang:

1. Timeout on the log collection call (e.g. 30s), treating a timeout as a warning and still calling OnCompleted normally
2. Async log collection — decouple log streaming from the critical path so OnCompleted is never gated on it

Either way, the backup outcome stays intact. Only the log collection becomes best-effort, which it arguably already should be.