Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Race condition causes empty ovf field in vm list #797

Closed
dupondje opened this issue Jan 11, 2023 · 9 comments
Closed

Race condition causes empty ovf field in vm list #797

dupondje opened this issue Jan 11, 2023 · 9 comments

Comments

@dupondje
Copy link
Member

When taking backups of our VM's we also backup the OVF which is returned by the vm's call '/ovirt-engine/api/vms?all_content=true'
Now we started to notice that sometimes the OVF was missing from the output, if you refresh, random VM's end up without OVF data.

After some debugging this looked like a race condition between the export and some monitoring thread?
What we observed:

During the export it does:

2023-01-11 15:19:51.624 UTC DETAIL:  parameters: $1 = '8c993442-96d3-4b2a-a08a-ae1298a51cea', $2 = '3afeaae3-6257-4e75-88a8-1e4bf92f1c55', $3 = 'memballoon', $4 = 'balloon', $5 = '{type=pci, slot=0x00, bus=0x05, domain=0x0000, function=0x0}', $6 = '{
          "model" : "virtio"
        }', $7 = 't', $8 = 't', $9 = 't', $10 = 'ua-8c993442-96d3-4b2a-a08a-ae1298a51cea', $11 = '{ }', $12 = NULL, $13 = NULL, $14 = ''
2023-01-11 15:19:51.624 UTC LOG:  execute S_44: select * from public.updatevmdevice(CAST ($1 AS uuid),CAST ($2 AS uuid),CAST ($3 AS varchar),CAST ($4 AS varchar),CAST ($5 AS varchar),CAST ($6 AS text),CAST ($7 AS bool),CAST ($8 AS bool),CAST ($9 AS bool),CAST ($10 AS varchar),CAST ($11 AS text),CAST ($12 AS uuid),CAST ($13 AS varchar),CAST ($14 AS varchar)) as result
2023-01-11 15:19:51.624 UTC DETAIL:  parameters: $1 = '94c36e10-44a9-4321-bea9-bc9ea5ac2c1a', $2 = '3afeaae3-6257-4e75-88a8-1e4bf92f1c55', $3 = 'usb', $4 = 'controller', $5 = '{type=pci, slot=0x00, bus=0x03, domain=0x0000, function=0x0}', $6 = '{
          "index" : "0",
          "model" : "qemu-xhci"
        }', $7 = 't', $8 = 't', $9 = 'f', $10 = 'ua-94c36e10-44a9-4321-bea9-bc9ea5ac2c1a', $11 = '{ }', $12 = NULL, $13 = NULL, $14 = ''

But some moments later:

2023-01-11 15:19:51.641 UTC LOG:  execute S_45: select * from deletevmdevice($1, $2) as result
2023-01-11 15:19:51.641 UTC DETAIL:  parameters: $1 = '055ab1be-a1f4-47d8-a5c5-a628e29ac794', $2 = '3afeaae3-6257-4e75-88a8-1e4bf92f1c55'
2023-01-11 15:19:51.641 UTC LOG:  execute S_45: select * from deletevmdevice($1, $2) as result
2023-01-11 15:19:51.641 UTC DETAIL:  parameters: $1 = '10e43dc0-6e21-490b-a65f-dfed03daf0fb', $2 = '3afeaae3-6257-4e75-88a8-1e4bf92f1c55'
2023-01-11 15:19:51.641 UTC LOG:  execute S_45: select * from deletevmdevice($1, $2) as result

Some other thread removes the vm devices.

And afaik this bumps the generation, which causes the ovf helper not to export the ova/ovf:
https://github.com/oVirt/ovirt-engine/blob/master/backend/manager/modules/bll/src/main/java/org/ovirt/engine/core/bll/storage/ovfstore/OvfHelper.java#L184

As I don't know the code completely, it's hard to know what the correct fix would be here :) Guess we need some locking on the exporting code so nothing else modifies the vm while exporting?

@dupondje
Copy link
Member Author

The thread that removes the devices is the following btw:

DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-60) [] VM 'xxxx' unmanaged device was marked for remove : {1}

dupondje added a commit to dupondje/ovirt-engine that referenced this issue Jan 12, 2023
Closes: oVirt#797

