Loading...

Type: Bug
Resolution: Done-Errata
Priority: Major
Fix Version/s: OADP 1.2.0
Affects Version/s: OADP 1.2.0
Component/s: velero
Labels:

Blocked:
False
Blocked Reason:

Hide

None

Show
None
Ready:
False
ACKs Check:

QE - Ack
QEStatus:
ToDo
Intelligence Requested:
Market:

Cost of Delay:
0
WSJF:
0
Risk Probability:
Very Likely
Risk Score:
0

Workstream:

None

Root Cause:
Unset
Failure Category:
Unknown

Regression:
Yes

SFDC Cases Links:
SFDC Cases Counter:
SFDC Cases Open:

Description of problem:

Velero pod is going in crashLoopBackOff due to nil pointer deference issue. It happens when restore CR contains hooks specification.

time="2022-12-09T10:45:18Z" level=info msg="Starting EventSource" controller=deletebackuprequest controllerGroup=velero.io controllerKind=DeleteBackupRequest logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.DeleteBackupRequest"
E1209 10:45:18.450965       1 runtime.go:79] Observed a panic: "invalid memory address or nil pointer dereference" (runtime error: invalid memory address or nil pointer dereference)
goroutine 1556 [running]:
k8s.io/apimachinery/pkg/util/runtime.logPanic({0x21f27a0?, 0x3d197d0})
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/runtime/runtime.go:75 +0x99
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc00097c8d0?})
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/runtime/runtime.go:49 +0x75
panic({0x21f27a0, 0x3d197d0})
    /usr/lib/golang/src/runtime/panic.go:884 +0x212
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).validateAndComplete(0xc000a32dd0, 0xc000ecc500, {0x2aba440, 0xc00059a6e0})
    /remote-source/velero/app/pkg/controller/restore_controller.go:345 +0xc5b
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processRestore(0xc000a32dd0, 0xc000ecc500)
    /remote-source/velero/app/pkg/controller/restore_controller.go:241 +0x117
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processQueueItem(0xc000a32dd0, {0xc000e00a50, 0x42})
    /remote-source/velero/app/pkg/controller/restore_controller.go:224 +0x30c
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).processNextWorkItem(0xc00083e780)
    /remote-source/velero/app/pkg/controller/generic_controller.go:132 +0xeb
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).runWorker(0xc000bd9ea8?)
    /remote-source/velero/app/pkg/controller/generic_controller.go:119 +0x25
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x1f05a60?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:155 +0x3e
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0xc000bd9f58?, {0x2a8ef20, 0xc000d352f0}, 0x1, 0xc000c97080)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:156 +0xb6
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0xc00089c3f0?, 0x3b9aca00, 0x0, 0x5?, 0x0?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:133 +0x89
k8s.io/apimachinery/pkg/util/wait.Until(...)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:90
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run.func2()
    /remote-source/velero/app/pkg/controller/generic_controller.go:92 +0x6e
created by github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run
    /remote-source/velero/app/pkg/controller/generic_controller.go:91 +0x45a
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x1f0ec1b]
goroutine 1556 [running]:
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc00097c8d0?})
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/runtime/runtime.go:56 +0xd7
panic({0x21f27a0, 0x3d197d0})
    /usr/lib/golang/src/runtime/panic.go:884 +0x212
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).validateAndComplete(0xc000a32dd0, 0xc000ecc500, {0x2aba440, 0xc00059a6e0})
    /remote-source/velero/app/pkg/controller/restore_controller.go:345 +0xc5b
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processRestore(0xc000a32dd0, 0xc000ecc500)
    /remote-source/velero/app/pkg/controller/restore_controller.go:241 +0x117
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processQueueItem(0xc000a32dd0, {0xc000e00a50, 0x42})
    /remote-source/velero/app/pkg/controller/restore_controller.go:224 +0x30c
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).processNextWorkItem(0xc00083e780)
    /remote-source/velero/app/pkg/controller/generic_controller.go:132 +0xeb
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).runWorker(0xc000bd9ea8?)
    /remote-source/velero/app/pkg/controller/generic_controller.go:119 +0x25
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x1f05a60?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:155 +0x3e
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0xc000bd9f58?, {0x2a8ef20, 0xc000d352f0}, 0x1, 0xc000c97080)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:156 +0xb6
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0xc00089c3f0?, 0x3b9aca00, 0x0, 0x5?, 0x0?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:133 +0x89
k8s.io/apimachinery/pkg/util/wait.Until(...)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:90
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run.func2()
    /remote-source/velero/app/pkg/controller/generic_controller.go:92 +0x6e
