Bug 2003112

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: