Bug 1617745 - startUnderlyingVm fails with exception resulting in split-brain
Summary: startUnderlyingVm fails with exception resulting in split-brain
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: vdsm
Version: 4.2.5
Hardware: x86_64
OS: Linux
Target Milestone: ovirt-4.3.0
: 4.3.0
Assignee: Milan Zamazal
QA Contact: Liran Rotenberg
Whiteboard: QE Sanity Only
Depends On:
Blocks: 1625646 1627289
TreeView+ depends on / blocked
Reported: 2018-08-16 04:34 UTC by Germano Veit Michel
Modified: 2021-12-10 17:05 UTC (History)
11 users (show)

Fixed In Version: v4.30.3
Doc Type: Bug Fix
Doc Text:
Previously, when a migrating virtual machine was not properly set up on the destination host, it could still start there under certain circumstances, then run unnoticed and without VDSM supervision. This situation sometimes resulted in split-brain. Now migration is always prevented from starting if the virtual machine set up fails on the destination host.
Clone Of:
: 1625646 1627289 (view as bug list)
Last Closed: 2018-11-20 13:02:03 UTC
oVirt Team: Virt
Target Upstream Version:
lsvaty: testing_plan_complete-

Attachments (Terms of Use)

System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker RHV-44247 0 None None None 2021-12-10 17:05:29 UTC
oVirt gerrit 94055 0 master MERGED virt: Wait until migration is fully prepared before reporting success 2020-07-06 18:55:40 UTC
oVirt gerrit 94161 0 ovirt-4.2 MERGED virt: Wait until migration is fully prepared before reporting success 2020-07-06 18:55:40 UTC

Description Germano Veit Michel 2018-08-16 04:34:18 UTC
Description of problem:

An exception during _startUnderlyingVm on an incoming migration leaves a VM running happily on the host and vdsm is NOT reporting it. So Down on RHV-M and Up on the host. This leaves space for data corruption if the VM has no lease.

The exception/error is being handled in BZ1598781. What is requested here is to better handle the exceptions so that if some other error occurs, at least the VM is killed to prevent a split brain.

1. During an incoming migration, VDSM failed to "start" the VM:

2018-08-16 10:15:39,271+1000 ERROR (vm/2e6bb483) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') The vm start process failed (vm:942)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 871, in _startUnderlyingVm
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2791, in _run
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2615, in _setup_devices
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vmdevices/graphics.py", line 91, in setup
    displaynetwork.create_network(display_network, self.vmid)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/displaynetwork.py", line 27, in create_network
    libvirtnetwork.create_network(netname, display_device, user_reference)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/libvirtnetwork.py", line 89, in create_network
    _createNetwork(createNetworkDef(netname, bridged, iface))
  File "/usr/lib/python2.7/site-packages/vdsm/virt/libvirtnetwork.py", line 108, in _createNetwork
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2981, in setAutostart
    if ret == -1: raise libvirtError ('virNetworkSetAutostart() failed', net=self)
libvirtError: Failed to create symlink '/etc/libvirt/qemu/networks/autostart/vdsm-production.xml' to '/etc/libvirt/qemu/networks/vdsm-production.xml': File exists

2. VM is "down"

2018-08-16 10:15:39,271+1000 INFO  (vm/2e6bb483) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') Changed state to Down: Failed to create symlink '/etc/libvirt/qemu/networks/autostart/vdsm-production.xml' to '/etc/libvirt/qemu/networks/vdsm-production.xml': File exists (code=1) (vm:1682)

2018-08-16 10:15:39,277+1000 INFO  (vm/2e6bb483) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') Stopping connection (guestagent:438)

3. But migration finishes and VM runs:

Libvirt event saying the nigration finished and VM runs:

2018-08-16 10:15:48,621+1000 INFO  (libvirt/events) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') CPU running: onResume (vm:6157)
2018-08-16 10:15:48,635+1000 INFO  (libvirt/events) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') CPU running: onResume (vm:6157)

4. Destroy is called

2018-08-16 10:15:53,729+1000 INFO  (jsonrpc/0) [api.virt] START destroy(gracefulAttempts=1) from=::ffff:,57282, vmId=2e6bb483-ff14-4743-8fc1-dcd41d644f15 (api:46)

2018-08-16 10:15:53,730+1000 INFO  (jsonrpc/0) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') Release VM resources (vm:5237)

2018-08-16 10:15:53,730+1000 WARN  (jsonrpc/0) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') trying to set state to Powering down when already Down (vm:606)

2018-08-16 10:15:53,730+1000 INFO  (jsonrpc/0) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') Stopping connection (guestagent:438)

5. VM is still running hours later

$ cat date 
Thu Aug 16 11:48:38 AEST 2018

$ grep 2e6bb483-ff14-4743-8fc1-dcd41d644f15 ps | wc -l

$ cat sos_commands/virsh/virsh_-r_list_--all  | grep NAS01 | wc -l

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

Actual results:
VDSM does not report a VM that is Up

Expected results:
VDSM kills the VM or report it as Up. Avoid split brain.

Comment 2 Michal Skrivanek 2018-08-16 12:35:29 UTC
do you have logs from teh source host? The source host should have cancelled the migration on seeing this error on destination. There's 9 seconds between teh error and successful migration so it shouldn't be a race

Comment 3 Michal Skrivanek 2018-08-17 04:32:19 UTC
Also, can anyone take a look at the underlying networking error? Dan?

Comment 4 Germano Veit Michel 2018-08-17 04:35:43 UTC
(In reply to Michal Skrivanek from comment #3)
> Also, can anyone take a look at the underlying networking error? Dan?

Michal, that is this: BZ1598781.

Btw, I just requested the sosreport for the source host. Will upload the logs once I get them.

Comment 5 Germano Veit Michel 2018-08-17 05:10:47 UTC
Looks like the source did not notice the error.

2018-08-16 10:15:48,430+1000 INFO  (libvirt/events) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') CPU stopped: onSuspend (vm:6157)                                                   
2018-08-16 10:15:49,169+1000 INFO  (migsrc/2e6bb483) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') migration took 12 seconds to complete (migration:514)                             
2018-08-16 10:15:49,170+1000 INFO  (migsrc/2e6bb483) [virt.vm] (vmId='2e6bb483-ff14-4743-8fc1-dcd41d644f15') Changed state to Down: Migration succeeded (code=4) (vm:1682)    

Attaching the logs...

Comment 7 Michal Skrivanek 2018-08-17 05:32:38 UTC
ok, no need to bother Dan then. Thanks

Comment 8 Michal Skrivanek 2018-08-17 07:36:19 UTC
yeah, it seems we do not wait for initialization failures on destination vm creation and return success to the source. When this happens fast before we start the actual migration from source there's no domain to destroy and then the libvirt migration creates one we do not track and completes migration

We should probably wait a bit longer in case of migrationCreate to return success only once we start waiting for the incoming migration, in waitForMigrationDestinationPrepare.
I would move self._pathsPreparedEvent.set() a bit later, after devices initialization (and rename it, it's not used for anything else than migration synchronization)

Comment 9 Liran Rotenberg 2018-09-12 07:49:43 UTC
I couldn't reproduce this bug.
I tried to get the same error and succeed using hwrng device and setting on the destination host directory: /etc/udev/rules.d immutable (chattr +i).
Although I do get the same errors, the split-brain didn't occur to me (with and without Milan's patch).
No regression about migration VMs is noticeable regarding this patch.

Comment 10 Martin Tessun 2018-09-12 11:48:35 UTC
As we cannot reproduce the issue, the fix is QAed for Sanity only. In case the issue happens again, please reopen this BZ or open a new one.

Comment 13 Daniel Gur 2019-08-28 13:13:15 UTC

Comment 14 Daniel Gur 2019-08-28 13:17:27 UTC

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