created by github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run
    /remote-source/velero/app/pkg/controller/generic_controller.go:91 +0x45a

Version-Release number of selected component (if applicable):
OADP 1.2.0-3

How reproducible:
Always
Failing consistently

Steps to Reproduce:
1. Deploy an application

2. Create a backup (wait until backup gets completed successfully)

3. Create a restore CR with hooks.
Example :-

apiVersion: velero.io/v1
kind: Restore
metadata:
   name: mysql-hooks-e2e-614a9540-77ab-11ed-8518-845cf3eff33a
   namespace: openshift-adp
spec:
    backupName: mysql-hooks-e2e-614a9540-77ab-11ed-8518-845cf3eff33a
    hooks:
      resources:
      - includedNamespaces:
        - mysql-persistent
        name: restore-hook-1
        postHooks:
        - exec:
            command:
            - bash
            - -c
            - while ! mysqladmin ping -h localhost --silent; do sleep 1; done
            execTimeout: 2m0s
            onError: Fail
            waitTimeout: 2m0s

Actual results:

Velero pod is going in crashloopbackoff due to nil pointer issue.

$ oc logs velero-6b57869f5b-wkx4n --previous

time="2022-12-09T10:50:27Z" level=info msg="setting log-level to INFO" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:189"
time="2022-12-09T10:50:27Z" level=info msg="Starting Velero server v1.9.2-OADP (-)" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:191"
time="2022-12-09T10:50:27Z" level=info msg="No feature flags enabled" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:195"
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/crd-remap-version
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/pod
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/pv
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/service-account
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/add-pv-from-pvc
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/add-pvc-from-pod
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/admission-webhook-configuration
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/apiservice
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/change-pvc-node-selector
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/change-storage-class
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/cluster-role-bindings
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/crd-preserve-fields
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/init-restore-hook
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/job
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/pod
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/pod-volume-restore
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/role-bindings
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/service
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/velero kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/service-account
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/backup-datavolume-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/backup-virtualmachine-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/backup-virtualmachineinstance-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/restore-pod-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/restore-pvc-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/restore-vm-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/kubevirt-velero-plugin kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=kubevirt-velero-plugin/restore-vmi-action
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugin-for-aws kind=VolumeSnapshotter logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/aws
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugin-for-aws kind=ObjectStore logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=velero.io/aws
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/01-common-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/02-serviceaccount-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/03-pv-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/04-imagestreamtag-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/09-replicationcontroller-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/12-replicaset-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=BackupItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/19-is-backup-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/01-common-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/02-serviceaccount-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/03-pv-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/04-imagestreamtag-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/04-pvc-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/05-route-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/06-build-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/07-pod-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/08-deploymentconfig-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/09-replicationcontroller-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/10-job-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/11-daemonset-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/12-replicaset-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/13-deployment-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/14-statefulset-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/15-service-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/16-cronjob-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/17-buildconfig-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/18-secret-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/19-is-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/20-SCC-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/21-role-bindings-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/22-cluster-role-bindings-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/23-imagetag-restore-plugin
time="2022-12-09T10:50:27Z" level=info msg="registering plugin" command=/plugins/velero-plugins kind=RestoreItemAction logSource="/remote-source/velero/app/pkg/plugin/clientmgmt/process/registry.go:101" name=openshift.io/24-horizontalpodautoscaler-restore-plugin
I1209 10:50:29.011335       1 request.go:601] Waited for 1.029674915s due to client-side throttling, not priority and fairness, request: GET:https://172.30.0.1:443/apis/console.openshift.io/v1?timeout=32s
time="2022-12-09T10:50:30Z" level=info msg="Metrics server is starting to listen" addr=":8080" logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" logger=controller-runtime.metrics
time="2022-12-09T10:50:30Z" level=info msg="Checking existence of namespace." logSource="/remote-source/velero/app/pkg/cmd/server/server.go:418" namespace=openshift-adp
time="2022-12-09T10:50:30Z" level=info msg="Namespace exists" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:424" namespace=openshift-adp
time="2022-12-09T10:50:37Z" level=info msg="Checking existence of Velero custom resource definitions" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:453"
time="2022-12-09T10:50:37Z" level=info msg="All Velero custom resource definitions exist" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:487"
time="2022-12-09T10:50:37Z" level=warning msg="Velero node agent not found; pod volume backups/restores will not work until it's created" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:550"
time="2022-12-09T10:50:37Z" level=warning msg="Velero node agent not found; pod volume backups/restores will not work until it's created" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:559"
I1209 10:50:39.020307       1 request.go:601] Waited for 1.045929201s due to client-side throttling, not priority and fairness, request: GET:https://172.30.0.1:443/apis/storage.k8s.io/v1beta1?timeout=32s
time="2022-12-09T10:50:40Z" level=info msg="Starting controllers" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:604"
time="2022-12-09T10:50:40Z" level=info msg="Starting metric server at address [:8085]" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:611"
time="2022-12-09T10:50:40Z" level=info msg="Waiting for informer caches to sync" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:763"
time="2022-12-09T10:50:42Z" level=info msg="Done waiting for informer caches to sync" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:766"
time="2022-12-09T10:50:42Z" level=info msg="Informer cache synced" informer="*v1.BackupRepository" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:777"
time="2022-12-09T10:50:42Z" level=info msg="Informer cache synced" informer="*v1.VolumeSnapshotLocation" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:777"
time="2022-12-09T10:50:42Z" level=info msg="Informer cache synced" informer="*v1.Backup" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:777"
time="2022-12-09T10:50:42Z" level=info msg="Informer cache synced" informer="*v1.Restore" logSource="/remote-source/velero/app/pkg/cmd/server/server.go:777"
time="2022-12-09T10:50:42Z" level=info msg="Server starting..." logSource="/remote-source/velero/app/pkg/cmd/server/server.go:886"
time="2022-12-09T10:50:42Z" level=info msg="Starting server" addr="{\"IP\":\"::\",\"Port\":8080,\"Zone\":\"\"}" kind=metrics logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" path=/metrics
time="2022-12-09T10:50:42Z" level=info msg="Starting controller" controller=backup logSource="/remote-source/velero/app/pkg/controller/generic_controller.go:76"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backupstoragelocation controllerGroup=velero.io controllerKind=BackupStorageLocation logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.BackupStorageLocation"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backupstoragelocation controllerGroup=velero.io controllerKind=BackupStorageLocation logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.BackupStorageLocationList"
time="2022-12-09T10:50:42Z" level=info msg="Starting Controller" controller=backupstoragelocation controllerGroup=velero.io controllerKind=BackupStorageLocation logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=downloadrequest controllerGroup=velero.io controllerKind=DownloadRequest logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.DownloadRequest"
time="2022-12-09T10:50:42Z" level=info msg="Starting controller" controller=restore logSource="/remote-source/velero/app/pkg/controller/generic_controller.go:76"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=schedule controllerGroup=velero.io controllerKind=Schedule logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.Schedule"
time="2022-12-09T10:50:42Z" level=info msg="Starting Controller" controller=downloadrequest controllerGroup=velero.io controllerKind=DownloadRequest logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=schedule controllerGroup=velero.io controllerKind=Schedule logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.ScheduleList"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backup controllerGroup=velero.io controllerKind=Backup logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.Backup"
time="2022-12-09T10:50:42Z" level=info msg="Starting Controller" controller=schedule controllerGroup=velero.io controllerKind=Schedule logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backup controllerGroup=velero.io controllerKind=Backup logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.BackupList"
time="2022-12-09T10:50:42Z" level=info msg="Starting Controller" controller=backup controllerGroup=velero.io controllerKind=Backup logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backuprepository controllerGroup=velero.io controllerKind=BackupRepository logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.BackupRepository"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backuprepository controllerGroup=velero.io controllerKind=BackupRepository logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.BackupRepositoryList"
time="2022-12-09T10:50:42Z" level=info msg="Starting EventSource" controller=backupstoragelocation controllerGroup=velero.io controllerKind=BackupStorageLocation logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108" source="kind source: *v1.BackupStorageLocation"
time="2022-12-09T10:50:42Z" level=info msg="Starting Controller" controller=backuprepository controllerGroup=velero.io controllerKind=BackupRepository logSource="/remote-source/velero/deps/gomod/pkg/mod/github.com/bombsimon/logrusr/v3@v3.0.0/logrusr.go:108"
E1209 10:50:42.353187       1 runtime.go:79] Observed a panic: "invalid memory address or nil pointer dereference" (runtime error: invalid memory address or nil pointer dereference)
goroutine 1517 [running]:
k8s.io/apimachinery/pkg/util/runtime.logPanic({0x21f27a0?, 0x3d197d0})
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/runtime/runtime.go:75 +0x99
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc000424030?})
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/runtime/runtime.go:49 +0x75
panic({0x21f27a0, 0x3d197d0})
    /usr/lib/golang/src/runtime/panic.go:884 +0x212
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).validateAndComplete(0xc0006f20d0, 0xc0010be780, {0x2aba440, 0xc000596d20})
    /remote-source/velero/app/pkg/controller/restore_controller.go:345 +0xc5b
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processRestore(0xc0006f20d0, 0xc0010be780)
    /remote-source/velero/app/pkg/controller/restore_controller.go:241 +0x117
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processQueueItem(0xc0006f20d0, {0xc000f6a140, 0x42})
    /remote-source/velero/app/pkg/controller/restore_controller.go:224 +0x30c
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).processNextWorkItem(0xc00036b020)
    /remote-source/velero/app/pkg/controller/generic_controller.go:132 +0xeb
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).runWorker(0xc001135ea8?)
    /remote-source/velero/app/pkg/controller/generic_controller.go:119 +0x25
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x1?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:155 +0x3e
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0xc00007dd00?, {0x2a8ef20, 0xc000d57e00}, 0x1, 0xc0007b0180)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:156 +0xb6
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x99336e?, 0x3b9aca00, 0x0, 0x5?, 0xc000f57680?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:133 +0x89
k8s.io/apimachinery/pkg/util/wait.Until(...)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:90
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run.func2()
    /remote-source/velero/app/pkg/controller/generic_controller.go:92 +0x6e
