Bug 1397077

Description of problem:

VM fails to start after changing IDE disks boot order

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

rhevm-backend-3.4.4-2.2.el6ev.noarch

How reproducible:


Steps to Reproduce:
1. Create new VM with IDE disk, verify it starts
2. Add second IDE disk
3. Turn off bootable flag from 1st disk, make 2nd disk bootable
4. Start the VM

Actual results:

VM fails to start,

2015-01-28 15:47:40,801 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-4-thread-30) Correlation ID: 846da54, Job ID: 66a0ed9b-c7c7-4822-b6f8-b89b56387d12, Call Stack: null, Custom Event ID: -1, Message: Failed to run VM fed2 on Host 10.xx.xx.xx.
2015-01-28 15:47:40,888 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-4-thread-30) Lock Acquired to object EngineLock [exclusiveLocks= key: 35f3b562-cb69-4ee1-8b47-47256520182b value: VM
, sharedLocks= ]
2015-01-28 15:47:40,902 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (org.ovirt.thread.pool-4-thread-30) START, IsVmDuringInitiatingVDSCommand( vmId = 35f3b562-cb69-4ee1-8b47-47256520182b), log id: 3107c06
2015-01-28 15:47:40,902 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (org.ovirt.thread.pool-4-thread-30) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 3107c06
2015-01-28 15:47:40,908 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-4-thread-30) CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,SCHEDULING_ALL_HOSTS_FILTERED_OUT


Expected results:

VM starts

Additional info:

This comment was originaly posted by akotov

this might be a libvirt issue, i was able to reproduce this locally  using the steps described, and this is what i got:
engine send to vdsm create with 3 ide devices:
1 - cdrom, with address (assigned by libvirt from previous run)
2 - disk with address (assigned by libvirt from previous run)
3 - disk without address (the new disk) but with request to be boot (boot_order=1)

<disk device="cdrom" snapshot="no" type="file">
    <address bus="1" controller="0" target="0" type="drive" unit="0"/>
    <source file="" startupPolicy="optional"/>
    <target bus="ide" dev="hdc"/>
    <readonly/>
    <serial/>
</disk>
<disk device="disk" snapshot="no" type="file">
    <source file="/rhev/data-center/.../..."/>
    <target bus="ide" dev="hda"/>
    <serial>483d2327-84bb-4de6-90a9-d282d5237ae1</serial>
    <boot order="1"/>
    <driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
</disk>
<disk device="disk" snapshot="no" type="file">
    <address bus="0" controller="0" target="0" type="drive" unit="0"/>
    <source file="/rhev/data-center/.../..."/>
    <target bus="ide" dev="hdb"/>
    <serial>901e7fe4-f479-4c9c-871e-d18ac1317cad</serial>
    <driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
</disk>

this results with
Thread-97773::ERROR::2015-02-22 18:26:41,923::vm::2331::vm.Vm::(_startUnderlyingVm) vmId=`517dce2c-f140-4079-bf61-e7eb116887a1`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/virt/vm.py", line 2271, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/virt/vm.py", line 3335, in _run
    self._connection.createXML(domxml, flags),
  File "/usr/lib/python2.6/site-packages/vdsm/libvirtconnection.py", line 111, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2665, in createXML
    if ret is None:raise libvirtError('virDomainCreateXML() failed', conn=self)
libvirtError: internal error process exited while connecting to monitor: qemu-kvm: -drive file=/rhev/data-center/00000002-0002-0002-0002-00000000033d/f23b9542-85ac-4957-84f4-a8ed99154502/images/901e7fe4-f479-4c9c-871e-d18ac1317cad/b7e35ad0-e7f8-4958-a44d-495fa19725e2,if=none,id=drive-ide0-0-0,format=raw,serial=901e7fe4-f479-4c9c-871e-d18ac1317cad,cache=none,werror=stop,rerror=stop,aio=threads: Duplicate ID 'drive-ide0-0-0' for drive

the error above refer to the older disk.
i don't think that the engine should have cleared the first disk address because like to have stable addresses between boot cycles..

Michal what do you think?

This comment was originaly posted by ofrenkel

looks like libvirt bug in disk assignment?

