Bug 1489361

+++ This bug was initially created as a clone of Bug #1481688 +++

Description of problem:
Storage migration is failing in VmReplicateDiskFinishVDSCommand with error Failed to change disk image 

I saw this error mainly in out automation tests and I can't reproduce it locally, but the problem was found in few tests and not only one. 

Version-Release number of selected component (if applicable):
ovirt-engine-4.2.0-0.0.master.20170801132145.git3e12cf0.el7.centos.noarch
vdsm-4.20.2-60.git06231e5.el7.centos.x86_64

How reproducible:
~50% maybe more 

Steps to Reproduce:
1. not really sure, just migrate disks (cold migration or live it doesn't matter) between storage domains.

Actual results:
In some cases the migration fails with the error Failed to change disk image

Expected results:
migration should end successfully 

Additional info:

engine.log

2017-08-12 10:39:26,349+03 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler9) [disks_syncAction_764a9c1c-f5bf-4ca5] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand' return value 'StatusOnlyReturn [status=Status [code=41, message=Failed to change disk image]]'

2017-08-12 10:39:27,546+03 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler1) [disks_syncAction_764a9c1c-f5bf-4ca5] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_2 command VmReplicateDiskFinishVDS failed: Drive replication error

2017-08-12 10:39:27,546+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand] (DefaultQuartzScheduler1) [disks_syncAction_764a9c1c-f5bf-4ca5] Command 'VmReplicateDiskFinishVDSCommand(HostName = host_mixed_2, VmReplicateDiskParameters:{hostId='824bbda7-cfbb-400b-a021-068dc060832f', vmId='f13ca114-d739-43b7-93ca-a97c4a951bc5', storagePoolId='19791d8f-814e-4241-a028-e103c310060a', srcStorageDomainId='e8045448-f2e3-421b-b92e-34f79f2a687d', targetStorageDomainId='e8045448-f2e3-421b-b92e-34f79f2a687d', imageGroupId='6d61ec9f-5a0a-4840-af54-04dd27762ad8', imageId='5a1fcef4-81ff-42e3-83be-33e013245673'})' execution failed: VDSGenericException: VDSErrorException: Failed to VmReplicateDiskFinishVDS, error = Drive replication error, code = 55

--- Additional comment from Lilach Zitnitski on 2017-08-15 09:00 EDT ---

engine and vdsm logs

--- Additional comment from Allon Mureinik on 2017-08-17 08:17:53 EDT ---

From VDSM's log:

017-08-12 10:39:26,109+0300 ERROR (jsonrpc/4) [virt.vm] (vmId='f13ca114-d739-43b7-93ca-a97c4a951bc5') Unable to stop the replication for the drive: vda (vm:4295)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4292, in diskReplicateFinish
    self._dom.blockJobAbort(drive.name, blockJobFlags)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 125, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 586, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 743, in blockJobAbort
    if ret == -1: raise libvirtError ('virDomainBlockJobAbort() failed', dom=self)

Daniel/Nir can you take a look?

--- Additional comment from Daniel Erez on 2017-08-17 08:31:46 EDT ---

@Lilach - can you please attach qemu and libvirt logs as well?

--- Additional comment from Lilach Zitnitski on 2017-08-20 07:08 EDT ---

Since the first logs were from the automation tests and I couldn't get the libvirt and qemu, I reproduced this bug. The new zip contains also new engine, vdsm logs with the libvirt and qemu.

correlationID - disks_syncAction_81a244b3-0f7c-4eeb
error in new engine log at 17:39:15

--- Additional comment from Daniel Erez on 2017-08-20 14:19:39 EDT ---

According to the log[1], there's a KeyError of missing 'protocol' key during replication start phase. Seems the cause is 'diskType': 'network', i.e. the disk has a path to a file domain, but is marked as a network disk.

@Sahina - Could it be related to https://gerrit.ovirt.org/#/c/79745/

@Lilach - Do you use GlusterFS for any of the tests?

[1]
2017-08-17 17:39:15,611+0300 ERROR (jsonrpc/1) [virt.vm] (vmId='d3f3c5c5-a337-45f6-b30c-26e2fc739951') Unable to start replication for vda to {'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'volumeInfo': {'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/0e8861ca-7a38-4bd0-8f04-b2344661b432', 'volType': 'path'}, 'format': 'cow', 'poolID': '30312c9a-2bff-4ebe-9335-120b48e52d91', 'device': 'disk', 'propagateErrors': 'off', 'diskType': 'network', 'cache': 'none', 'volumeID': '0e8861ca-7a38-4bd0-8f04-b2344661b432', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867', 'volumeChain': [{'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'leaseOffset': 116391936, 'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/0e8861ca-7a38-4bd0-8f04-b2344661b432', 'volumeID': '0e8861ca-7a38-4bd0-8f04-b2344661b432', 'leasePath': '/dev/00d54fa8-ac31-4190-addb-0085335e7272/leases', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}, {'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'leaseOffset': 114294784, 'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/b8bd4c59-ac36-4847-82ce-d09fc3552146', 'volumeID': 'b8bd4c59-ac36-4847-82ce-d09fc3552146', 'leasePath': '/dev/00d54fa8-ac31-4190-addb-0085335e7272/leases', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}, {'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'leaseOffset': 109051904, 'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/d5508161-5232-4453-b81d-4a65f1240d38', 'volumeID': 'd5508161-5232-4453-b81d-4a65f1240d38', 'leasePath': '/dev/00d54fa8-ac31-4190-addb-0085335e7272/leases', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}]} (vm:4166)
KeyError: 'protocol'

--- Additional comment from Lilach Zitnitski on 2017-08-21 02:44:05 EDT ---

Daniel, the first logs are not from tests using GlusterFS, the new logs are. I will try to re-run again the tests on iscsi and nfs only.

--- Additional comment from Allon Mureinik on 2017-08-21 06:52:52 EDT ---

(In reply to Daniel Erez from comment #5)
> According to the log[1], there's a KeyError of missing 'protocol' key during
> replication start phase. Seems the cause is 'diskType': 'network', i.e. the
> disk has a path to a file domain, but is marked as a network disk.
> 
> @Sahina - Could it be related to https://gerrit.ovirt.org/#/c/79745/
Denis, wasn't there a caveat about LSM and libgfapi?

--- Additional comment from Denis Chaplygin on 2017-08-21 06:58:11 EDT ---

There was, but on lower level - libvirt still doesn't support block copy to the network disks. This one seems to be different issue

--- Additional comment from Daniel Erez on 2017-08-21 07:31:05 EDT ---

(In reply to Denis Chaplygin from comment #8)
> There was, but on lower level - libvirt still doesn't support block copy to
> the network disks. This one seems to be different issue

@Denis - so why it's not disabled in the engine for now? Currently, passing diskType as network for image domain throws a KeyError in vdsm (as explained in comment 5). I.e. not sure I'm following the change introduced in https://gerrit.ovirt.org/#/c/79745/4/backend/manager/modules/bll/src/main/java/org/ovirt/engine/core/bll/storage/lsm/LiveMigrateDiskCommand.java

--- Additional comment from Denis Chaplygin on 2017-08-21 08:49:32 EDT ---

I'm afraid hat issue was introduced later and described in [1]

Anyway, libgfapi is by default disabled everywhere, except 4.2 


[1] https://bugzilla.redhat.com/show_bug.cgi?id=1481165

--- Additional comment from Daniel Erez on 2017-08-21 09:00:49 EDT ---

(In reply to Denis Chaplygin from comment #10)
> I'm afraid hat issue was introduced later and described in [1]
> 
> Anyway, libgfapi is by default disabled everywhere, except 4.2 
> 
> 
> [1] https://bugzilla.redhat.com/show_bug.cgi?id=1481165

Thanks Denis!

@Francesco - did you test storage live migration flow as part of bug 1481165 ?

--- Additional comment from Francesco Romani on 2017-08-21 09:27:23 EDT ---

(In reply to Daniel Erez from comment #11)
> (In reply to Denis Chaplygin from comment #10)
> > I'm afraid hat issue was introduced later and described in [1]
> > 
> > Anyway, libgfapi is by default disabled everywhere, except 4.2 
> > 
> > 
> > [1] https://bugzilla.redhat.com/show_bug.cgi?id=1481165
> 
> Thanks Denis!
> 
> @Francesco - did you test storage live migration flow as part of bug 1481165
> ?

I am testing the LSM flow in general. We have one more fix in this area: https://gerrit.ovirt.org/#/c/80831/5

--- Additional comment from Francesco Romani on 2017-08-21 13:09:34 EDT ---

(In reply to Francesco Romani from comment #12)
> (In reply to Daniel Erez from comment #11)
> > (In reply to Denis Chaplygin from comment #10)
> > > I'm afraid hat issue was introduced later and described in [1]
> > > 
> > > Anyway, libgfapi is by default disabled everywhere, except 4.2 
> > > 
> > > 
> > > [1] https://bugzilla.redhat.com/show_bug.cgi?id=1481165
> > 
> > Thanks Denis!
> > 
> > @Francesco - did you test storage live migration flow as part of bug 1481165
> > ?
> 
> I am testing the LSM flow in general. We have one more fix in this area:
> https://gerrit.ovirt.org/#/c/80831/5

To be clear, I didn't test LSM on glusterfs, only VM start/stop (IIUC it isn't supported and https://bugzilla.redhat.com/show_bug.cgi?id=1481688#c7 seems to confirm that)

Please note that from what I've seen here from the logs, the fix I'm working on [1] should not affect this bz.

[1] 80831 is about recovery, if Vdsm doesn't crash there is no issue.

--- Additional comment from Daniel Erez on 2017-08-21 13:44:56 EDT ---

(In reply to Francesco Romani from comment #13)
> (In reply to Francesco Romani from comment #12)
> > (In reply to Daniel Erez from comment #11)
> > > (In reply to Denis Chaplygin from comment #10)
> > > > I'm afraid hat issue was introduced later and described in [1]
> > > > 
> > > > Anyway, libgfapi is by default disabled everywhere, except 4.2 
> > > > 
> > > > 
> > > > [1] https://bugzilla.redhat.com/show_bug.cgi?id=1481165
> > > 
> > > Thanks Denis!
> > > 
> > > @Francesco - did you test storage live migration flow as part of bug 1481165
> > > ?
> > 
> > I am testing the LSM flow in general. We have one more fix in this area:
> > https://gerrit.ovirt.org/#/c/80831/5
> 
> To be clear, I didn't test LSM on glusterfs, only VM start/stop (IIUC it
> isn't supported and https://bugzilla.redhat.com/show_bug.cgi?id=1481688#c7
> seems to confirm that)
> 
> Please note that from what I've seen here from the logs, the fix I'm working
> on [1] should not affect this bz.
> 
> [1] 80831 is about recovery, if Vdsm doesn't crash there is no issue.

@Lilach - so we have two separate issues:
* LSM on glusterfs - IIUC, unsupported yet, so can be removed from tests.
* LSM on nfs - can you please attach full logs of the tests?

--- Additional comment from Nir Soffer on 2017-08-21 14:02:59 EDT ---

(In reply to Daniel Erez from comment #14)
> @Lilach - so we have two separate issues:
> * LSM on glusterfs - IIUC, unsupported yet, so can be removed from tests.

LSM on glusterfs is supported.

> * LSM on nfs - can you please attach full logs of the tests?

--- Additional comment from Daniel Erez on 2017-08-21 14:28:54 EDT ---

(In reply to Nir Soffer from comment #15)
> (In reply to Daniel Erez from comment #14)
> > @Lilach - so we have two separate issues:
> > * LSM on glusterfs - IIUC, unsupported yet, so can be removed from tests.
> 
> LSM on glusterfs is supported.

@Nir/Denis - I'm not following then:
1. According to https://bugzilla.redhat.com/show_bug.cgi?id=1481688#c8
I understand that we don't support LSM yet?
2. If we do support, why do we get a KeyError in start replication? and why do we set diskType to network?

[1] [1]
2017-08-17 17:39:15,611+0300 ERROR (jsonrpc/1) [virt.vm] (vmId='d3f3c5c5-a337-45f6-b30c-26e2fc739951') Unable to start replication for vda to {'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'volumeInfo': {'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/0e8861ca-7a38-4bd0-8f04-b2344661b432', 'volType': 'path'}, 'format': 'cow', 'poolID': '30312c9a-2bff-4ebe-9335-120b48e52d91', 'device': 'disk', 'propagateErrors': 'off', 'diskType': 'network', 'cache': 'none', 'volumeID': '0e8861ca-7a38-4bd0-8f04-b2344661b432', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867', 'volumeChain': [{'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'leaseOffset': 116391936, 'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/0e8861ca-7a38-4bd0-8f04-b2344661b432', 'volumeID': '0e8861ca-7a38-4bd0-8f04-b2344661b432', 'leasePath': '/dev/00d54fa8-ac31-4190-addb-0085335e7272/leases', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}, {'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'leaseOffset': 114294784, 'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/b8bd4c59-ac36-4847-82ce-d09fc3552146', 'volumeID': 'b8bd4c59-ac36-4847-82ce-d09fc3552146', 'leasePath': '/dev/00d54fa8-ac31-4190-addb-0085335e7272/leases', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}, {'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'leaseOffset': 109051904, 'path': '/rhev/data-center/mnt/blockSD/00d54fa8-ac31-4190-addb-0085335e7272/images/81738b6d-1693-46e6-b470-df38353ac867/d5508161-5232-4453-b81d-4a65f1240d38', 'volumeID': 'd5508161-5232-4453-b81d-4a65f1240d38', 'leasePath': '/dev/00d54fa8-ac31-4190-addb-0085335e7272/leases', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}]} (vm:4166)
KeyError: 'protocol'


> 
> > * LSM on nfs - can you please attach full logs of the tests?

--- Additional comment from Nir Soffer on 2017-08-21 14:42:47 EDT ---

Regarding comment 7 - the error is:

Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4149, in diskReplicateStart
    replica['path'] = self.cif.prepareVolumePath(replica)
  File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 345, in prepareVolumePath
    volPath = self._prepare_network_drive(drive, res)
  File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 632, in _prepare_network_drive
    drive['protocol'] = volinfo['protocol']
KeyError: 'protocol'

_prepare_netwrok_drive() was called with a non network drive, the error
is expected when sending invalid data to vdsm.

The bad request was:

# local_vdsm.log
2017-08-17 17:39:11,428+0300 INFO  (jsonrpc/1) [vdsm.api] START diskReplicateStart(srcDisk={'device': 'disk', 'poolID': '30312c9a-2bff-4ebe-9335-120b48e52d91', 'volumeID': '0e8861ca-7a38-4bd
0-8f04-b2344661b432', 'domainID': '25893777-25bb-4085-ac34-f0e88d4aa10f', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}, dstDisk={'domainID': '00d54fa8-ac31-4190-addb-0085335e7272', 'volumeID': '0e8861ca-7a38-4bd0-8f04-b2344661b432', 'diskType': 'network', 'poolID': '30312c9a-2bff-4ebe-9335-120b48e52d91', 'device': 'disk', 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}
) from=::ffff:10.35.69.27,55492, flow_id=disks_syncAction_81a244b3-0f7c-4eeb (api:46)

The destination storage domain is a block storage domain based on:

2017-08-17 17:04:56,686+0300 INFO  (monitor/00d54fa) [storage.LVM] Refreshing lvs: vg=00d54fa8-ac31-4190-addb-0085335e7272 lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1294)

The root cause is engine, sending networkDisk for block based disk.

Network disk should never be sent to LSM destination disk, even for gluster
disk, not in 4.1 and not in 4.2, since libvirt does not support yet LSM to 
network disk.

Denis check this?

--- Additional comment from Nir Soffer on 2017-08-21 14:47:03 EDT ---

(In reply to Daniel Erez from comment #16)
> (In reply to Nir Soffer from comment #15)
> > LSM on glusterfs is supported.
> 
> @Nir/Denis - I'm not following then:
> 1. According to https://bugzilla.redhat.com/show_bug.cgi?id=1481688#c8
> I understand that we don't support LSM yet?

We do support LSM to gluster, but not using network disk. If the source disk is
gluster disk using libgfapi (networkDisk=True, protocol="gluster"), LSM will
convert to the disk to a file based gluster disk, degrading performance - but
the operation will complete. Until libvirt is fixed to do blockCopy to network
disk don't have a choice.

> 2. If we do support, why do we get a KeyError in start replication? and why
> do we set diskType to network?

This is engine bug.

--- Additional comment from Lilach Zitnitski on 2017-08-22 02:39:06 EDT ---

(In reply to Daniel Erez from comment #14)
> @Lilach - so we have two separate issues:
> * LSM on glusterfs - IIUC, unsupported yet, so can be removed from tests.
> * LSM on nfs - can you please attach full logs of the tests?

For now I failed to reproduce this errors with NFS/ISCSI storage domains, only with GlusterFS on my local environment. 
The errors I saw on NFS/ISCSI were from the automation tests, so if I'll see them again on the same environment I'll attach new logs.

--- Additional comment from Daniel Erez on 2017-08-22 03:04:49 EDT ---

(In reply to Nir Soffer from comment #17)
> Regarding comment 7 - the error is:
> 
> Traceback (most recent call last):
>   File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4149, in
> diskReplicateStart
>     replica['path'] = self.cif.prepareVolumePath(replica)
>   File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 345, in
> prepareVolumePath
>     volPath = self._prepare_network_drive(drive, res)
>   File "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 632, in
> _prepare_network_drive
>     drive['protocol'] = volinfo['protocol']
> KeyError: 'protocol'
> 
> _prepare_netwrok_drive() was called with a non network drive, the error
> is expected when sending invalid data to vdsm.
> 
> The bad request was:
> 
> # local_vdsm.log
> 2017-08-17 17:39:11,428+0300 INFO  (jsonrpc/1) [vdsm.api] START
> diskReplicateStart(srcDisk={'device': 'disk', 'poolID':
> '30312c9a-2bff-4ebe-9335-120b48e52d91', 'volumeID': '0e8861ca-7a38-4bd
> 0-8f04-b2344661b432', 'domainID': '25893777-25bb-4085-ac34-f0e88d4aa10f',
> 'imageID': '81738b6d-1693-46e6-b470-df38353ac867'}, dstDisk={'domainID':
> '00d54fa8-ac31-4190-addb-0085335e7272', 'volumeID':
> '0e8861ca-7a38-4bd0-8f04-b2344661b432', 'diskType': 'network', 'poolID':
> '30312c9a-2bff-4ebe-9335-120b48e52d91', 'device': 'disk', 'imageID':
> '81738b6d-1693-46e6-b470-df38353ac867'}
> ) from=::ffff:10.35.69.27,55492, flow_id=disks_syncAction_81a244b3-0f7c-4eeb
> (api:46)
> 
> The destination storage domain is a block storage domain based on:
> 
> 2017-08-17 17:04:56,686+0300 INFO  (monitor/00d54fa) [storage.LVM]
> Refreshing lvs: vg=00d54fa8-ac31-4190-addb-0085335e7272 lvs=['metadata',
> 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1294)
> 
> The root cause is engine, sending networkDisk for block based disk.
> 
> Network disk should never be sent to LSM destination disk, even for gluster
> disk, not in 4.1 and not in 4.2, since libvirt does not support yet LSM to 
> network disk.
> 
> Denis check this?

--- Additional comment from Daniel Erez on 2017-08-27 05:16:07 EDT ---

As per comment 17, diskType 'Network' should not be sent to LSM destination disk. 
Moving to Gluster oVirt team, as the issue affects only Gluster and was introduced by https://gerrit.ovirt.org/#/c/79745/

--- Additional comment from Sahina Bose on 2017-08-30 01:57:24 EDT ---

If this breaks live storage migration when libgfapi access is not enabled, I think we should target for 4.1.6.
Denis?