created by github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run
    /remote-source/velero/app/pkg/controller/generic_controller.go:91 +0x45a
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x8 pc=0x1f0ec1b]
goroutine 1517 [running]:
k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc000424030?})
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/runtime/runtime.go:56 +0xd7
panic({0x21f27a0, 0x3d197d0})
    /usr/lib/golang/src/runtime/panic.go:884 +0x212
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).validateAndComplete(0xc0006f20d0, 0xc0010be780, {0x2aba440, 0xc000596d20})
    /remote-source/velero/app/pkg/controller/restore_controller.go:345 +0xc5b
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processRestore(0xc0006f20d0, 0xc0010be780)
    /remote-source/velero/app/pkg/controller/restore_controller.go:241 +0x117
github.com/vmware-tanzu/velero/pkg/controller.(*restoreController).processQueueItem(0xc0006f20d0, {0xc000f6a140, 0x42})
    /remote-source/velero/app/pkg/controller/restore_controller.go:224 +0x30c
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).processNextWorkItem(0xc00036b020)
    /remote-source/velero/app/pkg/controller/generic_controller.go:132 +0xeb
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).runWorker(0xc001135ea8?)
    /remote-source/velero/app/pkg/controller/generic_controller.go:119 +0x25
k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x1?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:155 +0x3e
k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0xc00007dd00?, {0x2a8ef20, 0xc000d57e00}, 0x1, 0xc0007b0180)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:156 +0xb6
k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x99336e?, 0x3b9aca00, 0x0, 0x5?, 0xc000f57680?)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:133 +0x89
k8s.io/apimachinery/pkg/util/wait.Until(...)
    /remote-source/velero/deps/gomod/pkg/mod/k8s.io/apimachinery@v0.24.2/pkg/util/wait/wait.go:90