During the creation of the ovf config export, oVirt does modifications
to the VmDevices.
Now another thread cleans those entries again, and if you are unlucky it
happens during the ovf generation itself.

DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring]
(EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-60)
[] VM 'xxxx' unmanaged device was marked for remove : {1}

And this causes the export to be skipped.

So we add a device lock during the ovf export to resolve this.

Signed-off-by: Jean-Louis Dupond <jean-louis@dupond.be>
@dupondje
Copy link
Member Author

@ahadas :

2023-01-12 09:40:56,996+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: runVdsCommand, params: [DumpXmls, Params:{hostId='231f5ff2-4e00-4977-bc2b-3af1da0a20b1', vmIds='[f9d8fb65-12ff-484a-9409-72583ad2964b, 1f9256d3-deda-40fd-9021-9c1715fe4182]'}], timeElapsed: 23ms
2023-01-12 09:40:57,000+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:57,023+01 WARN  [org.ovirt.engine.core.vdsbroker.libvirt.VmDevicesConverter] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] unmanaged disk with path '/run/vdsm/payload/f9d8fb65-12ff-484a-9409-72583ad2964b.img' is ignored
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='2becac39-d182-4d93-a3db-dbb9377a8daf', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='unix', type='CHANNEL', specParams='[]', address='{type=virtio-serial, bus=0, controller=0, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='ac534997-3c9e-411e-aebc-7d35e1d33f3f', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='unix', type='CHANNEL', specParams='[]', address='{type=virtio-serial, bus=0, controller=0, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='c0f7bdda-d25f-4de5-bb9e-717d52c32d31', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='spicevmc', type='CHANNEL', specParams='[]', address='{type=virtio-serial, bus=0, controller=0, port=3}', managed='false', plugged='true', readOnly='false', deviceAlias='channel2', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='72d92c30-ec6c-46cf-9999-de25f49ded39', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=1, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x0, multifunction=on}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.1', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='e8acf3a3-ac8a-4cde-8bc6-5921b11268a3', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=2, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.2', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='03858947-a6f6-4ac2-8870-15ed428536e3', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=3, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x2}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.3', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='eafbbdcc-85be-4712-a3a1-5f4af9dcb848', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=4, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x3}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.4', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='66f963f2-c143-486f-ba46-b57b4ac403ba', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=5, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x4}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.5', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='74c7ca4c-2adb-4a95-bd86-0acde21f9dd6', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=6, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x5}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.6', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='ab220537-6552-4f18-8e17-08950eea4976', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=7, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x6}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.7', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='9799cc0d-813e-4fe5-b646-6c22bb373ede', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=8, model=pcie-root-port]', address='{type=pci, slot=0x02, bus=0x00, domain=0x0000, function=0x7}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.8', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='7252fd32-b375-4f8b-b929-1401aea2f990', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=9, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x0, multifunction=on}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.9', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='36b441ab-5061-4308-bcf5-df7d70eb66a3', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=10, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.10', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='142d0a0a-471c-49cc-8d3d-5985b5800979', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=11, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x2}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.11', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='77ebb5fe-5d20-4c56-b958-5e7ed0a0fdb0', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=12, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x3}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.12', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='2b429400-e329-43df-9d42-a44b96e7e834', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=13, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x4}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.13', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='70e6ec32-5078-4587-a25f-a067dedbcce2', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=14, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x5}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.14', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='2ab89aba-0f51-462b-9340-84e4f44fb5fe', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=15, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x6}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.15', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='ba6079b4-6355-4861-9ffb-d04be86a2d7d', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='pci', type='CONTROLLER', specParams='[index=16, model=pcie-root-port]', address='{type=pci, slot=0x03, bus=0x00, domain=0x0000, function=0x7}', managed='false', plugged='true', readOnly='false', deviceAlias='pci.16', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] New device was marked for adding to VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' Device : 'VmDevice:{id='VmDeviceId:{deviceId='1d663243-683a-4a62-b3ca-03b75f4bcc77', vmId='f9d8fb65-12ff-484a-9409-72583ad2964b'}', device='sata', type='CONTROLLER', specParams='[index=0]', address='{type=pci, slot=0x1f, bus=0x00, domain=0x0000, function=0x2}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='null', snapshotId='null', logicalName='null', hostDevice='null'}'
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,064+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,065+01 DEBUG [org.ovirt.engine.core.vdsbroker.monitoring.VmDevicesMonitoring] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] VM 'f9d8fb65-12ff-484a-9409-72583ad2964b' unmanaged device was marked for remove : {1}
2023-01-12 09:40:57,160+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:57,160+01 DEBUG [org.ovirt.engine.core.vdsbroker.VmManager$VmDevicesLock] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] unlocking vm devices monitoring for VM f9d8fb65-12ff-484a-9409-72583ad2964b