This comment was originaly posted by michal.skrivanek

...
    <address bus="0" controller="0" target="0" type="drive" unit="0"/>
    <source file="/rhev/data-center/.../..."/>
    <target bus="ide" dev="hdb"/>
...

This doesn't make any sense. The address is for hda while target is specified as hdb. If you then try to add an hda disk, libvirt will try to assign it the right address, which is currently occupied by this second disk. Whoever changed the target of the former hda to hdb should have also changed the address (or alternatively, should have removed it).

This comment was originaly posted by jdenemar

Could you attach the original domain XML and the XML vdsm generated after changing the boot order?

This comment was originaly posted by jdenemar

I don't have the reproducer anymore, as i can't keep them for months.

This comment was originaly posted by akotov

Omer, do you have the domain xmls from the first and second runs?

This comment was originaly posted by michal.skrivanek

Let's hope VDSM guys can provide the XMLs then. So far looking at the only XML we got here (comment 2) the bug would be in VDSM which provided wrong XML.

This comment was originaly posted by jdenemar

Created attachment 1000437 [details]
engine log of the scenario

This comment was originaly posted by ofrenkel

Created attachment 1000439 [details]
vdsm log

This comment was originaly posted by ofrenkel

attached engine and vdsm log of the scenario, please let me know if anything else is needed
vm name: ideVm
vm id: 106acd37-f29b-468b-aa86-99db62c95070

first run on 2015-03-11 15:09:35
single ide disk, and ide cd-rom

after this run, the engine db has:
engine=> select device,is_managed,boot_order,address from vm_device where vm_id in (select vm_guid from vm_static where vm_name ilike 'ideVm') and type='disk';
 device | is_managed | boot_order |                       address                       
--------+------------+------------+-----------------------------------------------------
 disk     | t                 |          1 | {bus=0, controller=0, type=drive, target=0, unit=0}
 cdrom  | t                |          0 | {bus=1, controller=0, type=drive, target=0, unit=0}


after adding another disk and setting it to be bootable
engine=> select device,is_managed,boot_order,address from vm_device where vm_id in (select vm_guid from vm_static where vm_name ilike 'ideVm') and type='disk';
 device | is_managed | boot_order |                       address                       
--------+------------+------------+-----------------------------------------------------
 disk   | t              |          0       | {bus=0, controller=0, type=drive, target=0, unit=0}
 disk   | t              |          1       | 
 cdrom  | t           |          0       | {bus=1, controller=0, type=drive, target=0, unit=0}


second run (attempt) time: 2015-03-11 15:18:16

This comment was originaly posted by ofrenkel

Thanks, comment 5 is correct according to the vdsm.log. It seems the original hda disk was renamed as hdb but its address was left untouched and so it conflicts with the automatically assigned address of the new hda disk. VDSM should either add hdb without changing hda or change or even remove the address of the original hda when it renames it to hdb.

This comment was originaly posted by jdenemar

yep. Taking back, I suspect normalizeDrivesIndices and related stuff not taking into account the existing drives, hence flagging storage

This comment was originaly posted by michal.skrivanek

*** Bug 1313406 has been marked as a duplicate of this bug. ***

This comment was originaly posted by michal.skrivanek

oVirt 4.0 Alpha has been released, moving to oVirt 4.0 Beta target.

This comment was originaly posted by ydary

Tested with the following code:
----------------------------------------
rhevm-4.0.5-0.1.el7ev.noarch
vdsm-4.18.15-1.el7ev.x86_64

Tested with the following scenario:

Steps to Reproduce:
1. Create new VM with IDE disk, verify it starts
2. Add second IDE disk
3. Turn off bootable flag from 1st disk, make 2nd disk bootable
4. Start the VM - Now starts successfully



Actual results:
The VM now starts successfully

Expected results:



Moving to VERIFIED!

This comment was originaly posted by kgoldbla

4.0.5 has been released, closing.

4.0.5 vdsm errata:
https://access.redhat.com/errata/RHBA-2016:2787

4.0.5-1 vdsm errata:
https://access.redhat.com/errata/RHBA-2016:2818

So, I guess, it is somewhere in there.
4.0.5-1 to be on the safe side.