github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run.func2()
    /remote-source/velero/app/pkg/controller/generic_controller.go:92 +0x6e
created by github.com/vmware-tanzu/velero/pkg/controller.(*genericController).Run
    /remote-source/velero/app/pkg/controller/generic_controller.go:91 +0x45a

Expected results:
Restore should be successful.

Additional info:

Backup hook case passed https://reportportal-migration-qe.apps.ocp-c1.prod.psi.redhat.com/ui/#oadp/launches/all/2441/82365/log?item0Params=filter.eq.hasStats%3Dtrue%26filter.eq.hasChildren%3Dfalse%26filter.in.type%3DSTEP%26filter.in.status%3DPASSED

links to

Prevent nil panic on exec restore hooks #5675

mentioned on

Merge request - fix assert in hook in test OADP-1076

1.	[RedHat QE] Verify Bug OADP-1076 - Velero pod going in crashLoopbackoff when restore hooks is specified	Closed	Prasad Joshi
2.	[IBM QE-P] Verify Bug OADP-1076 - Velero pod going in crashLoopbackoff when restore hooks is specified	Release Pending	Sonia Garudi
3.	[IBM QE-Z] Verify Bug OADP-1076 - Velero pod going in crashLoopbackoff when restore hooks is specified	Release Pending	SHIVA SAI K (Inactive)

Details

Description

Description of problem:

Actual results:

Attachments

Issue Links

Sub-Tasks

Activity

People

Dates