Created attachment 1305476 [details]
engine log

Description of problem:
Migration in rhv seem to be broken.

Version-Release number of selected component (if applicable):
RHEL-7.4-20170711.0
rhv-4.1.4-2
vdagent-win-4.1-3

How reproducible:
100%

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

When I tailed the vdsm.log:

2017-07-27 11:04:48,246-0400 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:04:51,199-0400 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:04:51,205-0400 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:04:53,694-0400 INFO  (jsonrpc/2) [vdsm.api] START migrate(params={u'incomingLimit': 2, u'src': u'10.19.168.11', u'dstqemu': u'10.19.168.22', u'autoConverge': u'false', u'tunneled': u'false', u'enableGuestEvents': False, u'dst': u'10.19.168.22:54321', u'vmId': u'7a6531a4-6404-4a34-90b8-7a305a9b257d', u'abortOnError': u'true', u'outgoingLimit': 2, u'compressed': u'false', u'maxBandwidth': 500, u'method': u'online', 'mode': 'remote'}) from=::ffff:10.19.168.41,35206, flow_id=cfccd278-3084-4f81-99c8-f2846a70f541 (api:46)
2017-07-27 11:04:53,698-0400 INFO  (jsonrpc/2) [vdsm.api] FINISH migrate return={'status': {'message': 'Migration in progress', 'code': 0}, 'progress': 0} from=::ffff:10.19.168.41,35206, flow_id=cfccd278-3084-4f81-99c8-f2846a70f541 (api:52)
2017-07-27 11:04:53,698-0400 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call VM.migrate succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:04:54,987-0400 INFO  (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') Creation of destination VM took: 0 seconds (migration:455)
2017-07-27 11:04:54,988-0400 INFO  (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') starting migration to qemu+tls://10.19.168.22/system with miguri tcp://10.19.168.22 (migration:480)
2017-07-27 11:04:55,399-0400 ERROR (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') internal error: Attempt to migrate guest to the same host localhost.localdomain (migration:287)
2017-07-27 11:04:55,632-0400 ERROR (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') Failed to migrate (migration:429)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 411, in run
    self._startUnderlyingMigration(time.time())
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 489, in _startUnderlyingMigration
    self._perform_with_downtime_thread(duri, muri)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 556, in _perform_with_downtime_thread
    self._perform_migration(duri, muri)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 529, in _perform_migration
    self._vm._dom.migrateToURI3(duri, params, flags)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 69, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 123, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 941, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1679, in migrateToURI3
    if ret == -1: raise libvirtError ('virDomainMigrateToURI3() failed', dom=self)
libvirtError: internal error: Attempt to migrate guest to the same host localhost.localdomain
2017-07-27 11:04:57,188-0400 INFO  (periodic/1) [vdsm.api] START repoStats(options=None) from=internal, task_id=2aa534aa-395b-41d0-98be-470a95fff377 (api:46)
2017-07-27 11:04:57,189-0400 INFO  (periodic/1) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00143775', 'lastCheck': '0.3', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00112157', 'lastCheck': '4.3', 'valid': True}} from=internal, task_id=2aa534aa-395b-41d0-98be-470a95fff377 (api:52)
2017-07-27 11:05:02,467-0400 INFO  (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.19.168.41,35206, flow_id=6dcba44, task_id=8aeb25f6-bb3a-4bf5-80c8-a1d52b0cc8f2 (api:46)
2017-07-27 11:05:02,467-0400 INFO  (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00138502', 'lastCheck': '0.3', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00128768', 'lastCheck': '0.0', 'valid': True}} from=::ffff:10.19.168.41,35206, flow_id=6dcba44, task_id=8aeb25f6-bb3a-4bf5-80c8-a1d52b0cc8f2 (api:52)
2017-07-27 11:05:02,478-0400 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2017-07-27 11:05:04,308-0400 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:05:05,395-0400 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getVMFullList succeeded in 0.02 seconds (__init__:539)
2017-07-27 11:05:05,398-0400 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.getMigrationStatus succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:06,215-0400 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:06,221-0400 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:07,528-0400 INFO  (jsonrpc/5) [vdsm.api] START migrate(params={u'incomingLimit': 2, u'src': u'10.19.168.11', u'dstqemu': u'10.19.168.16', u'autoConverge': u'false', u'tunneled': u'false', u'enableGuestEvents': False, u'dst': u'10.19.168.16:54321', u'vmId': u'7a6531a4-6404-4a34-90b8-7a305a9b257d', u'abortOnError': u'true', u'outgoingLimit': 2, u'compressed': u'false', u'maxBandwidth': 500, u'method': u'online', 'mode': 'remote'}) from=::ffff:10.19.168.41,35206, flow_id=3cb11d17 (api:46)
2017-07-27 11:05:07,532-0400 INFO  (jsonrpc/5) [vdsm.api] FINISH migrate return={'status': {'message': 'Migration in progress', 'code': 0}, 'progress': 0} from=::ffff:10.19.168.41,35206, flow_id=3cb11d17 (api:52)
2017-07-27 11:05:07,532-0400 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call VM.migrate succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:08,718-0400 INFO  (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') Creation of destination VM took: 0 seconds (migration:455)
2017-07-27 11:05:08,719-0400 INFO  (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') starting migration to qemu+tls://10.19.168.16/system with miguri tcp://10.19.168.16 (migration:480)
2017-07-27 11:05:10,176-0400 ERROR (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') internal error: Attempt to migrate guest to the same host localhost.localdomain (migration:287)
2017-07-27 11:05:10,352-0400 ERROR (migsrc/7a6531a4) [virt.vm] (vmId='7a6531a4-6404-4a34-90b8-7a305a9b257d') Failed to migrate (migration:429)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 411, in run
    self._startUnderlyingMigration(time.time())
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 489, in _startUnderlyingMigration
    self._perform_with_downtime_thread(duri, muri)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 556, in _perform_with_downtime_thread
    self._perform_migration(duri, muri)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/migration.py", line 529, in _perform_migration
    self._vm._dom.migrateToURI3(duri, params, flags)
  File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 69, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line 123, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 941, in wrapper
    return func(inst, *args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1679, in migrateToURI3
    if ret == -1: raise libvirtError ('virDomainMigrateToURI3() failed', dom=self)
libvirtError: internal error: Attempt to migrate guest to the same host localhost.localdomain
2017-07-27 11:05:12,207-0400 INFO  (periodic/1) [vdsm.api] START repoStats(options=None) from=internal, task_id=347a0c47-a932-4b99-adb7-1ab99414bd51 (api:46)
2017-07-27 11:05:12,208-0400 INFO  (periodic/1) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00125618', 'lastCheck': '0.1', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00128768', 'lastCheck': '9.3', 'valid': True}} from=internal, task_id=347a0c47-a932-4b99-adb7-1ab99414bd51 (api:52)
2017-07-27 11:05:18,661-0400 INFO  (jsonrpc/2) [vdsm.api] START repoStats(options=None) from=::ffff:10.19.168.41,35206, flow_id=76d7efd4, task_id=4262834a-f4a4-4b3d-b3dc-1c32f83c9efe (api:46)
2017-07-27 11:05:18,661-0400 INFO  (jsonrpc/2) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00125618', 'lastCheck': '1.8', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00118194', 'lastCheck': '5.7', 'valid': True}} from=::ffff:10.19.168.41,35206, flow_id=76d7efd4, task_id=4262834a-f4a4-4b3d-b3dc-1c32f83c9efe (api:52)
2017-07-27 11:05:18,671-0400 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:05:20,480-0400 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:20,685-0400 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getVMFullList succeeded in 0.02 seconds (__init__:539)
2017-07-27 11:05:20,688-0400 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call VM.getMigrationStatus succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:21,225-0400 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:21,236-0400 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:27,227-0400 INFO  (periodic/0) [vdsm.api] START repoStats(options=None) from=internal, task_id=1a176e64-65a5-4f41-bf14-09d408038da3 (api:46)
2017-07-27 11:05:27,227-0400 INFO  (periodic/0) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00134676', 'lastCheck': '0.3', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00103665', 'lastCheck': '4.3', 'valid': True}} from=internal, task_id=1a176e64-65a5-4f41-bf14-09d408038da3 (api:52)
2017-07-27 11:05:34,860-0400 INFO  (jsonrpc/0) [vdsm.api] START repoStats(options=None) from=::ffff:10.19.168.41,35206, flow_id=7e769959, task_id=81074fd2-2dbc-4023-be40-69505f3d20c8 (api:46)
2017-07-27 11:05:34,860-0400 INFO  (jsonrpc/0) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00119638', 'lastCheck': '2.7', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00132163', 'lastCheck': '1.9', 'valid': True}} from=::ffff:10.19.168.41,35206, flow_id=7e769959, task_id=81074fd2-2dbc-4023-be40-69505f3d20c8 (api:52)
2017-07-27 11:05:34,871-0400 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:05:35,759-0400 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:05:36,237-0400 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:05:36,252-0400 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:42,236-0400 INFO  (periodic/1) [vdsm.api] START repoStats(options=None) from=internal, task_id=e6cf24ae-cd6b-450f-8d7c-f5e61aee74c6 (api:46)
2017-07-27 11:05:42,236-0400 INFO  (periodic/1) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00133247', 'lastCheck': '0.1', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00132163', 'lastCheck': '9.3', 'valid': True}} from=internal, task_id=e6cf24ae-cd6b-450f-8d7c-f5e61aee74c6 (api:52)
2017-07-27 11:05:42,760-0400 INFO  (periodic/3) [vdsm.api] START getVolumeSize(sdUUID=u'81e26001-f018-4088-83a1-efe1698fa0a9', spUUID=u'00000001-0001-0001-0001-000000000311', imgUUID=u'2e06a1a0-bbc7-4244-8047-88dd2f470d95', volUUID=u'17bdc735-94b6-4a29-9cd0-5fe3b0737dab', options=None) from=internal, task_id=8e5b4d0e-d1ad-45df-b25d-a75514262a22 (api:46)
2017-07-27 11:05:42,760-0400 INFO  (periodic/3) [vdsm.api] FINISH getVolumeSize return={'truesize': '42949672960', 'apparentsize': '42949672960'} from=internal, task_id=8e5b4d0e-d1ad-45df-b25d-a75514262a22 (api:52)
2017-07-27 11:05:50,924-0400 INFO  (jsonrpc/4) [vdsm.api] START repoStats(options=None) from=::ffff:10.19.168.41,35206, flow_id=3227e4ea, task_id=a041d588-b3c0-4e70-84f6-f40adefb2fb0 (api:46)
2017-07-27 11:05:50,925-0400 INFO  (jsonrpc/4) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00133247', 'lastCheck': '4.0', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00121959', 'lastCheck': '8.0', 'valid': True}} from=::ffff:10.19.168.41,35206, flow_id=3227e4ea, task_id=a041d588-b3c0-4e70-84f6-f40adefb2fb0 (api:52)
2017-07-27 11:05:50,936-0400 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:05:51,261-0400 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:51,272-0400 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:51,810-0400 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:05:57,255-0400 INFO  (periodic/3) [vdsm.api] START repoStats(options=None) from=internal, task_id=17eb4f12-f473-481a-ae1d-3d0beb511818 (api:46)
2017-07-27 11:05:57,256-0400 INFO  (periodic/3) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00140294', 'lastCheck': '0.3', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00116667', 'lastCheck': '4.3', 'valid': True}} from=internal, task_id=17eb4f12-f473-481a-ae1d-3d0beb511818 (api:52)
2017-07-27 11:06:06,270-0400 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:06:06,299-0400 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2017-07-27 11:06:06,985-0400 INFO  (jsonrpc/2) [vdsm.api] START repoStats(options=None) from=::ffff:10.19.168.41,35206, flow_id=2a2b2855, task_id=33031e58-05a7-405f-b6c3-f3f3b32f93a3 (api:46)
2017-07-27 11:06:06,986-0400 INFO  (jsonrpc/2) [vdsm.api] FINISH repoStats return={u'81e26001-f018-4088-83a1-efe1698fa0a9': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.0011877', 'lastCheck': '0.1', 'valid': True}, u'70909ad8-63dc-4c8d-9343-9e7574648ee6': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00123938', 'lastCheck': '4.0', 'valid': True}} from=::ffff:10.19.168.41,35206, flow_id=2a2b2855, task_id=33031e58-05a7-405f-b6c3-f3f3b32f93a3 (api:52)
2017-07-27 11:06:06,996-0400 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.01 seconds (__init__:539)
2017-07-27 11:06:07,773-0400 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)