This was for example a VM that did not contain its ovf config in the api output.
As far as I see the devices are added here: https://github.com/oVirt/ovirt-engine/blob/master/backend/manager/modules/bll/src/main/java/org/ovirt/engine/core/bll/GetVmOvfByVmIdQuery.java#L39

And then the VmDevicesMonitoring directly removes them again, before the ovf export ended.

@ahadas
Copy link
Member

ahadas commented Jan 12, 2023

@dupondje and what happened before 2023-01-12 09:40:56 that led to this update?

@dupondje
Copy link
Member Author

@dupondje and what happened before 2023-01-12 09:40:56 that led to this update?

2023-01-12 09:40:41,683+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-97) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:41,785+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, true], timeElapsed: 0ms
2023-01-12 09:40:41,785+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:41,785+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:41,785+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:41,785+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:41,785+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:41,794+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:41,804+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-9) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:48,989+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-439) [44ad3288-c41e-419f-9f9a-1c3aeb06f06a] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:48,989+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (default task-439) [44ad3288-c41e-419f-9f9a-1c3aeb06f06a] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:56,719+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:56,886+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, true], timeElapsed: 0ms
2023-01-12 09:40:56,886+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:56,886+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:56,886+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:56,886+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:56,886+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:56,959+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:56,973+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b, false], timeElapsed: 0ms
2023-01-12 09:40:56,973+01 DEBUG [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] method: getVmManager, params: [f9d8fb65-12ff-484a-9409-72583ad2964b], timeElapsed: 0ms
2023-01-12 09:40:56,974+01 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] START, DumpXmlsVDSCommand(HostName = hv001, Params:{hostId='231f5ff2-4e00-4977-bc2b-3af1da0a20b1', vmIds='[f9d8fb65-12ff-484a-9409-72583ad2964b, 1f9256d3-deda-40fd-9021-9c1715fe4182]'}), log id: a3136f8
2023-01-12 09:40:56,995+01 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] FINISH, DumpXmlsVDSCommand, return: {f9d8fb65-12ff-484a-9409-72583ad2964b=<domain type='kvm' id='3' xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0'>
  <uuid>f9d8fb65-12ff-484a-9409-72583ad2964b</uuid>
      <entry name='uuid'>f9d8fb65-12ff-484a-9409-72583ad2964b</entry>
      <source file='/run/vdsm/payload/f9d8fb65-12ff-484a-9409-72583ad2964b.img' startupPolicy='optional' index='3'>
      <source mode='bind' path='/var/run/ovirt-vmconsole-console/f9d8fb65-12ff-484a-9409-72583ad2964b.sock'/>
      <source mode='bind' path='/var/run/ovirt-vmconsole-console/f9d8fb65-12ff-484a-9409-72583ad2964b.sock'/>
      <source mode='bind' path='/var/lib/libvirt/qemu/channels/f9d8fb65-12ff-484a-9409-72583ad2964b.ovirt-guest-agent.0'/>
      <source mode='bind' path='/var/lib/libvirt/qemu/channels/f9d8fb65-12ff-484a-9409-72583ad2964b.org.qemu.guest_agent.0'/>

The updates are caused by the ovf export afaik. (https://github.com/oVirt/ovirt-engine/blob/master/backend/manager/modules/bll/src/main/java/org/ovirt/engine/core/bll/GetVmOvfByVmIdQuery.java#L39).
Nothing else except the export was running at that moment. No other changes or whatever.

@ahadas
Copy link
Member

ahadas commented Jan 12, 2023

@dupondje thanks for the additional logs - I'm afraid we can't tell what caused the VM to update from the portion of the log above because unless I'm missing something there're only calls to getVmManager.. but you have the entire log, so please check or share it - it doesn't make sense that the code you referred to updated the VM on the host or in the database, something changed the VM there and led to calling DumpXmls after detecting that the hash of the VM in the database doesn't match the one reported from the host...

@dupondje
Copy link
Member Author

@ahadas: Thanks for checking. I tought the regular DumpXmls calls were normal, but your comment made me aware its not :)

So I checked further, to find out why oVirt kept running the DumpXmls calls.
And it seems they are triggered by the 'GetAllVmStatsVDSCommand'

It seems to run the DumpXml because of the following:
2023-01-12 09:40:57,023+01 WARN [org.ovirt.engine.core.vdsbroker.libvirt.VmDevicesConverter] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-77) [] unmanaged disk with path '/run/vdsm/payload/f9d8fb65-12ff-484a-9409-72583ad2964b.img' is ignored

