kubevirt: ghost record not cleanup properly causes error to find the correct launcher client

BUG REPORT:

/kind bug

What happened: We noticed an issue that VMI stuck in Scheduled and the launcher pod was Error:

NAMESPACE  NAME          AGE    PHASE       IP     NODENAME
ns01       vm-08         12h    Scheduled            node01


NAMESPACE  NAME                        READY STATUS RESTARTS AGE 
ns01      virt-launcher-vm-08-2pdj6      2/3   Error     0   12h

Looked into the stuck vmi, the pod went to Error because the compute container was terminated due to timeout failure of creating virt-launcher client connection when the entry already exists with differing UID

{“component”:“virt-handler”,“kind”:“”,“level”:“error”,“msg”:“Synchronizing the VirtualMachineInstance failed.”,“name”:“vm-08”,“namespace”:“ns01”,“pos”:“vm.go:1359”,“reason”:“unable to create virt-launcher client connection: can not add ghost record when entry already exists with differing UID”,“timestamp”:“2021-12-08T09:23:02.504977Z”,“uid”:“054e439b-4402-4a65-9dd1-70e4235762b3”}

Events:
  Type     Reason      Age                     From          Message
  ----     ------      ----                    ----          -------
  Warning  SyncFailed  4m30s (x4316 over 13h)  virt-handler  unable to create virt-launcher client connection: can not add ghost record when entry already exists with differing UID

{“component”:“virt-launcher”,“level”:“info”,“msg”:“Marked as ready”,“pos”:“virt-launcher.go:72”,“timestamp”:“2021-12-08T09:23:02.187469Z”} panic: timed out waiting for domain to be defined

goroutine 1 [running]: main.waitForDomainUUID(0x45d964b800, 0xc0003376e0, 0xc0005a68a0, 0x1af0838, 0xc000452180, 0x0) cmd/virt-launcher/virt-launcher.go:218 +0x517 main.main() cmd/virt-launcher/virt-launcher.go:449 +0x1265

This is an issue that virt-handler was using a wrong virt-launcher client to build connection.

{“component”:“virt-handler”,“kind”:“VirtualMachineInstance”,“level”:“error”,“msg”:“Updating the VirtualMachineInstance status failed.”,“name”:“vm-08”,“namespace”:“ns01”,“pos”:“vm.go:1366”,“reason”:“Operation cannot be fulfilled on virtualmachineinstances.kubevirt.io "vm-08": StorageError: invalid object, Code: 4, Key: /registry/kubevirt.io/virtualmachineinstances/ns01/vm-08, ResourceVersion: 0, AdditionalErrorMsg: Precondition failed: UID in precondition: 8667609c-15c6-44dd-bdc1-704ee0bdf40f, UID in object meta: 054e439b-4402-4a65-9dd1-70e4235762b3”,“timestamp”:“2021-12-08T09:22:54.560475Z”,“uid”:“8667609c-15c6-44dd-bdc1-704ee0bdf40f”}

The error can not add ghost record when entry already exists with differing UID showed that the ghost record was not deleted properly. This issue was noticed when a pod was evicted from node which went NotReady for a period of time, and virt-handler did not properly handle VMI shutdown process and cleanup of local data.

What you expected to happen: A rebooted VMI scheduled to the node where a prior vmi of the same name was terminated improperly can be Running

How to reproduce it (as minimally and precisely as possible):

Anything else we need to know?:

Environment:

  • KubeVirt version (use virtctl version): 0.35
  • Kubernetes version (use kubectl version): 1.20
  • VM or VMI specifications:
  • Cloud provider or hardware configuration: bare metal
  • OS (e.g. from /etc/os-release):
     NAME="CentOS Linux"
     VERSION="8 (Core)"
      ID="centos"
      ID_LIKE="rhel fedora"
      VERSION_ID="8"
      PLATFORM_ID="platform:el8"
      PRETTY_NAME="CentOS Linux 8 (Core)"
      ANSI_COLOR="0;31"
      CPE_NAME="cpe:/o:centos:centos:8"
      HOME_URL="https://www.centos.org/"
      BUG_REPORT_URL="https://bugs.centos.org/"
      CENTOS_MANTISBT_PROJECT="CentOS-8"
      CENTOS_MANTISBT_PROJECT_VERSION="8"
      REDHAT_SUPPORT_PRODUCT="centos"
    
  • Kernel (e.g. uname -a):
    Linux gs-node.nvmetal.net 4.18.0-193.13.2.el8.1622008870.664c92a05.x86_64 #1 SMP Wed May 26 13:04:56 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
    
  • Install tools:
  • Others:

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 17 (13 by maintainers)

Most upvoted comments

interesting bug.

The ghost records exist in order to guarantee that a VMI’s local data is cleaned up when virt-handler re-initializes even if the VMI is deleted from etcd.

What you’re hitting is that the ghost record for a VMI is sticking around even after a new VMI with the exact same name has been created. Looking at the code, we don’t handle this situation at all, and the result is the new VMI will never get processed.

Here’s my suggestion as a fix.

When virt-handler is executing on a VMI, add a check to determine if an old ghost record exists for the a VMI with the same name but has a different UID. If that condition exists, run the equavalent of this code in order to process the cleanup of the old ghost record. https://github.com/kubevirt/kubevirt/blob/bf73abb9ac945bc0798b88235db8f487be0d5d82/pkg/virt-handler/vm.go#L1745

We’re already doing this exact same thing to cleanup when we detect an old domain exists somehow, so extend that logic to handle when an old ghost record exists somehow.