Bug 1434105 - Live storage migration failed
Summary: Live storage migration failed
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 4.1.1.4
Hardware: x86_64
OS: Linux
unspecified
high vote
Target Milestone: ovirt-4.3.0
: ---
Assignee: Benny Zlotnik
QA Contact: SATHEESARAN
URL:
Whiteboard:
: 1440198 (view as bug list)
Depends On: 1312909
Blocks: Gluster-HC-2 1433896
TreeView+ depends on / blocked
 
Reported: 2017-03-20 17:49 UTC by SATHEESARAN
Modified: 2018-07-02 08:51 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-07-02 08:51:29 UTC
oVirt Team: Storage
amureini: ovirt-4.3?
sasundar: planning_ack?
sasundar: devel_ack?
sasundar: testing_ack?


Attachments (Terms of Use)
compressed archived vdsm.log (586.60 KB, application/x-gzip)
2017-03-20 18:10 UTC, SATHEESARAN
no flags Details
compressed archived engine.log (341.94 KB, application/x-gzip)
2017-03-20 18:11 UTC, SATHEESARAN
no flags Details
vdsm.log from host6 which ran the VM (644.23 KB, application/x-xz)
2017-03-21 10:32 UTC, SATHEESARAN
no flags Details

Description SATHEESARAN 2017-03-20 17:49:48 UTC
Description of problem:
------------------------
I have 2 glusterfs data domain backed with sharded replica 3 gluster volumes ( Domain_1 and domain_3 ). I had a VM with its disk on Domain_1. When tried to move the disk ( with the VM active ), from one domain ( Domain_1 ) to another domain ( Domain_3), I observed an error while performing live storage migration

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

How reproducible:
-----------------
Always

Steps to Reproduce:
--------------------
1. Create 2 storage glusterfs data domain backed with sharded replica 3 gluster volumes
2. Create a VM with its root disk from domain_1
3. Install the VM with OS and perform some I/O inside the VM
4. Migrate the disk from one domain to another

Actual results:
---------------
live storage migration failed
The events says this - "User admin@internal-authz have failed to move disk set2_appvm51_Disk1 to domain Domain_3."

Expected results:
------------------
Disk should get migrated to another domain successfully

Comment 1 SATHEESARAN 2017-03-20 18:10:44 UTC
Created attachment 1264818 [details]
compressed archived vdsm.log

Comment 2 SATHEESARAN 2017-03-20 18:11:37 UTC
Created attachment 1264819 [details]
compressed archived engine.log

Comment 3 SATHEESARAN 2017-03-21 10:31:45 UTC
I could see that the VM was running on host6 and I see the following errors with vdsm.log on host6

# xzgrep ERROR /var/log/vdsm/vdsm.log.1.xz 
2017-03-20 08:54:51,213+0530 ERROR (monitor/1025388) [storage.Monitor] Error checking domain 10253882-040a-4f28-a6b6-3c2015fb7594 (monitor:426)
2017-03-20 08:54:51,250+0530 ERROR (check/loop) [storage.Monitor] Error checking path /rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-a6b6-3c2015fb7594/dom_md/metadata (monitor:485)
2017-03-20 08:54:55,631+0530 ERROR (check/loop) [storage.Monitor] Error checking path /rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-a6b6-3c2015fb7594/dom_md/metadata (monitor:485)
2017-03-20 08:55:01,224+0530 ERROR (monitor/1025388) [storage.Monitor] Error checking domain 10253882-040a-4f28-a6b6-3c2015fb7594 (monitor:426)
2017-03-20 18:58:52,706+0530 ERROR (jsonrpc/3) [virt.vm] (vmId='226433a3-4a34-46d6-91b6-2a679c394ec9') Replication job unfinished (drive: 'sda', srcDisk: {u'device': u'disk', u'poolID': u'00000001-0001-0001-0001-000000000311', u'volumeID': u'80c9f20c-3dd7-466b-808d-62337f6cc153', u'domainID': u'4828a460-1825-4ba9-b456-64afad078198', u'imageID': u'da3c126e-d848-4b2e-b1fe-eb9c4cf6b04d'}, job: {'end': 5059117056L, 'bandwidth': 0L, 'type': 2, 'cur': 5040308224L}) (vm:3753)
2017-03-20 18:58:53,990+0530 ERROR (jsonrpc/1) [virt.vm] (vmId='226433a3-4a34-46d6-91b6-2a679c394ec9') Replication job unfinished (drive: 'sda', srcDisk: {u'device': u'disk', u'poolID': u'00000001-0001-0001-0001-000000000311', u'volumeID': u'80c9f20c-3dd7-466b-808d-62337f6cc153', u'domainID': u'4828a460-1825-4ba9-b456-64afad078198', u'imageID': u'da3c126e-d848-4b2e-b1fe-eb9c4cf6b04d'}, job: {'end': 5062262784L, 'bandwidth': 0L, 'type': 2, 'cur': 5061869568L}) (vm:3753)
2017-03-20 18:59:00,186+0530 ERROR (jsonrpc/0) [virt.vm] (vmId='226433a3-4a34-46d6-91b6-2a679c394ec9') Live merge failed (job: 140f8b05-293f-4347-a0d1-fcde17df1e38) (vm:4798)