In the attached logs you can clearly see the thread adds and removes some devices on the vm. Which will bump the generation and cause then the ovf export to fail.
But I think we need to resolved the fact the GetAllVmStatsVDSCommand does this :)

log.txt

@dupondje
Copy link
Member Author

And if I check the db, I see indeed that the devices hash seems to change quite often.
That hash is generated by vdsm, so I checked the debug logs there, and noticed something weird:

2023-01-13 15:23:52,818+0100 DEBUG (jsonrpc/5) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619832.8182437 diff=503.33019948005676 (vm:1949)
2023-01-13 15:23:59,334+0100 DEBUG (jsonrpc/6) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619839.334118 diff=509.8460736274719 (vm:1949)
2023-01-13 15:24:07,882+0100 DEBUG (jsonrpc/2) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619847.8822665 diff=518.3942222595215 (vm:1949)
2023-01-13 15:24:08,524+0100 DEBUG (vmchannels) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') Guest connection timed out (guestagent:560)
2023-01-13 15:24:14,473+0100 DEBUG (jsonrpc/7) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619854.4730744 diff=524.9850301742554 (vm:1949)
2023-01-13 15:24:22,946+0100 DEBUG (jsonrpc/5) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619862.9464297 diff=533.4583854675293 (vm:1949)
2023-01-13 15:24:29,612+0100 DEBUG (jsonrpc/6) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619869.6128905 diff=540.1248462200165 (vm:1949)
2023-01-13 15:24:38,074+0100 DEBUG (jsonrpc/4) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619878.074777 diff=548.5867326259613 (vm:1949)
2023-01-13 15:24:38,554+0100 DEBUG (vmchannels) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') Guest connection timed out (guestagent:560)
2023-01-13 15:24:44,685+0100 DEBUG (jsonrpc/2) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619884.6850967 diff=555.1970524787903 (vm:1949)
2023-01-13 15:24:53,150+0100 DEBUG (jsonrpc/1) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619893.150132 diff=563.6620876789093 (vm:1949)
2023-01-13 15:24:59,858+0100 DEBUG (jsonrpc/5) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619899.8583288 diff=570.3702845573425 (vm:1949)
2023-01-13 15:25:08,217+0100 DEBUG (jsonrpc/4) [virt.vm] (vmId='76e46ed5-fd2e-41bd-b238-3031bbd3e3ee') VM status from guest: event=RebootInProgress event_time=1673619329.4880443 now=1673619908.217762 diff=578.7297177314758 (vm:1949)

For some reason the VM is stuck in RebootInProgress in VDSM, which seems to cause weird things?
But the VM is just running, and if you restart the qemu-ga, you clearly see it in the logs also as connected again.

After restarting vdsm, the changes in devices hash went away, but still the timeouts to the guest agent for some reason...

@ahadas
Copy link
Member

ahadas commented Jan 15, 2023

After restarting vdsm, the changes in devices hash went away,

good, so now you don't see so many calls to DumpXmls, right? if so, that should practically resolve the issue with the missing OVFs - not entirely, it can still happen when the generation changes which in my opinion is something that should be handled on the client side, but the frequency should be reduced significantly

but still the timeouts to the guest agent for some reason...

I don't think it's related to this issue because it shouldn't affect the computed hash but maybe you face the issue that was reported in https://bugzilla.redhat.com/show_bug.cgi?id=2120381?

@dupondje
Copy link
Member Author

@ahadas : Finally found the real cause of the continous dumpxml's :)

Fix in oVirt/vdsm#369

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants