Bug 1954663

Summary: VMs cannot be deleted
Product: Container Native Virtualization (CNV) Reporter: Ruth Netser <rnetser>
Component: NetworkingAssignee: Ram Lavi <ralavi>
Status: CLOSED ERRATA QA Contact: Ruth Netser <rnetser>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 4.8.0CC: cnv-qe-bugs, phoracek, ralavi
Target Milestone: ---Keywords: Regression, TestBlocker
Target Release: 4.8.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: kubemacpool-container-v4.8.0-14 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-07-27 14:31:30 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
VM, VMI yamls and virt-launcher pod
none
VMs in UI console none

Description Ruth Netser 2021-04-28 14:30:18 UTC 
Created attachment 1776743 [details]
VM, VMI yamls and virt-launcher pod

Description of problem:
VMs (running or not) cannot be deleted.

Version-Release number of selected component (if applicable):
CNV 4.8.0
virt-operator v4.8.0-46

How reproducible:
100%

Steps to Reproduce:
1. Create a VM
2. (either start it or not)
3. Delete the VM

Actual results:
VM is not deleted (if the VM is running; VMI and virt-launcher pod are not deleted either)

Expected results:
VM should be deleted.

Additional info:
====== VM ======
VM and VMI yamls attached as well as vir-launcher pod

---
apiVersion: kubevirt.io/v1
kind: VirtualMachine
metadata:
  labels:
    kubevirt.io/vm: vm-cirros114
  name: vm-cirros114
spec:
  running: false
  template:
    metadata:
      labels:
        kubevirt.io/vm: vm-cirros114
    spec:
      domain:
        devices:
          disks:
          - disk:
              bus: virtio
            name: containerdisk
          - disk:
              bus: virtio
            name: cloudinitdisk
        machine:
          type: ""
        resources:
          requests:
            memory: 128Mi
      terminationGracePeriodSeconds: 0
      volumes:
      - containerDisk:
          image: kubevirt/cirros-container-disk-demo:latest
        name: containerdisk
      - cloudInitNoCloud:
          userData: |
            #!/bin/sh

            echo 'printed from cloud-init userdata'
        name: cloudinitdisk
Comment 2 Ruth Netser 2021-04-28 14:34:11 UTC 
$ oc logs -n openshift-cnv virt-api-599947b948-tv2c8 | grep cirros112
{"component":"virt-api","contentLength":0,"level":"info","method":"PUT","pos":"filter.go:46","proto":"HTTP/1.1","remoteAddress":"10.130.0.1","statusCode":202,"timestamp":"2021-04-28T14:07:21.863738Z","url":"/apis/subresources.kubevirt.io/v1alpha3/namespaces/default/virtualmachines/vm-cirros112/start","username":"-"}
[cnv-qe-jenkins@ruty-480-28-nf2ll-executor ~]$ oc logs -n openshift-cnv virt-api-599947b948-tv2c8 | grep "cirros112\|ee0ae3d5600f"
{"component":"virt-api","contentLength":0,"level":"info","method":"PUT","pos":"filter.go:46","proto":"HTTP/1.1","remoteAddress":"10.130.0.1","statusCode":202,"timestamp":"2021-04-28T14:07:21.863738Z","url":"/apis/subresources.kubevirt.io/v1alpha3/namespaces/default/virtualmachines/vm-cirros112/start","username":"-"}


