Description of problem: VM failed to start vm while the restore from offline vm snapshot was not complete Version-Release number of selected component (if applicable): oc version Client Version: 4.8.0-0.nightly-2021-04-09-101800 Server Version: 4.8.0-0.nightly-2021-04-09-101800 Kubernetes Version: v1.21.0-rc.0+6d27558 oc get csv -n openshift-cnv NAME DISPLAY VERSION REPLACES PHASE kubevirt-hyperconverged-operator.v4.8.0 OpenShift Virtualization 4.8.0 kubevirt-hyperconverged-operator.v2.5.3 Succeeded How reproducible: Sometimes Steps to Reproduce: 1. Create a vm with large disk 2. Created 3 offline snapshots 3. Started the restore snapshot operation to snapshot2 and started the VM very soon after with virtctl start vm-name >>>>> The vm would not come up. Checked the restore snapshot was not complete. Stopped the VM, the restore completed and started the vm successfully Actual results: VM would not start as vm restored from snapshot was in progress Expected results: virtctl vm start should not have tried to start the vm Additional info: oc describe virtualmachinerestore restore-snapshot-3 Name: restore-snapshot-3 Namespace: default Labels: <none> Annotations: <none> API Version: snapshot.kubevirt.io/v1alpha1 Kind: VirtualMachineRestore Metadata: Creation Timestamp: 2021-05-05T13:36:22Z Generation: 3 Managed Fields: API Version: snapshot.kubevirt.io/v1alpha1 Fields Type: FieldsV1 fieldsV1: f:spec: .: f:target: .: f:apiGroup: f:kind: f:name: f:virtualMachineSnapshotName: Manager: kubectl-create Operation: Update Time: 2021-05-05T13:36:22Z API Version: snapshot.kubevirt.io/v1alpha1 Fields Type: FieldsV1 fieldsV1: f:metadata: f:ownerReferences: .: k:{"uid":"b2a1551e-8e2a-48ed-9b5e-aeb8b1a084ac"}: .: f:apiVersion: f:blockOwnerDeletion: f:controller: f:kind: f:name: f:uid: f:status: .: f:complete: f:conditions: f:restores: Manager: virt-controller Operation: Update Time: 2021-05-05T13:36:22Z Owner References: API Version: kubevirt.io/v1 Block Owner Deletion: true Controller: true Kind: VirtualMachine Name: vm-win19-datavolume UID: b2a1551e-8e2a-48ed-9b5e-aeb8b1a084ac Resource Version: 16585098 UID: 83ecc50d-4771-43f4-92c8-015773930932 Spec: Target: API Group: kubevirt.io Kind: VirtualMachine Name: vm-win19-datavolume Virtual Machine Snapshot Name: test-snapshot-3 Status: Complete: false Conditions: Last Probe Time: <nil> Last Transition Time: 2021-05-05T13:36:22Z Reason: Creating new PVCs Status: True Type: Progressing Last Probe Time: <nil> Last Transition Time: 2021-05-05T13:36:22Z Reason: Waiting for new PVCs Status: False Type: Ready Restores: Persistent Volume Claim: restore-83ecc50d-4771-43f4-92c8-015773930932-datavolumedisk1 Volume Name: datavolumedisk1 Volume Snapshot Name: vmsnapshot-b472641b-b12b-423f-9ef6-8779177d3d3a-volume-datavolumedisk1 Events: <none> device virtio-blk-pci-non-transitional,bus=pci.4,addr=0x0,drive=libvirt-1-format,id=ua-datavolumedisk1,bootindex=1,write-cache=on,werror=stop,rerror=stop \\-netdev tap,fd=21,id=hostua-default,vhost=on,vhostfd=22 \\-device virtio-net-pci-n on-transitional,host_mtu=1392,netdev=hostua-default,id=ua-default,mac=52:54:00:47:dd:ed,bus=pci.1,addr=0x0,romfile= \\-chardev socket,id=charserial0,fd=23,server,nowait \\-device isa-serial,chardev=charserial0,id=serial0 \\-chardev socket ,id=charchannel0,fd=24,server,nowait \\-device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_agent.0 \\-vnc vnc=unix:/var/run/kubevirt-private/3711ad45-5bfd-4a72-a1c5-a988c4655dcd/virt-vnc \ \-device VGA,id=video0,vgamem_mb=16,bus=pcie.0,addr=0x1 \\-device virtio-balloon-pci-non-transitional,id=balloon0,bus=pci.5,addr=0x0 \\-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny \\-msg timestamp=on"," subcomponent":"qemu","timestamp":"2021-05-05T12:45:19.470968Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:45:19.507172Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"Found PID for 8601e0ad-f15c-5b35-a822-d5451aed0625: 70","pos":"monitor.go:135","timestamp":"2021-05-05T12:45:19.574326Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:45:19.650790Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:45:27.773994Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"GuestAgentLifecycle event state 1 with reason 2 received","pos":"client.go:458","timestamp":"2021-05-05T12:46:18.044015Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:18.051573Z"} {"component":"virt-launcher","level":"info","msg":"Domain name event: default_vm-win19-datavolume","pos":"client.go:377","timestamp":"2021-05-05T12:46:18.060394Z"} {"component":"virt-launcher","level":"info","msg":"Starting agent poller with commands: [guest-info]","pos":"agent_poller.go:297","timestamp":"2021-05-05T12:46:18.060509Z"} {"component":"virt-launcher","level":"info","msg":"Starting agent poller with commands: [guest-network-get-interfaces guest-get-osinfo guest-get-timezone guest-get-host-name]","pos":"agent_poller.go:297","timestamp":"2021-05-05T12:46:18.0 60557Z"} {"component":"virt-launcher","level":"info","msg":"Starting agent poller with commands: [guest-get-fsinfo]","pos":"agent_poller.go:297","timestamp":"2021-05-05T12:46:18.060571Z"} {"component":"virt-launcher","level":"info","msg":"Starting agent poller with commands: [guest-get-users]","pos":"agent_poller.go:297","timestamp":"2021-05-05T12:46:18.060581Z"} {"component":"virt-launcher","level":"info","msg":"Polling command: [guest-get-users]","pos":"agent_poller.go:196","timestamp":"2021-05-05T12:46:18.060637Z"} {"component":"virt-launcher","level":"info","msg":"Polling command: [guest-network-get-interfaces guest-get-osinfo guest-get-timezone guest-get-host-name]","pos":"agent_poller.go:196","timestamp":"2021-05-05T12:46:18.060913Z"} {"component":"virt-launcher","level":"info","msg":"Polling command: [guest-info]","pos":"agent_poller.go:196","timestamp":"2021-05-05T12:46:18.060973Z"} {"component":"virt-launcher","level":"info","msg":"Polling command: [guest-get-fsinfo]","pos":"agent_poller.go:196","timestamp":"2021-05-05T12:46:18.061309Z"} {"component":"virt-launcher","level":"warning","msg":"Domain id=1 name='default_vm-win19-datavolume' uuid=8601e0ad-f15c-5b35-a822-d5451aed0625 is tainted: custom-ga-command","pos":"qemuDomainObjTaint:6292","subcomponent":"libvirt","thread ":"31","timestamp":"2021-05-05T12:46:18.064000Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:18.074704Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:18.148124Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:18.370756Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:18.389228Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:20.029581Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:20.039090Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:20.043265Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:20.047974Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:20.052917Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:20.057276Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:20.061006Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:20.084157Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:20.126005Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"error","msg":"Guest agent is not responding: Guest agent not available for now","pos":"qemuAgentSend:850","subcomponent":"libvirt","thread":"30","timestamp":"2021-05-05T12:46:35.328000Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:36.053126Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:36.053126Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:36.064732Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:56.054595Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:56.065052Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:57.102354Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:57.109467Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:46:58.385469Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:46:58.394147Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:47:36.059108Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:47:36.069583Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:47:37.131008Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:47:37.140044Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:48:56.064381Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:48:56.073997Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:48:57.171051Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:48:57.183358Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:50:27.778129Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:50:27.832214Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:50:57.194914Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:50:57.204108Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:50:57.322984Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:51:36.070512Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:51:36.080429Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:52:57.194738Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:52:57.204043Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:54:57.191081Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:54:57.202795Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:55:27.774165Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:55:27.826613Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:56:36.076407Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:56:36.086316Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:56:36.120423Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:56:57.268670Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:56:57.279284Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T12:58:57.205807Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T12:58:57.216127Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:00:27.777227Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:00:27.827871Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:00:57.206710Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:00:57.215192Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:00:57.247336Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:01:36.084697Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:01:36.095561Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:02:57.196279Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:02:57.205564Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:04:57.195082Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:04:57.205531Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:05:27.773663Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:05:27.825107Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:06:36.092136Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:06:36.103278Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:06:36.139280Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:06:57.193341Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:06:57.208209Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:08:57.196499Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:08:57.207419Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:10:27.833821Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:10:28.017354Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:10:57.193588Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:10:57.202157Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:10:57.251034Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:11:36.074044Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:11:36.082391Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:12:57.193658Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:12:57.203616Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:14:57.201168Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:14:57.218341Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:15:27.780853Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:15:27.859272Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:16:36.076411Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:16:36.087911Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:16:36.138841Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:16:57.191509Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:16:57.202188Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:18:57.209627Z"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:19:03.773824Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:19:03.882962Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:20:27.774538Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:20:27.813825Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:20:57.219620Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:20:57.229032Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:20:57.257913Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:22:57.201329Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:22:57.214178Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:24:45.838675Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:24:57.198541Z"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:24:57.424830Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:25:28.021596Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:25:39.882871Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:26:50.513925Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:26:57.191587Z"} {"component":"virt-launcher","kind":"VirtualMachineInstance","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:27:03.633566Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:27:03.645966Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:27:03.678205Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:28:57.191659Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:28:57.199937Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:30:27.773806Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:30:27.823982Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:262","timestamp":"2021-05-05T13:30:57.199255Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:30:57.207247Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-win19-datavolume","namespace":"default","pos":"server.go:167","timestamp":"2021-05-05T13:30:57.243877Z","uid":"3711ad45-5bfd-4a72-a1c5-a988c4655dcd"} {"component":"virt-launcher","level":"info","msg":"Received signal terminated","pos":"virt-launcher.go:442","timestamp":"2021-05-05T13:31:22.873791Z"} {"component":"virt-launcher","level":"error","msg":"Failed to terminate process 70 with SIGTERM: Device or resource busy","pos":"virProcessKillPainfullyDelay:431","subcomponent":"libvirt","thread":"37","timestamp":"2021-05-05T13:31:37.854000Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 6 with reason 2 received","pos":"client.go:401","timestamp":"2021-05-05T13:31:38.113944Z"} (END) ----------------------------------------------------- oc get pv NAME CAPACITY ACCESS MODES RECLAIM POLICY STATUS CLAIM STORAGECLASS REASON AGE local-pv-9df2e109 250Gi RWO Delete Bound openshift-storage/ocs-deviceset-1-data-0tw2b6 local-block 14d local-pv-c87a4c93 250Gi RWO Delete Bound openshift-storage/ocs-deviceset-0-data-0dz85g local-block 14d local-pv-cc48e595 250Gi RWO Delete Bound openshift-storage/ocs-deviceset-2-data-0vrj5x local-block 14d nfs-pv-01 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-02 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-03 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-04 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-05 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-06 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-07 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-08 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-09 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-10 5Gi RWO,RWX Retain Available nfs 14d nfs-pv-11 25Gi RWO,RWX Retain Available nfs 14d nfs-pv-12 25Gi RWO,RWX Retain Available nfs 14d nfs-pv-13 25Gi RWO,RWX Retain Available nfs 14d nfs-pv-14 25Gi RWO,RWX Retain Available nfs 14d nfs-pv-15 25Gi RWO,RWX Retain Available nfs 14d nfs-pv-16 25Gi RWO,RWX Retain Available nfs 14d nfs-pv-17 70Gi RWO,RWX Retain Available nfs 14d nfs-pv-18 70Gi RWO,RWX Retain Available nfs 14d nfs-pv-19 70Gi RWO,RWX Retain Available nfs 14d nfs-pv-20 70Gi RWO,RWX Retain Available nfs 14d pvc-2afdaf48-e12b-4453-83d1-2387e6722e7d 5Gi RWO Delete Bound default/vm1-disk1-rbd-block ocs-storagecluster-ceph-rbd 2d pvc-80b0ee54-112b-4737-9bc2-d662dde8c142 954Mi RWO Delete Bound default/vm1-disk2-rbd-block ocs-storagecluster-ceph-rbd 2d pvc-bbb37198-daa1-4892-ba8e-ecfaf7307346 58Gi RWO Delete Bound default/win19-dv ocs-storagecluster-ceph-rbd 2d pvc-c843d137-a106-4e57-902d-14637629155b 50Gi RWO Delete Bound openshift-storage/db-noobaa-db-pg-0 ocs-storagecluster-ceph-rbd 14d oc get dv NAME PHASE PROGRESS RESTARTS AGE vm1-disk1-rbd-block Succeeded 100.0% 2d vm1-disk2-rbd-block Succeeded 100.0% 2d win19-dv Succeeded 100.0% 2d [cnv-qe-jenkins@stg03-kevin-6jx9c-executor kev]$ oc get pvc NAME STATUS VOLUME CAPACITY ACCESS MODES STORAGECLASS AGE restore-83ecc50d-4771-43f4-92c8-015773930932-datavolumedisk1 Pending ocs-storagecluster-ceph-rbd 49m vm1-disk1-rbd-block Bound pvc-2afdaf48-e12b-4453-83d1-2387e6722e7d 5Gi RWO ocs-storagecluster-ceph-rbd 2d vm1-disk2-rbd-block Bound pvc-80b0ee54-112b-4737-9bc2-d662dde8c142 954Mi RWO ocs-storagecluster-ceph-rbd 2d win19-dv Bound pvc-bbb37198-daa1-4892-ba8e-ecfaf7307346 58Gi RWO ocs-storagecluster-ceph-rbd 2d [cnv-qe-jenkins@stg03-kevin-6jx9c-executor kev]$ oc get vm NAME AGE VOLUME vm-win19-datavolume 2d vm2disk-fedora-fedora-datavolume-rbd-block 2d oc describe virtualmachinerestore restore-snapshot-3 [cnv-qe-jenkins@stg03-kevin-6jx9c-executor kev]$ oc get vmi NAME AGE PHASE IP NODENAME vm-win19-datavolume 100m Failed 10.128.2.177 stg03-kevin-6jx9c-worker-0-4rghs [cnv-qe-jenkins@stg03-kevin-6jx9c-executor kev]$ oc get virtualmachinesnapshots NAME SOURCEKIND SOURCENAME READYTOUSE CREATIONTIME ERROR test-snapshot-1 VirtualMachine vm-win19-datavolume true 60m test-snapshot-2 VirtualMachine vm-win19-datavolume true 60m test-snapshot-3 VirtualMachine vm-win19-datavolume true 59m test-snapshot-4 VirtualMachine vm-win19-datavolume true 59m
Re-assigning this to the storage component because this BZ appears to be about blocking on storage related events. Please feel free to revert if you think this is a core Virtualization issue.
Hey Michael. How are we handling the case where a VM undergoing a restore is immediately started? My expectation is that the restore would be finished first and then the VM would be launched.
currently VM status reports "snapshot in progress" but not "restore in progress". It should. Would make such synchronization possible.
Not fixable in time for 4.8 and not a blocker. Since this will introduce user-visible changes via the APIs and there is a clear workaround I am pushing to 4.9. Workaround: Wait until the restore is completed before attempting to start the VM.
Verified with the following code: --------------------------------------- oc version Client Version: 4.9.0-202107292313.p0.git.1557476.assembly.stream-1557476 Server Version: 4.9.0-0.nightly-2021-08-04-025616 Kubernetes Version: v1.21.1+8268f88 [cnv-qe-jenkins@stg10-kevin-jdtkw-executor kev]$ oc get csv -n openshift-cnv NAME DISPLAY VERSION REPLACES PHASE kubevirt-hyperconverged-operator.v4.9.0 OpenShift Virtualization 4.9.0 kubevirt-hyperconverged-operator.v4.8.1 Succeeded Verified with the following scenario: --------------------------------------- 1. Create a vm with large disk 2. Created 3 offline snapshots 3. Started the restore snapshot operation to snapshot2 and started the VM very soon after with virtctl start vm-name >>>>> Error starting VirtualMachine Internal error occurred: admission webhook "virtualmachine-validator.kubevirt.io" denied the request: Cannot start VM until restore "restore-snapshot-2" completes The expected behaviour is now correct. Moving to VERIFIED!
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory (Moderate: OpenShift Virtualization 4.9.0 Images security and bug fix update), and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHSA-2021:4104