Comment 4 SATHEESARAN 2017-03-21 10:32:28 UTC
Created attachment 1265006 [details]
vdsm.log from host6 which ran the VM

Comment 5 Adam Litke 2017-03-21 14:23:07 UTC
Seeing the following exception in the log.  This seems to indicate a problem on the gluster side.  Can you check to make sure your gluster storage wasn't reporting errors?  I am not really sure where to look for that but something has caused the gluster mount to become disconnected.

2017-03-20 08:54:55,631+0530 ERROR (check/loop) [storage.Monitor] Error checking path /rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-a6b6-3c2015fb7594/dom_md/metadata (monitor:485)
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/monitor.py", line 483, in _pathChecked
    delay = result.delay()
  File "/usr/lib/python2.7/site-packages/vdsm/storage/check.py", line 368, in delay
    raise exception.MiscFileReadException(self.path, self.rc, self.err)
MiscFileReadException: Internal file read failure: (u'/rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-a6b6-3c2015fb7594/dom_md/metadata', 1, bytearray(b"/usr/bin/dd: failed to open \'/rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-a6b6-3c2015fb7594/dom_md/metadata\': Transport endpoint is not connected\n"))

Comment 6 Sahina Bose 2017-03-22 05:15:13 UTC
(In reply to Adam Litke from comment #5)
> Seeing the following exception in the log.  This seems to indicate a problem
> on the gluster side.  Can you check to make sure your gluster storage wasn't
> reporting errors?  I am not really sure where to look for that but something
> has caused the gluster mount to become disconnected.
> 
> 2017-03-20 08:54:55,631+0530 ERROR (check/loop) [storage.Monitor] Error
> checking path
> /rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-a6b6-
> 3c2015fb7594/dom_md/metadata (monitor:485)
> Traceback (most recent call last):
>   File "/usr/share/vdsm/storage/monitor.py", line 483, in _pathChecked
>     delay = result.delay()
>   File "/usr/lib/python2.7/site-packages/vdsm/storage/check.py", line 368,
> in delay
>     raise exception.MiscFileReadException(self.path, self.rc, self.err)
> MiscFileReadException: Internal file read failure:
> (u'/rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-
> a6b6-3c2015fb7594/dom_md/metadata', 1, bytearray(b"/usr/bin/dd: failed to
> open
> \'/rhev/data-center/mnt/glusterSD/10.70.36.73:_engine/10253882-040a-4f28-
> a6b6-3c2015fb7594/dom_md/metadata\': Transport endpoint is not connected\n"))

This error is from the HE gluster volume (HE storage domain). Does that affect the live migration on the other storage domains?

Comment 7 Adam Litke 2017-03-28 18:47:53 UTC
Sahina you are correct.  Those monitoring errors are unrelated.

Comment 8 Adam Litke 2017-03-28 19:12:02 UTC
After further analyzing the engine logs I am concerned that there could be a problem with the engine flow for LiveMigrateDiskCommand.  This command performs the following actions in sequence:

1. CreateImagePlaceholder - Clone the disk structure from the source domain to the destination domain.

2. VmReplicateDiskStart - Instruct qemu to replicate the active volume of the source disk to the active layer of the destination disk and mirror all writes to both the source and destination disks.  This operation is a two phase process.  First, data is copied from the source to the destination.  Once this converges, subsequent writes are sent to both the source and destination simultaneously. 

3. SyncImageGroupData - Sync the contents of source disk's internal volumes to the corresponding destination disk volumes.

--- wait for SyncImageGroupData to complete ---

4. VmReplicateDiskFinish - Instruct qemu to pivot to the destination disk and suspend write mirroring on the source disk.  This only works if step 2 has converged to the mirroring phase and step 3 is also complete.


What appears to be happening in the attached logs is that due to high I/O, step 2  is unable to converge before step 4 is executed.  This is usually not a problem since step 3 can take a relatively long time and with low I/O step 2 will converge quickly.

The following log entry confirms that step 2 did not converge (cur != end):

2017-03-20 18:58:52,706+0530 ERROR (jsonrpc/3) [virt.vm] (vmId='226433a3-4a34-46d6-91b6-2a679c394ec9') Replication job unfinished (drive: 'sda', srcDisk: {u'device': u'disk', u'poolID': u'00000001-0001-0001-0001-000000000311', u'volumeID': u'80c9f20c-3dd7-466b-808d-62337f6cc153', u'domainID': u'4828a460-1825-4ba9-b456-64afad078198', u'imageID': u'da3c126e-d848-4b2e-b1fe-eb9c4cf6b04d'}, job: {'end': 5059117056L, 'bandwidth': 0L, 'type': 2, 'cur': 5040308224L}) (vm:3753)


I believe the engine needs to add an additional step before VmReplicateDiskFinish which checks that the replication has converged.  Alternatively, we could wait and retry VmReplicateDiskFinish a number of times before failing the entire operation.

Comment 9 Adam Litke 2017-03-28 19:36:00 UTC
I just talked to Liron and this is a known issue and already has an assigned bug.

*** This bug has been marked as a duplicate of bug 1312909 ***

Comment 12 Sahina Bose 2017-04-17 07:11:57 UTC
*** Bug 1440198 has been marked as a duplicate of this bug. ***

Comment 14 Tal Nisan 2018-07-02 08:51:29 UTC
The whole LSM flow was changed, please reopen if the issue still exists.


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