$ oc logs -n openshift-cnv virt-handler-jh999 | grep "cirros112\|ee0ae3d5600f"
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:07:30.519671Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Scheduled\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:07:30.519739Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"","level":"info","msg":"Bind mounting container disk at /var/lib/containers/storage/overlay/22b3789c4effbb618dc6ab9f3678926281d9b47502d2fecc1f7fcad58f8f8a9b/merged/disk/downloaded to /var/lib/kubelet/pods/704e45b6-1fcf-45b7-a8b4-989d418edb57/volumes/kubernetes.io~empty-dir/container-disks/disk_0.img","name":"vm-cirros112","namespace":"default","pos":"mount.go:250","timestamp":"2021-04-28T14:07:30.527095Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"","level":"info","msg":"Accepted new notify pipe connection for vmi","name":"vm-cirros112","namespace":"default","pos":"vm.go:331","timestamp":"2021-04-28T14:07:31.455614Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type ADDED","name":"vm-cirros112","namespace":"default","pos":"server.go:78","timestamp":"2021-04-28T14:07:31.457581Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain is in state Shutoff reason Unknown","name":"vm-cirros112","namespace":"default","pos":"vm.go:2596","timestamp":"2021-04-28T14:07:31.457678Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type MODIFIED","name":"vm-cirros112","namespace":"default","pos":"server.go:78","timestamp":"2021-04-28T14:07:31.458499Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type MODIFIED","name":"vm-cirros112","namespace":"default","pos":"server.go:78","timestamp":"2021-04-28T14:07:31.545833Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain is in state Paused reason StartingUp","name":"vm-cirros112","namespace":"default","pos":"vm.go:2626","timestamp":"2021-04-28T14:07:31.545962Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type MODIFIED","name":"vm-cirros112","namespace":"default","pos":"server.go:78","timestamp":"2021-04-28T14:07:31.996485Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain is in state Running reason Unknown","name":"vm-cirros112","namespace":"default","pos":"vm.go:2626","timestamp":"2021-04-28T14:07:31.996626Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type MODIFIED","name":"vm-cirros112","namespace":"default","pos":"server.go:78","timestamp":"2021-04-28T14:07:32.004511Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:07:32.015289Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Scheduled\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:07:32.015355Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:07:32.015396Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:07:32.032770Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:07:32.032824Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:07:32.032851Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:07:32.047553Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:07:32.047609Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:07:32.047652Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:07:32.074798Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:07:32.074869Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:07:32.074914Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:07:42.482148Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:07:42.482217Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:07:42.482243Z","uid":""}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:12:42.484217Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:12:42.484276Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:12:42.484300Z","uid":""}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:17:42.483056Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:17:42.483114Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:17:42.483148Z","uid":""}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:22:42.484625Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:22:42.484673Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:22:42.484712Z","uid":""}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:27:42.482914Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:27:42.482965Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:27:42.482990Z","uid":""}
{"component":"virt-handler","level":"info","msg":"Processing event default/vm-cirros112","pos":"vm.go:1512","timestamp":"2021-04-28T14:32:42.482617Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1514","timestamp":"2021-04-28T14:32:42.482674Z","uid":"27413a57-ed14-4e93-aff6-c780a11ae925"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"vm-cirros112","namespace":"default","pos":"vm.go:1519","timestamp":"2021-04-28T14:32:42.482712Z","uid":""}
Comment 3 Ruth Netser 2021-04-28 15:02:10 UTC 
Created attachment 1776771 [details]
VMs in UI console
Comment 4 Ruth Netser 2021-04-29 11:16:13 UTC 
From Ram:
"In short, kubemacpool needs to wait for kubevirt to appear, but it doesn't do that now
since kubevirt is not waited for, the VM controller is not created, and as a consequence, when vms are deleted, the VM controller is not there to remove the finalizer"
Comment 5 Ram Lavi 2021-04-29 12:51:40 UTC 
PR to solve this. https://github.com/k8snetworkplumbingwg/kubemacpool/pull/292
Comment 7 Ram Lavi 2021-05-06 14:38:04 UTC 
Hi
Before verifying this bug, make sure that during this particular deployment, kubemacpool was present before kubevirt was ready - otherwise the scenario was not reproduced.

An easy way to check this is by checking the kubemacpool logs like so:
oc logs -n openshift-cnv <kubemacpool-pod-name> | grep "kubevirt was not found in the cluster start a watching process"
Comment 8 Ruth Netser 2021-05-10 10:47:42 UTC 
Verified with kubemacpool-mac-controller-manager v4.8.0-14

- Verified that kubemacpool was present before kubevirt was ready:
$ oc logs -n openshift-cnv kubemacpool-mac-controller-manager-6d46fb95d5-hrkfw |grep "kubevirt was not found"
{"level":"info","ts":1620585745.117114,"logger":"manager","msg":"kubevirt was not found in the cluster start a watching process"}

- VMs can be deleted
Comment 11 errata-xmlrpc 2021-07-27 14:31:30 UTC 
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.8.0 Images), 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:2920