Bug 2003112 - Frequent ' VirtualMachineInstance defined' events for the VM when there is no activity
Summary: Frequent ' VirtualMachineInstance defined' events for the VM when there is no...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Container Native Virtualization (CNV)
Classification: Red Hat
Component: Virtualization
Version: 2.6.6
Hardware: All
OS: Linux
high
medium
Target Milestone: ---
: 4.9.1
Assignee: David Vossel
QA Contact: Denys Shchedrivyi
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-09-10 12:04 UTC by nijin ashok
Modified: 2024-12-20 21:01 UTC (History)
7 users (show)

Fixed In Version: virt-operator-container-v4.9.1-2 hco-bundle-registry-container-v4.9.1-2
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-12-13 19:59:01 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2021:5091 0 None None None 2021-12-13 19:59:17 UTC

Description nijin ashok 2021-09-10 12:04:44 UTC
Description of problem:

In the events of the virtual machines, we can see frequent "VirtualMachineInstance defined" events for every VMs. I can see these events in my namespace without any activity.

~~~
oc get events |grep "VirtualMachineInstance defined"
37s         Normal    Created                 virtualmachineinstance/rhel7-creepy-camel          VirtualMachineInstance defined.
2m47s       Normal    Created                 virtualmachineinstance/rhel7-horizontal-mackerel   VirtualMachineInstance defined.
69s         Normal    Created                 virtualmachineinstance/rhel7-kind-coyote           VirtualMachineInstance defined.

oc get vmi
NAME                        AGE   PHASE     IP            NODENAME
rhel7-creepy-camel          10d   Running   10.128.2.36   openshift-worker-1
rhel7-horizontal-mackerel   10d   Running   10.128.2.49   openshift-worker-1
rhel7-kind-coyote           8d    Running   10.128.2.88   openshift-worker-1
~~~

The virt-handler says it got an event "Received Domain Event of type MODIFIED".

~~~
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type MODIFIED","name":"rhel7-horizontal-mackerel","namespace":"nijin-cnv","pos":"server.go:78","timestamp":"2021-09-10T11:33:53.510457Z","uid":"095ed6b4-e4cf-4602-84af-d80d8afa8eb2"}
{"component":"virt-handler","level":"info","msg":"Processing event nijin-cnv/rhel7-horizontal-mackerel","pos":"vm.go:1399","timestamp":"2021-09-10T11:33:53.510648Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"rhel7-horizontal-mackerel","namespace":"nijin-cnv","pos":"vm.go:1401","timestamp":"2021-09-10T11:33:53.510683Z","uid":"095ed6b4-e4cf-4602-84af-d80d8afa8eb2"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"rhel7-horizontal-mackerel","namespace":"nijin-cnv","pos":"vm.go:1406","timestamp":"2021-09-10T11:33:53.510713Z","uid":"095ed6b4-e4cf-4602-84af-d80d8afa8eb2"}
{"component":"virt-handler","level":"info","msg":"Processing event nijin-cnv/rhel7-horizontal-mackerel","pos":"vm.go:1399","timestamp":"2021-09-10T11:33:53.572393Z"}
{"component":"virt-handler","kind":"","level":"info","msg":"VMI is in phase: Running\n","name":"rhel7-horizontal-mackerel","namespace":"nijin-cnv","pos":"vm.go:1401","timestamp":"2021-09-10T11:33:53.572466Z","uid":"095ed6b4-e4cf-4602-84af-d80d8afa8eb2"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Domain status: Running, reason: Unknown\n","name":"rhel7-horizontal-mackerel","namespace":"nijin-cnv","pos":"vm.go:1406","timestamp":"2021-09-10T11:33:53.572499Z","uid":"095ed6b4-e4cf-4602-84af-d80d8afa8eb2"}
{"component":"virt-handler","kind":"Domain","level":"info","msg":"Received Domain Event of type MODIFIED","name":"rhel7-kind-coyote","namespace":"nijin-cnv","pos":"server.go:78","timestamp":"2021-09-10T11:35:11.364844Z","uid":"8970d90c-ab64-43fd-acc6-21d8a4589ae7"}
~~~

I can see `Synced vmi` every 2 minutes in the virt-launcher. So virt-handler does process the event and send `SyncVirtualMachine`. 

~~~
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:241","timestamp":"2021-09-10T11:31:45.925313Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"rhel7-creepy-camel","namespace":"nijin-cnv","pos":"server.go:186","timestamp":"2021-09-10T11:31:45.931138Z","uid":"ea022202-b106-4116-94af-b53063c8f857"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"rhel7-creepy-camel","namespace":"nijin-cnv","pos":"server.go:186","timestamp":"2021-09-10T11:33:43.381638Z","uid":"ea022202-b106-4116-94af-b53063c8f857"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:241","timestamp":"2021-09-10T11:33:45.960696Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"rhel7-creepy-camel","namespace":"nijin-cnv","pos":"server.go:186","timestamp":"2021-09-10T11:33:45.967995Z","uid":"ea022202-b106-4116-94af-b53063c8f857"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:241","timestamp":"2021-09-10T11:35:45.938986Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"rhel7-creepy-camel","namespace":"nijin-cnv","pos":"server.go:186","timestamp":"2021-09-10T11:35:45.947558Z","uid":"ea022202-b106-4116-94af-b53063c8f857"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:241","timestamp":"2021-09-10T11:37:45.956805Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"rhel7-creepy-camel","namespace":"nijin-cnv","pos":"server.go:186","timestamp":"2021-09-10T11:37:45.968483Z","uid":"ea022202-b106-4116-94af-b53063c8f857"}
~~~

It happens every 2 minutes and it looks to be coming from "agentpoller" and "qemuAgentSysInterval" is 2 minutes. This worker runs qemu-monitor commands guest-network-get-interfaces, guest-get-osinfo, guest-get-timezone and guest-get-host-name. As per my understanding, the "MODIFIED" event will be generated only when it sees new data compared to what it has stored in the last iteration.

I enabled the libvirtd debug logs and I cannot see any data getting changed(other than the packet statistics in guest-network-get-interfaces which anyway we are not storing). We don't have any log to understand from where exactly we are getting these events.

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

v 2.6.6

How reproducible:

Observed in two lab environments and in customer's environment.

Steps to Reproduce:

Observe the event page of VM in the Openshift console and we can see frequent ' VirtualMachineInstance defined' messages.


Actual results:

Frequent ' VirtualMachineInstance defined' events for the VM when there is no activity

Expected results:


Additional info:

Comment 2 Roman Mohr 2021-10-20 12:26:52 UTC
Backport for 4.9: https://github.com/kubevirt/kubevirt/pull/6653

Comment 3 Roman Mohr 2021-10-21 07:50:30 UTC
Backported to the target release.

Comment 6 Denys Shchedrivyi 2021-11-09 23:12:27 UTC
Verified with virt-operator-container-v4.9.1-4

Comment 12 errata-xmlrpc 2021-12-13 19:59:01 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 (OpenShift Virtualization 4.9.1 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/RHBA-2021:5091


Note You need to log in before you can comment on or make changes to this bug.