[ovirt-users] Re: Unable to do Live Migration

28 Jun 2018


      Hello,

for my issue, her we go:
vdsm.log source
2018-06-28 12:25:47,566+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:47,575+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:25:48,926+0200 INFO  (jsonrpc/0) [vdsm.api] START migrate(params={u'incomingLimit': 2, u'src': u'10.157.8.40', u'dstqemu': u'192.168.1.113', u'autoConverge': u'false', u'tunneled': u'false', u'enableGuestEvents': False, u'dst': u'10.157.8.42:54321', u'vmId': u'a54af7cd-3b89-43c1-82b3-ae0c08d103d3', u'abortOnError': u'true', u'outgoingLimit': 2, u'compressed': u'false', u'maxBandwidth': 500, u'method': u'online', 'mode': 'remote'}) from=::ffff:10.157.8.36,53170, flow_id=db7c94d5-7e11-43b0-95d8-a9095e4f8e83 (api:46)
2018-06-28 12:25:48,929+0200 INFO  (jsonrpc/0) [vdsm.api] FINISH migrate return={'status': {'message': 'Migration in progress', 'code': 0}, 'progress': 0} from=::ffff:10.157.8.36,53170, flow_id=db7c94d5-7e11-43b0-95d8-a9095e4f8e83 (api:52)
2018-06-28 12:25:48,930+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.migrate succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:25:49,153+0200 INFO  (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=554b6d96-89b0-4ff5-a2de-ced7f268d58c (api:46)
2018-06-28 12:25:49,154+0200 INFO  (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000299843', 'lastCheck': '2.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000570989', 'lastCheck': '5.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000248445', 'lastCheck': '5.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000408845', 'lastCheck': '4.9', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=554b6d96-89b0-4ff5-a2de-ced7f268d58c (api:52)
2018-06-28 12:25:49,173+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:49,860+0200 INFO  (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Creation of destination VM took: 0 seconds (migration:455)
2018-06-28 12:25:49,861+0200 INFO  (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') starting migration to qemu+tls://10.157.8.42/system with miguri tcp://192.168.1.113 (migration:480)
2018-06-28 12:25:52,080+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:55,836+0200 INFO  (periodic/7090) [vdsm.api] START repoStats(options=None) from=internal, task_id=07d6e59b-93a7-46ef-8ffe-a9b8d8f1d3b1 (api:46)
2018-06-28 12:25:55,837+0200 INFO  (periodic/7090) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000349569', 'lastCheck': '5.3', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000632803', 'lastCheck': '1.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00025132', 'lastCheck': '2.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000334113', 'lastCheck': '1.6', 'valid': True}} from=internal, task_id=07d6e59b-93a7-46ef-8ffe-a9b8d8f1d3b1 (api:52)
2018-06-28 12:25:59,865+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 10 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:26:02,584+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:02,610+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:04,177+0200 INFO  (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=6226131d-2afb-453f-8fdd-4814985f2602 (api:46)
2018-06-28 12:26:04,177+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000240789', 'lastCheck': '3.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00048312', 'lastCheck': '0.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000303582', 'lastCheck': '0.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000334113', 'lastCheck': '3.5', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=6226131d-2afb-453f-8fdd-4814985f2602 (api:52)
2018-06-28 12:26:04,196+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:26:07,142+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:09,868+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:26:09,869+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 20 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:26:10,885+0200 INFO  (periodic/7091) [vdsm.api] START repoStats(options=None) from=internal, task_id=55ee01e0-c474-44ee-a9a5-b1d5fd599043 (api:46)
2018-06-28 12:26:10,885+0200 INFO  (periodic/7091) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000350665', 'lastCheck': '0.3', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00048312', 'lastCheck': '6.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000303582', 'lastCheck': '7.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000420027', 'lastCheck': '0.2', 'valid': True}} from=internal, task_id=55ee01e0-c474-44ee-a9a5-b1d5fd599043 (api:52)
2018-06-28 12:26:16,735+0200 INFO  (itmap/0) [IOProcessClient] Starting client ioprocess-351445 (__init__:330)
2018-06-28 12:26:16,743+0200 INFO  (ioprocess/11232) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,744+0200 INFO  (itmap/1) [IOProcessClient] Starting client ioprocess-351446 (__init__:330)
2018-06-28 12:26:16,750+0200 INFO  (itmap/2) [IOProcessClient] Starting client ioprocess-351447 (__init__:330)
2018-06-28 12:26:16,755+0200 INFO  (ioprocess/11240) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,757+0200 INFO  (itmap/3) [IOProcessClient] Starting client ioprocess-351448 (__init__:330)
2018-06-28 12:26:16,763+0200 INFO  (ioprocess/11247) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,765+0200 INFO  (itmap/4) [IOProcessClient] Starting client ioprocess-351449 (__init__:330)
2018-06-28 12:26:16,771+0200 INFO  (ioprocess/11256) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,773+0200 INFO  (itmap/5) [IOProcessClient] Starting client ioprocess-351450 (__init__:330)
2018-06-28 12:26:16,778+0200 INFO  (ioprocess/11265) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,780+0200 INFO  (itmap/6) [IOProcessClient] Starting client ioprocess-351451 (__init__:330)
2018-06-28 12:26:16,785+0200 INFO  (ioprocess/11275) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,787+0200 INFO  (itmap/7) [IOProcessClient] Starting client ioprocess-351452 (__init__:330)
2018-06-28 12:26:16,791+0200 INFO  (ioprocess/11283) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,793+0200 INFO  (itmap/8) [IOProcessClient] Starting client ioprocess-351453 (__init__:330)
2018-06-28 12:26:16,798+0200 INFO  (ioprocess/11290) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,799+0200 INFO  (itmap/9) [IOProcessClient] Starting client ioprocess-351454 (__init__:330)
2018-06-28 12:26:16,804+0200 INFO  (ioprocess/11297) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,806+0200 INFO  (itmap/10) [IOProcessClient] Starting client ioprocess-351455 (__init__:330)
2018-06-28 12:26:16,813+0200 INFO  (ioprocess/11304) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,815+0200 INFO  (ioprocess/11311) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:26:16,822+0200 INFO  (monitor/48055e2) [storage.StorageDomain] Resource namespace 01_img_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:758)
2018-06-28 12:26:16,822+0200 INFO  (monitor/48055e2) [storage.StorageDomain] Resource namespace 02_vol_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:767)
2018-06-28 12:26:17,617+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:26:17,628+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:19,199+0200 INFO  (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=13488a51-8f0b-4ea0-89b7-3bc39bb68fa9 (api:46)
2018-06-28 12:26:19,199+0200 INFO  (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000350665', 'lastCheck': '2.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00063241', 'lastCheck': '5.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000543002', 'lastCheck': '5.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000434669', 'lastCheck': '5.0', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=13488a51-8f0b-4ea0-89b7-3bc39bb68fa9 (api:52)
2018-06-28 12:26:19,218+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:26:19,871+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:26:19,872+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 30 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:26:22,198+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:26:25,922+0200 INFO  (periodic/7090) [vdsm.api] START repoStats(options=None) from=internal, task_id=59c658bf-3f91-4c87-8942-549703fcfbfb (api:46)
2018-06-28 12:26:25,923+0200 INFO  (periodic/7090) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000306354', 'lastCheck': '5.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000571317', 'lastCheck': '1.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000244739', 'lastCheck': '2.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000327441', 'lastCheck': '1.7', 'valid': True}} from=internal, task_id=59c658bf-3f91-4c87-8942-549703fcfbfb (api:52)
2018-06-28 12:26:29,874+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:26:29,875+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 40 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:26:32,636+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:26:32,662+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:34,220+0200 INFO  (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=b219c494-760f-43fa-9220-22602e7b3aef (api:46)
2018-06-28 12:26:34,220+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00027001', 'lastCheck': '3.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00069247', 'lastCheck': '0.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000463365', 'lastCheck': '0.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000327441', 'lastCheck': '3.5', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=b219c494-760f-43fa-9220-22602e7b3aef (api:52)
2018-06-28 12:26:34,244+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:26:37,252+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:38,944+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'714ca627-a9d2-4c2f-8e29-00165c3c0778', volUUID=u'171a4bcc-6e6b-4201-a2d9-1c08296517b7', options=None) from=internal, task_id=576397ad-8f47-45dd-bfaf-d5d50808c165 (api:46)
2018-06-28 12:26:38,944+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '128849018880', 'apparentsize': '128849018880'} from=internal, task_id=576397ad-8f47-45dd-bfaf-d5d50808c165 (api:52)
2018-06-28 12:26:38,945+0200 INFO  (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'c2cfa750-22ce-4c1d-802e-1739c6926f78', volUUID=u'934fcb45-444b-45ef-975f-7d63f228dcc4', options=None) from=internal, task_id=18608522-878e-4cc1-aa84-6ebcb822d5fa (api:46)
2018-06-28 12:26:38,945+0200 INFO  (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '19327352832', 'apparentsize': '19327352832'} from=internal, task_id=18608522-878e-4cc1-aa84-6ebcb822d5fa (api:52)
2018-06-28 12:26:38,946+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cfe6d612-40cc-4f1d-990e-ae6c52a4f70f', volUUID=u'02af893d-647e-4906-8814-de4003506c96', options=None) from=internal, task_id=e3bc7fe2-2ced-4ae4-b5e4-64a4153172b3 (api:46)
2018-06-28 12:26:38,946+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '26843545600', 'apparentsize': '26843545600'} from=internal, task_id=e3bc7fe2-2ced-4ae4-b5e4-64a4153172b3 (api:52)
2018-06-28 12:26:38,947+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1a7022e0-54b5-419a-a144-439c8526e1cd', volUUID=u'f05a1e54-e612-41d2-a7cc-d4f7e16dfc4f', options=None) from=internal, task_id=8c9230ca-7c43-4c89-a799-1c98ebf74bab (api:46)
2018-06-28 12:26:38,947+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=8c9230ca-7c43-4c89-a799-1c98ebf74bab (api:52)
2018-06-28 12:26:38,947+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cb2d4f33-6fa6-4448-b1cc-c060297407b7', volUUID=u'e6168731-26fc-4dd2-92c1-443de74d49bb', options=None) from=internal, task_id=4b7ec2e7-79a4-425d-a295-5918126a33cf (api:46)
2018-06-28 12:26:38,948+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '1099511627776', 'apparentsize': '1099511627776'} from=internal, task_id=4b7ec2e7-79a4-425d-a295-5918126a33cf (api:52)
2018-06-28 12:26:38,949+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5fc7b643-db9a-4162-a67d-fb61a8cd87f7', volUUID=u'd259d325-e2bc-4a2a-935b-6eca167c6b51', options=None) from=internal, task_id=1a011e63-21ab-4b35-bd47-79ff77634775 (api:46)
2018-06-28 12:26:38,949+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=1a011e63-21ab-4b35-bd47-79ff77634775 (api:52)
2018-06-28 12:26:38,950+0200 INFO  (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'33235bbf-0156-421e-9391-0749247b6ba6', volUUID=u'0d2949b6-af0f-4de2-b29a-10dcb39ad857', options=None) from=internal, task_id=0f9ec553-58ac-48b4-97da-e5e08a861a6b (api:46)
2018-06-28 12:26:38,950+0200 INFO  (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '5368709120', 'apparentsize': '5368709120'} from=internal, task_id=0f9ec553-58ac-48b4-97da-e5e08a861a6b (api:52)
2018-06-28 12:26:38,951+0200 INFO  (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5149067a-b18c-41cf-a355-033317291148', volUUID=u'f0afa250-6704-410c-b9be-60b99cb28ce9', options=None) from=internal, task_id=ccfa4241-0799-4645-bbde-a3ccd866107d (api:46)
2018-06-28 12:26:38,951+0200 INFO  (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '16106127360', 'apparentsize': '16106127360'} from=internal, task_id=ccfa4241-0799-4645-bbde-a3ccd866107d (api:52)
2018-06-28 12:26:38,952+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'07c38269-db89-4f7e-9194-f0c8923ed879', volUUID=u'366d9d18-07fa-4342-9246-fc0f396e3059', options=None) from=internal, task_id=061ca7ab-d0fd-406b-989f-c9cd0246d80c (api:46)
2018-06-28 12:26:38,952+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '25769803776', 'apparentsize': '25769803776'} from=internal, task_id=061ca7ab-d0fd-406b-989f-c9cd0246d80c (api:52)
2018-06-28 12:26:38,953+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'9d92c039-5c22-4459-bc8b-ca62f0d763dd', volUUID=u'b9abe859-bd8f-412d-b1ca-f814f17d2572', options=None) from=internal, task_id=c3aa0fd8-cfd6-47cc-8a4a-a799f2ccf232 (api:46)
2018-06-28 12:26:38,953+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '144149839872', 'apparentsize': '144149839872'} from=internal, task_id=c3aa0fd8-cfd6-47cc-8a4a-a799f2ccf232 (api:52)
2018-06-28 12:26:38,954+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'a2f86027-9569-411a-8dec-b5ef0b6a30cd', volUUID=u'1eb84b01-512a-4e08-b6bc-0c056c5c86b6', options=None) from=internal, task_id=8ad4c399-0fe3-4236-859d-d18a02e4cafd (api:46)
2018-06-28 12:26:38,954+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '72074919936', 'apparentsize': '72074919936'} from=internal, task_id=8ad4c399-0fe3-4236-859d-d18a02e4cafd (api:52)
2018-06-28 12:26:38,955+0200 INFO  (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', volUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', options=None) from=internal, task_id=c5ecbbb8-503a-4e83-ac8e-9e1d63ac7347 (api:46)
2018-06-28 12:26:38,955+0200 INFO  (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '53687091200', 'apparentsize': '53687091200'} from=internal, task_id=c5ecbbb8-503a-4e83-ac8e-9e1d63ac7347 (api:52)
2018-06-28 12:26:39,877+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:26:39,877+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 50 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:26:40,962+0200 INFO  (periodic/7085) [vdsm.api] START repoStats(options=None) from=internal, task_id=52703fc2-7917-4f58-a390-425850ca3b24 (api:46)
2018-06-28 12:26:40,962+0200 INFO  (periodic/7085) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000235121', 'lastCheck': '0.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00069247', 'lastCheck': '7.0', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000463365', 'lastCheck': '7.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000375592', 'lastCheck': '0.2', 'valid': True}} from=internal, task_id=52703fc2-7917-4f58-a390-425850ca3b24 (api:52)
2018-06-28 12:26:47,671+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:26:47,697+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:26:49,242+0200 INFO  (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=7409865e-ff52-406b-b22d-f2934674de2e (api:46)
2018-06-28 12:26:49,242+0200 INFO  (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000235121', 'lastCheck': '2.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000510816', 'lastCheck': '5.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000324262', 'lastCheck': '5.4', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000441143', 'lastCheck': '5.0', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=7409865e-ff52-406b-b22d-f2934674de2e (api:52)
2018-06-28 12:26:49,265+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.03 seconds (__init__:539)
2018-06-28 12:26:49,881+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:26:49,881+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 60 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:26:52,319+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:26:56,008+0200 INFO  (periodic/7093) [vdsm.api] START repoStats(options=None) from=internal, task_id=dbbb6f8a-457c-4a6a-b1ec-3abd59962551 (api:46)
2018-06-28 12:26:56,009+0200 INFO  (periodic/7093) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000316826', 'lastCheck': '5.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000514374', 'lastCheck': '2.0', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000374509', 'lastCheck': '2.2', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000400921', 'lastCheck': '1.8', 'valid': True}} from=internal, task_id=dbbb6f8a-457c-4a6a-b1ec-3abd59962551 (api:52)
2018-06-28 12:26:59,883+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:26:59,884+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 70 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:27:02,705+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:27:02,714+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:27:04,297+0200 INFO  (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=4e03d286-f133-4767-8815-70f0fcdb8d44 (api:46)
2018-06-28 12:27:04,297+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000339338', 'lastCheck': '3.8', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000629102', 'lastCheck': '0.3', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000554273', 'lastCheck': '0.5', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000380205', 'lastCheck': '0.1', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=4e03d286-f133-4767-8815-70f0fcdb8d44 (api:52)
2018-06-28 12:27:04,315+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:27:07,372+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:27:09,886+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:27:09,886+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 80 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:27:11,056+0200 INFO  (periodic/7090) [vdsm.api] START repoStats(options=None) from=internal, task_id=0b893099-f458-458a-86cb-185409463a4c (api:46)
2018-06-28 12:27:11,056+0200 INFO  (periodic/7090) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000252952', 'lastCheck': '0.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000629102', 'lastCheck': '7.1', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000554273', 'lastCheck': '7.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000380205', 'lastCheck': '0.3', 'valid': True}} from=internal, task_id=0b893099-f458-458a-86cb-185409463a4c (api:52)
2018-06-28 12:27:16,838+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351449 (__init__:598)
2018-06-28 12:27:16,838+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351446 (__init__:598)
2018-06-28 12:27:16,838+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351445 (__init__:598)
2018-06-28 12:27:16,839+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351454 (__init__:598)
2018-06-28 12:27:16,839+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351451 (__init__:598)
2018-06-28 12:27:16,839+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351455 (__init__:598)
2018-06-28 12:27:16,839+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351453 (__init__:598)
2018-06-28 12:27:16,839+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351450 (__init__:598)
2018-06-28 12:27:16,840+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351447 (__init__:598)
2018-06-28 12:27:16,840+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351452 (__init__:598)
2018-06-28 12:27:16,840+0200 INFO  (monitor/48055e2) [IOProcessClient] Closing client ioprocess-351448 (__init__:598)
2018-06-28 12:27:17,728+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:27:17,737+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:27:19,321+0200 INFO  (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=5d54f7d8-0ebe-4175-b7b7-6b33cac964ad (api:46)
2018-06-28 12:27:19,321+0200 INFO  (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000252952', 'lastCheck': '2.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000510061', 'lastCheck': '5.3', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000301065', 'lastCheck': '5.5', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000442633', 'lastCheck': '5.1', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=5d54f7d8-0ebe-4175-b7b7-6b33cac964ad (api:52)
2018-06-28 12:27:19,341+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:27:19,888+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:27:19,888+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 90 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:27:22,422+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:27:26,094+0200 INFO  (periodic/7091) [vdsm.api] START repoStats(options=None) from=internal, task_id=97f4298f-dae2-4107-9f7a-e62b99e3c6d5 (api:46)
2018-06-28 12:27:26,094+0200 INFO  (periodic/7091) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000345748', 'lastCheck': '5.6', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00064893', 'lastCheck': '2.1', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000473681', 'lastCheck': '2.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000367846', 'lastCheck': '1.9', 'valid': True}} from=internal, task_id=97f4298f-dae2-4107-9f7a-e62b99e3c6d5 (api:52)
2018-06-28 12:27:29,891+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:27:29,892+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 100 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:27:32,745+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:27:32,772+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:27:34,354+0200 INFO  (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=2ffd5e90-01c0-46fa-bc86-74e2a0c9bdb5 (api:46)
2018-06-28 12:27:34,355+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000366741', 'lastCheck': '3.8', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00067226', 'lastCheck': '0.4', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00046561', 'lastCheck': '0.6', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000365602', 'lastCheck': '0.1', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=2ffd5e90-01c0-46fa-bc86-74e2a0c9bdb5 (api:52)
2018-06-28 12:27:34,373+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:27:37,477+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:27:38,935+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'714ca627-a9d2-4c2f-8e29-00165c3c0778', volUUID=u'171a4bcc-6e6b-4201-a2d9-1c08296517b7', options=None) from=internal, task_id=28d944b0-ea96-4a56-afc1-4ca642804765 (api:46)
2018-06-28 12:27:38,936+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '128849018880', 'apparentsize': '128849018880'} from=internal, task_id=28d944b0-ea96-4a56-afc1-4ca642804765 (api:52)
2018-06-28 12:27:38,937+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'c2cfa750-22ce-4c1d-802e-1739c6926f78', volUUID=u'934fcb45-444b-45ef-975f-7d63f228dcc4', options=None) from=internal, task_id=83d16ca0-5975-4e0f-84fe-1d63ed13783f (api:46)
2018-06-28 12:27:38,937+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '19327352832', 'apparentsize': '19327352832'} from=internal, task_id=83d16ca0-5975-4e0f-84fe-1d63ed13783f (api:52)
2018-06-28 12:27:38,938+0200 INFO  (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cfe6d612-40cc-4f1d-990e-ae6c52a4f70f', volUUID=u'02af893d-647e-4906-8814-de4003506c96', options=None) from=internal, task_id=161ed3bc-4d7d-4c9b-9915-f67829d7183d (api:46)
2018-06-28 12:27:38,938+0200 INFO  (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '26843545600', 'apparentsize': '26843545600'} from=internal, task_id=161ed3bc-4d7d-4c9b-9915-f67829d7183d (api:52)
2018-06-28 12:27:38,939+0200 INFO  (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1a7022e0-54b5-419a-a144-439c8526e1cd', volUUID=u'f05a1e54-e612-41d2-a7cc-d4f7e16dfc4f', options=None) from=internal, task_id=e4fd4063-be84-493f-8616-1a23ca7085b3 (api:46)
2018-06-28 12:27:38,939+0200 INFO  (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=e4fd4063-be84-493f-8616-1a23ca7085b3 (api:52)
2018-06-28 12:27:38,939+0200 INFO  (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'cb2d4f33-6fa6-4448-b1cc-c060297407b7', volUUID=u'e6168731-26fc-4dd2-92c1-443de74d49bb', options=None) from=internal, task_id=6ada779f-ea02-48f2-99ea-e7090a7e4b18 (api:46)
2018-06-28 12:27:38,940+0200 INFO  (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '1099511627776', 'apparentsize': '1099511627776'} from=internal, task_id=6ada779f-ea02-48f2-99ea-e7090a7e4b18 (api:52)
2018-06-28 12:27:38,940+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5fc7b643-db9a-4162-a67d-fb61a8cd87f7', volUUID=u'd259d325-e2bc-4a2a-935b-6eca167c6b51', options=None) from=internal, task_id=89408443-0882-42f5-9c61-4699fdab4556 (api:46)
2018-06-28 12:27:38,941+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=89408443-0882-42f5-9c61-4699fdab4556 (api:52)
2018-06-28 12:27:38,941+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'33235bbf-0156-421e-9391-0749247b6ba6', volUUID=u'0d2949b6-af0f-4de2-b29a-10dcb39ad857', options=None) from=internal, task_id=e440afe9-a3fb-4942-9e68-3e14f5a9d271 (api:46)
2018-06-28 12:27:38,942+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '5368709120', 'apparentsize': '5368709120'} from=internal, task_id=e440afe9-a3fb-4942-9e68-3e14f5a9d271 (api:52)
2018-06-28 12:27:38,942+0200 INFO  (periodic/7090) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'5149067a-b18c-41cf-a355-033317291148', volUUID=u'f0afa250-6704-410c-b9be-60b99cb28ce9', options=None) from=internal, task_id=3399f449-2dcc-4d82-8285-f1945d0e2baf (api:46)
2018-06-28 12:27:38,942+0200 INFO  (periodic/7090) [vdsm.api] FINISH getVolumeSize return={'truesize': '16106127360', 'apparentsize': '16106127360'} from=internal, task_id=3399f449-2dcc-4d82-8285-f1945d0e2baf (api:52)
2018-06-28 12:27:38,943+0200 INFO  (periodic/7091) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'07c38269-db89-4f7e-9194-f0c8923ed879', volUUID=u'366d9d18-07fa-4342-9246-fc0f396e3059', options=None) from=internal, task_id=1d361a42-8c9e-4885-a8ff-e7ce0c1c224f (api:46)
2018-06-28 12:27:38,943+0200 INFO  (periodic/7091) [vdsm.api] FINISH getVolumeSize return={'truesize': '25769803776', 'apparentsize': '25769803776'} from=internal, task_id=1d361a42-8c9e-4885-a8ff-e7ce0c1c224f (api:52)
2018-06-28 12:27:38,944+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'9d92c039-5c22-4459-bc8b-ca62f0d763dd', volUUID=u'b9abe859-bd8f-412d-b1ca-f814f17d2572', options=None) from=internal, task_id=a17d38fc-772e-47ad-99e1-fd7fea5e2b97 (api:46)
2018-06-28 12:27:38,944+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '144149839872', 'apparentsize': '144149839872'} from=internal, task_id=a17d38fc-772e-47ad-99e1-fd7fea5e2b97 (api:52)
2018-06-28 12:27:38,945+0200 INFO  (periodic/7085) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'a2f86027-9569-411a-8dec-b5ef0b6a30cd', volUUID=u'1eb84b01-512a-4e08-b6bc-0c056c5c86b6', options=None) from=internal, task_id=aacf55d3-3fdd-49e1-af58-bae7ce9fbd6f (api:46)
2018-06-28 12:27:38,945+0200 INFO  (periodic/7085) [vdsm.api] FINISH getVolumeSize return={'truesize': '72074919936', 'apparentsize': '72074919936'} from=internal, task_id=aacf55d3-3fdd-49e1-af58-bae7ce9fbd6f (api:52)
2018-06-28 12:27:38,945+0200 INFO  (periodic/7093) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', volUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', options=None) from=internal, task_id=6213f532-b194-467b-9799-02032e59af58 (api:46)
2018-06-28 12:27:38,946+0200 INFO  (periodic/7093) [vdsm.api] FINISH getVolumeSize return={'truesize': '53687091200', 'apparentsize': '53687091200'} from=internal, task_id=6213f532-b194-467b-9799-02032e59af58 (api:52)
2018-06-28 12:27:39,894+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:27:39,894+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 110 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:27:41,143+0200 INFO  (periodic/7085) [vdsm.api] START repoStats(options=None) from=internal, task_id=79f2e7e6-ef1d-47d8-87a9-46aefcd02467 (api:46)
2018-06-28 12:27:41,143+0200 INFO  (periodic/7085) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000291026', 'lastCheck': '0.6', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00067226', 'lastCheck': '7.1', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.00046561', 'lastCheck': '7.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000365602', 'lastCheck': '0.4', 'valid': True}} from=internal, task_id=79f2e7e6-ef1d-47d8-87a9-46aefcd02467 (api:52)
2018-06-28 12:27:41,313+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['metadata'] (lvm:1291)
2018-06-28 12:27:41,313+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['metadata']) (lvm:1319)
2018-06-28 12:27:41,475+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['ids'] (lvm:1291)
2018-06-28 12:27:41,476+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['ids']) (lvm:1319)
2018-06-28 12:27:41,544+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['leases'] (lvm:1291)
2018-06-28 12:27:41,544+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['leases']) (lvm:1319)
2018-06-28 12:27:41,622+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1291)
2018-06-28 12:27:41,623+0200 INFO  (monitor/68b8aaf) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master']) (lvm:1319)
2018-06-28 12:27:41,716+0200 INFO  (monitor/68b8aaf) [storage.StorageDomain] Resource namespace 01_img_68b8aaff-770d-4a08-800b-0c15e94efaa8 already registered (sd:758)
2018-06-28 12:27:41,716+0200 INFO  (monitor/68b8aaf) [storage.StorageDomain] Resource namespace 02_vol_68b8aaff-770d-4a08-800b-0c15e94efaa8 already registered (sd:767)
2018-06-28 12:27:41,716+0200 INFO  (monitor/68b8aaf) [storage.StorageDomain] Resource namespace 03_lvm_68b8aaff-770d-4a08-800b-0c15e94efaa8 already registered (blockSD:989)
2018-06-28 12:27:47,784+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:27:47,809+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:27:49,415+0200 INFO  (jsonrpc/7) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=01be8d64-d54a-4c9d-979e-3971279eac9b (api:46)
2018-06-28 12:27:49,416+0200 INFO  (jsonrpc/7) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000291026', 'lastCheck': '2.6', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000573367', 'lastCheck': '5.4', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000457603', 'lastCheck': '5.6', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000393837', 'lastCheck': '5.2', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=01be8d64-d54a-4c9d-979e-3971279eac9b (api:52)
2018-06-28 12:27:49,435+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:27:49,896+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:27:49,897+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 120 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:27:52,532+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:27:56,181+0200 INFO  (periodic/7093) [vdsm.api] START repoStats(options=None) from=internal, task_id=db929a1d-f13a-4ea3-89fb-4d8825204cac (api:46)
2018-06-28 12:27:56,182+0200 INFO  (periodic/7093) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000398606', 'lastCheck': '5.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000667386', 'lastCheck': '2.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000471581', 'lastCheck': '2.3', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000276833', 'lastCheck': '2.0', 'valid': True}} from=internal, task_id=db929a1d-f13a-4ea3-89fb-4d8825204cac (api:52)
2018-06-28 12:27:59,899+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration stalling: remaining (2112MiB) > lowmark (2112MiB). Refer to RHBZ#919201. (migration:785)
2018-06-28 12:27:59,899+0200 INFO  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Migration Progress: 130 seconds elapsed, 1% of data processed, total data: 2113MB, processed data: 0MB, remaining data: 2112MB, transfer speed 0MBps, zero pages: 6MB, compressed: 0MB, dirty rate: 0, memory iteration: 1 (migration:815)
2018-06-28 12:28:00,752+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['metadata'] (lvm:1291)
2018-06-28 12:28:00,752+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['metadata']) (lvm:1319)
2018-06-28 12:28:00,895+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['ids'] (lvm:1291)
2018-06-28 12:28:00,896+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['ids']) (lvm:1319)
2018-06-28 12:28:00,962+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['leases'] (lvm:1291)
2018-06-28 12:28:00,963+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['leases']) (lvm:1319)
2018-06-28 12:28:01,033+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing lvs: vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master'] (lvm:1291)
2018-06-28 12:28:01,033+0200 INFO  (monitor/8924ce2) [storage.LVM] Refreshing LVs (vg=8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5, lvs=['metadata', 'leases', 'ids', 'inbox', 'outbox', 'xleases', 'master']) (lvm:1319)
2018-06-28 12:28:01,113+0200 INFO  (monitor/8924ce2) [storage.StorageDomain] Resource namespace 01_img_8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 already registered (sd:758)
2018-06-28 12:28:01,114+0200 INFO  (monitor/8924ce2) [storage.StorageDomain] Resource namespace 02_vol_8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 already registered (sd:767)
2018-06-28 12:28:01,114+0200 INFO  (monitor/8924ce2) [storage.StorageDomain] Resource namespace 03_lvm_8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5 already registered (blockSD:989)
2018-06-28 12:28:02,822+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:28:02,848+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:28:04,455+0200 INFO  (jsonrpc/3) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,53170, task_id=8d2d2379-1f5a-47a1-8b37-b922d13a02c6 (api:46)
2018-06-28 12:28:04,456+0200 INFO  (jsonrpc/3) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000321492', 'lastCheck': '3.9', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000650208', 'lastCheck': '0.5', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000296691', 'lastCheck': '0.7', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000362554', 'lastCheck': '0.2', 'valid': True}} from=::ffff:10.157.8.36,53170, task_id=8d2d2379-1f5a-47a1-8b37-b922d13a02c6 (api:52)
2018-06-28 12:28:04,473+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:28:07,585+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:28:09,902+0200 WARN  (migmon/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') The migration took 140 seconds which is exceeding the configured maximum time for migrations of 131 seconds. The migration will be aborted. (migration:773)
2018-06-28 12:28:10,955+0200 ERROR (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Operation abgebrochen: Migrations-Job: abgebrochen durch Client (migration:287)
2018-06-28 12:28:11,174+0200 ERROR (migsrc/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') 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 1006, 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: Operation abgebrochen: Migrations-Job: abgebrochen durch Client
2

and vdsm.log from destination:
2018-06-28 12:25:01,919+0200 INFO  (periodic/6162) [vdsm.api] START repoStats(options=None) from=internal, task_id=cb3869db-d960-49e0-ba4a-d726bf27539b (api:46)
2018-06-28 12:25:01,920+0200 INFO  (periodic/6162) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000606644', 'lastCheck': '0.5', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000570293', 'lastCheck': '3.6', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000286344', 'lastCheck': '3.7', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000345685', 'lastCheck': '1.6', 'valid': True}} from=internal, task_id=cb3869db-d960-49e0-ba4a-d726bf27539b (api:52)
2018-06-28 12:25:04,109+0200 INFO  (jsonrpc/0) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=dc938a7a-3c7a-40d3-9e06-7f712e7fc527 (api:46)
2018-06-28 12:25:04,110+0200 INFO  (jsonrpc/0) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000606644', 'lastCheck': '2.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000570293', 'lastCheck': '5.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000286344', 'lastCheck': '5.9', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000345685', 'lastCheck': '3.7', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=dc938a7a-3c7a-40d3-9e06-7f712e7fc527 (api:52)
2018-06-28 12:25:04,157+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539)
2018-06-28 12:25:12,757+0200 INFO  (jsonrpc/4) [vdsm.api] START setBalloonTarget(target=9874629) from=::1,46990 (api:46)
2018-06-28 12:25:12,774+0200 INFO  (jsonrpc/4) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52)
2018-06-28 12:25:12,774+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:13,453+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:14,824+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:14,847+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:25:17,007+0200 INFO  (periodic/6163) [vdsm.api] START repoStats(options=None) from=internal, task_id=3136344f-2e0d-4d0d-83a7-b6cd8809acbc (api:46)
2018-06-28 12:25:17,008+0200 INFO  (periodic/6163) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000507353', 'lastCheck': '1.2', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000568841', 'lastCheck': '1.2', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000262659', 'lastCheck': '8.8', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000300632', 'lastCheck': '6.6', 'valid': True}} from=internal, task_id=3136344f-2e0d-4d0d-83a7-b6cd8809acbc (api:52)
2018-06-28 12:25:19,137+0200 INFO  (jsonrpc/6) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=8c36bf93-c4b6-49a6-a019-82c02b98e03f (api:46)
2018-06-28 12:25:19,138+0200 INFO  (jsonrpc/6) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000507353', 'lastCheck': '3.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000588412', 'lastCheck': '0.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000514061', 'lastCheck': '1.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000388286', 'lastCheck': '0.5', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=8c36bf93-c4b6-49a6-a019-82c02b98e03f (api:52)
2018-06-28 12:25:19,187+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539)
2018-06-28 12:25:27,960+0200 INFO  (jsonrpc/1) [vdsm.api] START setBalloonTarget(target=9854363) from=::1,46990 (api:46)
2018-06-28 12:25:27,993+0200 INFO  (jsonrpc/1) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52)
2018-06-28 12:25:27,994+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.03 seconds (__init__:539)
2018-06-28 12:25:28,530+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:29,870+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:29,914+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:25:32,113+0200 INFO  (periodic/6162) [vdsm.api] START repoStats(options=None) from=internal, task_id=5c30fd65-66e8-4f36-b036-47bec09fd522 (api:46)
2018-06-28 12:25:32,114+0200 INFO  (periodic/6162) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000500395', 'lastCheck': '0.7', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000620907', 'lastCheck': '3.8', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000339191', 'lastCheck': '3.9', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000404014', 'lastCheck': '1.7', 'valid': True}} from=internal, task_id=5c30fd65-66e8-4f36-b036-47bec09fd522 (api:52)
2018-06-28 12:25:34,151+0200 INFO  (jsonrpc/5) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=9351125d-3a9e-4e22-9bdb-e86ed35032fd (api:46)
2018-06-28 12:25:34,151+0200 INFO  (jsonrpc/5) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000500395', 'lastCheck': '2.8', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000620907', 'lastCheck': '5.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000339191', 'lastCheck': '6.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000404014', 'lastCheck': '3.8', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=9351125d-3a9e-4e22-9bdb-e86ed35032fd (api:52)
2018-06-28 12:25:34,198+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539)
2018-06-28 12:25:41,239+0200 INFO  (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'6c94e2de-d65d-45f3-842e-68c006bc1a15', volUUID=u'70e61b28-fb15-4c0f-a425-bcbf8a506423', options=None) from=internal, task_id=d17b01b6-2321-49c9-a564-1689dacbae66 (api:46)
2018-06-28 12:25:41,240+0200 INFO  (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '6442450944', 'apparentsize': '6442450944'} from=internal, task_id=d17b01b6-2321-49c9-a564-1689dacbae66 (api:52)
2018-06-28 12:25:41,241+0200 INFO  (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'30e80e8a-a30d-4f4a-b593-d5df59acd6b9', volUUID=u'dc6b8058-895d-48c3-aff8-d381877a9904', options=None) from=internal, task_id=ca550e56-5d6c-4f71-aa82-f572feb23192 (api:46)
2018-06-28 12:25:41,241+0200 INFO  (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=ca550e56-5d6c-4f71-aa82-f572feb23192 (api:52)
2018-06-28 12:25:41,242+0200 INFO  (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'55a7014f-aaaa-4a48-8522-8d962fa3e37a', volUUID=u'd0a9a441-6c77-4539-8851-908e3d91331c', options=None) from=internal, task_id=633bf144-d519-42fc-949a-c3edab728255 (api:46)
2018-06-28 12:25:41,242+0200 INFO  (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=633bf144-d519-42fc-949a-c3edab728255 (api:52)
2018-06-28 12:25:41,243+0200 INFO  (periodic/6164) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'0e3981b3-045b-4a66-a08e-b0bfccd81f5a', volUUID=u'acf2c734-b052-445b-98cc-e7f3eca8bd76', options=None) from=internal, task_id=8486f1b4-a8a8-4692-97ae-ea1c7f135758 (api:46)
2018-06-28 12:25:41,243+0200 INFO  (periodic/6164) [vdsm.api] FINISH getVolumeSize return={'truesize': '80530636800', 'apparentsize': '80530636800'} from=internal, task_id=8486f1b4-a8a8-4692-97ae-ea1c7f135758 (api:52)
2018-06-28 12:25:41,244+0200 INFO  (periodic/6160) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'df435578-a524-4cd8-9b3d-74f36c4b182f', volUUID=u'd971520b-464b-4939-bff8-562572e9a439', options=None) from=internal, task_id=bc538510-62f6-4eba-bcb6-bbd1088b3673 (api:46)
2018-06-28 12:25:41,244+0200 INFO  (periodic/6160) [vdsm.api] FINISH getVolumeSize return={'truesize': '67645734912', 'apparentsize': '67645734912'} from=internal, task_id=bc538510-62f6-4eba-bcb6-bbd1088b3673 (api:52)
2018-06-28 12:25:41,245+0200 INFO  (periodic/6160) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'b5ee85a6-eaef-4cc4-9506-8ccd540a03fb', volUUID=u'd9853bb2-54c3-44c7-be61-862484ed031d', options=None) from=internal, task_id=83653b45-6b15-485f-9c7a-65df75e1af8a (api:46)
2018-06-28 12:25:41,245+0200 INFO  (periodic/6160) [vdsm.api] FINISH getVolumeSize return={'truesize': '215822106624', 'apparentsize': '215822106624'} from=internal, task_id=83653b45-6b15-485f-9c7a-65df75e1af8a (api:52)
2018-06-28 12:25:41,246+0200 INFO  (periodic/6162) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'6f19ce7b-78d4-4c04-a9e7-97cf2667fbc1', volUUID=u'465e9ac1-08ee-48ec-9159-7dde0ae00499', options=None) from=internal, task_id=d761d21f-6513-4507-b22a-ec1ba4ad2c98 (api:46)
2018-06-28 12:25:41,247+0200 INFO  (periodic/6162) [vdsm.api] FINISH getVolumeSize return={'truesize': '17179869184', 'apparentsize': '17179869184'} from=internal, task_id=d761d21f-6513-4507-b22a-ec1ba4ad2c98 (api:52)
2018-06-28 12:25:41,248+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'157e6919-01d1-47d6-b2e9-4934a5e2743b', volUUID=u'bbe845e7-5b64-4a78-8c9c-c078d23ea50e', options=None) from=internal, task_id=5fffe581-8293-492b-87ac-6b2ac99617b6 (api:46)
2018-06-28 12:25:41,248+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '21474836480', 'apparentsize': '21474836480'} from=internal, task_id=5fffe581-8293-492b-87ac-6b2ac99617b6 (api:52)
2018-06-28 12:25:41,249+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'3ec22ced-a137-4c4c-8fdc-80afedde01d3', volUUID=u'b8aeb887-cc52-4941-b91c-10673a772d60', options=None) from=internal, task_id=6a76cbaa-6704-4c6d-80cb-84a8b7381f92 (api:46)
2018-06-28 12:25:41,249+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=6a76cbaa-6704-4c6d-80cb-84a8b7381f92 (api:52)
2018-06-28 12:25:41,250+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'b9b990e3-abcd-49e0-a4be-fa4f2e3ab17d', volUUID=u'd4eb437e-4442-4469-a3b7-c33ce3ef0619', options=None) from=internal, task_id=87adcf3e-0e0e-4a8e-8912-6985b06b6ee6 (api:46)
2018-06-28 12:25:41,250+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '44023414784', 'apparentsize': '44023414784'} from=internal, task_id=87adcf3e-0e0e-4a8e-8912-6985b06b6ee6 (api:52)
2018-06-28 12:25:41,251+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'ac124e30-064b-4af2-a32b-dea3d9a492a9', volUUID=u'fa387755-b06a-4fda-ad19-6761a765e257', options=None) from=internal, task_id=183a7469-58d8-4cad-8c63-a24c00df50bc (api:46)
2018-06-28 12:25:41,251+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '47244640256', 'apparentsize': '47244640256'} from=internal, task_id=183a7469-58d8-4cad-8c63-a24c00df50bc (api:52)
2018-06-28 12:25:41,252+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'983a5eff-5a53-4677-9d9f-899e500f8535', volUUID=u'5769e03a-2df4-4514-9b93-859fe453e6f9', options=None) from=internal, task_id=b2d4c682-4ffd-46ab-bb2f-cf03edfb1325 (api:46)
2018-06-28 12:25:41,252+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '107374182400', 'apparentsize': '107374182400'} from=internal, task_id=b2d4c682-4ffd-46ab-bb2f-cf03edfb1325 (api:52)
2018-06-28 12:25:41,253+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'53152751-8ae3-4760-aabf-e5f7b0ec6434', volUUID=u'6ad3a22b-dc92-45f8-b06b-27d22ba79ad3', options=None) from=internal, task_id=692228d9-624b-45f0-b0da-08fda6b434cc (api:46)
2018-06-28 12:25:41,253+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '21474836480', 'apparentsize': '21474836480'} from=internal, task_id=692228d9-624b-45f0-b0da-08fda6b434cc (api:52)
2018-06-28 12:25:41,254+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'28aa3761-33d2-4824-b3bb-55fd93996582', volUUID=u'8b7c0a22-79de-4e36-9e8a-934aad6d4c7e', options=None) from=internal, task_id=95868d0a-2efc-44a7-b688-da156122ad38 (api:46)
2018-06-28 12:25:41,254+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '10737418240', 'apparentsize': '10737418240'} from=internal, task_id=95868d0a-2efc-44a7-b688-da156122ad38 (api:52)
2018-06-28 12:25:41,255+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'c9366f52-f1a8-411a-8e0c-3fcb0da264eb', volUUID=u'841b22dd-0ba0-487f-9256-b2e481b4d92b', options=None) from=internal, task_id=211d11fb-dfeb-45d8-93a2-17f0e4289cd0 (api:46)
2018-06-28 12:25:41,255+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '26843545600', 'apparentsize': '26843545600'} from=internal, task_id=211d11fb-dfeb-45d8-93a2-17f0e4289cd0 (api:52)
2018-06-28 12:25:41,256+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'55d90f2e-05d0-4a17-b066-ef52d0f21469', volUUID=u'cf7c3c97-1a7c-4b54-a21d-8d3232fb1667', options=None) from=internal, task_id=e2b43a11-334e-4f30-a7de-b41ffe5ceb33 (api:46)
2018-06-28 12:25:41,257+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '32212254720', 'apparentsize': '32212254720'} from=internal, task_id=e2b43a11-334e-4f30-a7de-b41ffe5ceb33 (api:52)
2018-06-28 12:25:41,257+0200 INFO  (periodic/6163) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'4910730a-1537-4564-80fe-5df0eb9ca276', volUUID=u'77593d90-f216-492d-aced-264ba5c0632f', options=None) from=internal, task_id=e28bdb33-9438-414e-9b58-f4f81c117c34 (api:46)
2018-06-28 12:25:41,258+0200 INFO  (periodic/6163) [vdsm.api] FINISH getVolumeSize return={'truesize': '17716740096', 'apparentsize': '17716740096'} from=internal, task_id=e28bdb33-9438-414e-9b58-f4f81c117c34 (api:52)
2018-06-28 12:25:43,195+0200 INFO  (jsonrpc/7) [vdsm.api] START setBalloonTarget(target=9835175) from=::1,46990 (api:46)
2018-06-28 12:25:43,211+0200 INFO  (jsonrpc/7) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52)
2018-06-28 12:25:43,212+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:43,595+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:44,923+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:44,945+0200 INFO  (jsonrpc/1) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:47,193+0200 INFO  (periodic/6163) [vdsm.api] START repoStats(options=None) from=internal, task_id=0676d13f-11b7-473d-8c58-157bec36772f (api:46)
2018-06-28 12:25:47,193+0200 INFO  (periodic/6163) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000490941', 'lastCheck': '1.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.00065911', 'lastCheck': '1.4', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000546678', 'lastCheck': '9.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000449752', 'lastCheck': '6.8', 'valid': True}} from=internal, task_id=0676d13f-11b7-473d-8c58-157bec36772f (api:52)
2018-06-28 12:25:48,932+0200 INFO  (Reactor thread) [ProtocolDetector.AcceptorImpl] Accepted connection from ::ffff:10.157.8.40:35732 (protocoldetector:72)
2018-06-28 12:25:48,941+0200 INFO  (Reactor thread) [ProtocolDetector.Detector] Detected protocol stomp from ::ffff:10.157.8.40:35732 (protocoldetector:127)
2018-06-28 12:25:48,942+0200 INFO  (Reactor thread) [Broker.StompAdapter] Processing CONNECT request (stompreactor:103)
2018-06-28 12:25:48,943+0200 INFO  (JsonRpc (StompReactor)) [Broker.StompAdapter] Subscribe command received (stompreactor:132)
2018-06-28 12:25:49,169+0200 INFO  (jsonrpc/2) [vdsm.api] START repoStats(options=None) from=::ffff:10.157.8.36,36662, task_id=8c64d73b-10e4-45f7-8c49-43f5e6e61ee5 (api:46)
2018-06-28 12:25:49,170+0200 INFO  (jsonrpc/2) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000490941', 'lastCheck': '3.4', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000692455', 'lastCheck': '0.9', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000301581', 'lastCheck': '1.0', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000362669', 'lastCheck': '0.6', 'valid': True}} from=::ffff:10.157.8.36,36662, task_id=8c64d73b-10e4-45f7-8c49-43f5e6e61ee5 (api:52)
2018-06-28 12:25:49,218+0200 INFO  (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.05 seconds (__init__:539)
2018-06-28 12:25:49,233+0200 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call Host.ping succeeded in 0.00 seconds (__init__:539)
2018-06-28 12:25:49,276+0200 INFO  (jsonrpc/4) [vdsm.api] START __init__(cif=<clientIF.clientIF object at 0x255ef10>, params={u'status': u'Up', u'acpiEnable': u'true', u'emulatedMachine': u'pc-i440fx-rhel7.3.0', u'afterMigrationStatus': u'', u'enableGuestEvents': False, u'vmId': u'a54af7cd-3b89-43c1-82b3-ae0c08d103d3', u'elapsedTimeOffset': 791575.6959090233, u'guestDiskMapping': {u'1fe4d656-8f59-4221-a': {u'name': u'/dev/vda'}}, u'transparentHugePages': u'true', u'timeOffset': u'0', u'cpuType': u'Westmere', u'custom': {u'device_3b6d92fa-999b-40cf-883e-209fa76b1751device_8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920device_83fbbdab-d906-4629-9c6a-29fc59410630': u"VmDevice:{id='VmDeviceId:{deviceId='83fbbdab-d906-4629-9c6a-29fc59410630', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='unix', type='CHANNEL', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=2}', managed='false', plugged='true', readOnly='false', deviceAlias='channel1', customProperties='[]', snapsho
 tId='null', logicalName='null', hostDevice='null'}", u'device_3b6d92fa-999b-40cf-883e-209fa76b1751device_8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920device_83fbbdab-d906-4629-9c6a-29fc59410630device_4bec2c2b-442c-4a7a-9759-a7a13729bc90': u"VmDevice:{id='VmDeviceId:{deviceId='4bec2c2b-442c-4a7a-9759-a7a13729bc90', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='tablet', type='UNKNOWN', specParams='[]', address='{bus=0, type=usb, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='input0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}", u'device_3b6d92fa-999b-40cf-883e-209fa76b1751': u"VmDevice:{id='VmDeviceId:{deviceId='3b6d92fa-999b-40cf-883e-209fa76b1751', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='ide', type='CONTROLLER', specParams='[]', address='{slot=0x01, bus=0x00, domain=0x0000, type=pci, function=0x1}', managed='false', plugged='true', readOnly='false', deviceAlias='ide', customProperties='[]', snapshotId='n
 ull', logicalName='null', hostDevice='null'}", u'device_3b6d92fa-999b-40cf-883e-209fa76b1751device_8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920': u"VmDevice:{id='VmDeviceId:{deviceId='8b7ae8e2-ef0d-45bb-9a99-e33d1b9af920', vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3'}', device='unix', type='CHANNEL', specParams='[]', address='{bus=0, controller=0, type=virtio-serial, port=1}', managed='false', plugged='true', readOnly='false', deviceAlias='channel0', customProperties='[]', snapshotId='null', logicalName='null', hostDevice='null'}"}, u'pauseCode': u'NOERR', u'migrationDest': u'libvirt', u'guestNumaNodes': [{u'nodeIndex': 0, u'cpus': u'0,1', u'memory': u'2096'}], u'smp': u'2', u'vmType': u'kvm', u'smpThreadsPerCore': u'1', u'_srcDomXML': u'<domain type=\'kvm\' id=\'4108\'>\n  <name>bbgpvmas108</name>\n  <uuid>a54af7cd-3b89-43c1-82b3-ae0c08d103d3</uuid>\n  <metadata xmlns:ovirt="http://ovirt.org/vm/tune/1.0">\n    <ovirt:qos/>\n  </metadata>\n  <maxMemory slots=\'16\' unit=\'KiB\'>8585216</maxM
 emory>\n  <memory unit=\'KiB\'>2146304</memory>\n  <currentMemory unit=\'KiB\'>2146304</currentMemory>\n  <vcpu placement=\'static\' current=\'2\'>16</vcpu>\n  <cputune>\n    <shares>1020</shares>\n  </cputune>\n  <resource>\n    <partition>/machine</partition>\n  </resource>\n  <sysinfo type=\'smbios\'>\n    <system>\n      <entry name=\'manufacturer\'>oVirt</entry>\n      <entry name=\'product\'>oVirt Node</entry>\n      <entry name=\'version\'>7-4.1708.el7.centos</entry>\n      <entry name=\'serial\'>DF14F0EB-EAAF-33CB-BC4A-4D90DE3A5EEB</entry>\n      <entry name=\'uuid\'>a54af7cd-3b89-43c1-82b3-ae0c08d103d3</entry>\n    </system>\n  </sysinfo>\n  <os>\n    <type arch=\'x86_64\' machine=\'pc-i440fx-rhel7.3.0\'>hvm</type>\n    <smbios mode=\'sysinfo\'/>\n  </os>\n  <features>\n    <acpi/>\n  </features>\n  <cpu mode=\'custom\' match=\'exact\' check=\'full\'>\n    <model fallback=\'forbid\'>Westmere</model>\n    <topology sockets=\'16\' cores=\'1\' threads=\'1\'/>\n    <feature pol
 icy=\'require\' name=\'vme\'/>\n    <feature policy=\'require\' name=\'pclmuldq\'/>\n    <feature policy=\'require\' name=\'x2apic\'/>\n    <feature policy=\'require\' name=\'hypervisor\'/>\n    <feature policy=\'require\' name=\'arat\'/>\n    <numa>\n      <cell id=\'0\' cpus=\'0-1\' memory=\'2146304\' unit=\'KiB\'/>\n    </numa>\n  </cpu>\n  <clock offset=\'variable\' adjustment=\'0\' basis=\'utc\'>\n    <timer name=\'rtc\' tickpolicy=\'catchup\'/>\n    <timer name=\'pit\' tickpolicy=\'delay\'/>\n    <timer name=\'hpet\' present=\'no\'/>\n  </clock>\n  <on_poweroff>destroy</on_poweroff>\n  <on_reboot>restart</on_reboot>\n  <on_crash>destroy</on_crash>\n  <devices>\n    <emulator>/usr/libexec/qemu-kvm</emulator>\n    <disk type=\'file\' device=\'cdrom\'>\n      <driver name=\'qemu\' type=\'raw\'/>\n      <source startupPolicy=\'optional\'/>\n      <backingStore/>\n      <target dev=\'hdc\' bus=\'ide\'/>\n      <readonly/>\n      <alias name=\'ide0-1-0\'/>\n      <address type=\'dri
 ve\' controller=\'0\' bus=\'1\' target=\'0\' unit=\'0\'/>\n    </disk>\n    <disk type=\'block\' device=\'disk\' snapshot=\'no\'>\n      <driver name=\'qemu\' type=\'raw\' cache=\'none\' error_policy=\'stop\' io=\'native\'/>\n      <source dev=\'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289\'/>\n      <backingStore/>\n      <target dev=\'vda\' bus=\'virtio\'/>\n      <serial>1fe4d656-8f59-4221-a859-2f7bcbdb43c3</serial>\n      <boot order=\'1\'/>\n      <alias name=\'virtio-disk0\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x05\' function=\'0x0\'/>\n    </disk>\n    <controller type=\'usb\' index=\'0\' model=\'piix3-uhci\'>\n      <alias name=\'usb\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x01\' function=\'0x2\'/>\n    </controller>\n    <controller type=\'virtio-serial\' index=\'0\' ports=\'16\'>\n   
    <alias name=\'virtio-serial0\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x04\' function=\'0x0\'/>\n    </controller>\n    <controller type=\'pci\' index=\'0\' model=\'pci-root\'>\n      <alias name=\'pci.0\'/>\n    </controller>\n    <controller type=\'ide\' index=\'0\'>\n      <alias name=\'ide\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x01\' function=\'0x1\'/>\n    </controller>\n    <interface type=\'bridge\'>\n      <mac address=\'00:16:36:4f:bd:df\'/>\n      <source bridge=\'VMs\'/>\n      <target dev=\'vnet16\'/>\n      <model type=\'virtio\'/>\n      <filterref filter=\'vdsm-no-mac-spoofing\'/>\n      <link state=\'up\'/>\n      <alias name=\'net0\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x03\' function=\'0x0\'/>\n    </interface>\n    <interface type=\'bridge\'>\n      <mac address=\'00:1a:4a:bd:ed:22\'/>\n      <source bridge=\'Backup\'/>\n      <target dev=\'vnet17\'/>\n      <model t
 ype=\'virtio\'/>\n      <filterref filter=\'vdsm-no-mac-spoofing\'/>\n      <link state=\'up\'/>\n      <alias name=\'net1\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x07\' function=\'0x0\'/>\n    </interface>\n    <channel type=\'unix\'>\n      <source mode=\'bind\' path=\'/var/lib/libvirt/qemu/channels/a54af7cd-3b89-43c1-82b3-ae0c08d103d3.com.redhat.rhevm.vdsm\'/>\n      <target type=\'virtio\' name=\'com.redhat.rhevm.vdsm\' state=\'connected\'/>\n      <alias name=\'channel0\'/>\n      <address type=\'virtio-serial\' controller=\'0\' bus=\'0\' port=\'1\'/>\n    </channel>\n    <channel type=\'unix\'>\n      <source mode=\'bind\' path=\'/var/lib/libvirt/qemu/channels/a54af7cd-3b89-43c1-82b3-ae0c08d103d3.org.qemu.guest_agent.0\'/>\n      <target type=\'virtio\' name=\'org.qemu.guest_agent.0\' state=\'disconnected\'/>\n      <alias name=\'channel1\'/>\n      <address type=\'virtio-serial\' controller=\'0\' bus=\'0\' port=\'2\'/>\n    </channel>\n    <inpu
 t type=\'tablet\' bus=\'usb\'>\n      <alias name=\'input0\'/>\n      <address type=\'usb\' bus=\'0\' port=\'1\'/>\n    </input>\n    <input type=\'mouse\' bus=\'ps2\'>\n      <alias name=\'input1\'/>\n    </input>\n    <input type=\'keyboard\' bus=\'ps2\'>\n      <alias name=\'input2\'/>\n    </input>\n    <graphics type=\'vnc\' port=\'5907\' autoport=\'yes\' listen=\'10.157.8.40\' keymap=\'de\' passwdValidTo=\'1970-01-01T00:00:01\'>\n      <listen type=\'network\' address=\'10.157.8.40\' network=\'vdsm-ovirtmgmt\'/>\n    </graphics>\n    <video>\n      <model type=\'vga\' vram=\'16384\' heads=\'1\' primary=\'yes\'/>\n      <alias name=\'video0\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x02\' function=\'0x0\'/>\n    </video>\n    <memballoon model=\'virtio\'>\n      <alias name=\'balloon0\'/>\n      <address type=\'pci\' domain=\'0x0000\' bus=\'0x00\' slot=\'0x06\' function=\'0x0\'/>\n    </memballoon>\n  </devices>\n  <seclabel type=\'dynamic\' model=\
 'selinux\' relabel=\'yes\'>\n    <label>system_u:system_r:svirt_t:s0:c76,c549</label>\n    <imagelabel>system_u:object_r:svirt_image_t:s0:c76,c549</imagelabel>\n  </seclabel>\n  <seclabel type=\'dynamic\' model=\'dac\' relabel=\'yes\'>\n    <label>+107:+107</label>\n    <imagelabel>+107:+107</imagelabel>\n  </seclabel>\n</domain>\n', u'memSize': 2096, u'smpCoresPerSocket': u'1', u'vmName': u'bbgpvmas108', u'nice': u'0', u'username': u'None', u'maxMemSize': 8384, u'bootMenuEnable': u'false', u'tabletEnable': u'true', u'smartcardEnable': u'false', u'clientIp': u'', u'guestFQDN': u'bbgpvmas108-test.bbg.michelin.com', u'guestAgentAPIVersion': 1, u'kvmEnable': u'true', u'pitReinjection': u'false', u'displayNetwork': u'ovirtmgmt', u'devices': [{u'target': 2146304, u'alias': u'balloon0', u'specParams': {u'model': u'virtio'}, u'deviceId': u'046ac3a6-864d-4d70-9822-484c99b833e5', u'address': {u'function': u'0x0', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'slot': u'0x06'}, u'de
 vice': u'memballoon', u'type': u'balloon'}, {u'index': u'0', u'alias': u'usb', u'specParams': {}, u'deviceId': u'a24b60c7-dbd0-416d-8791-43e101aeaccb', u'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}, u'device': u'usb', u'model': u'piix3-uhci', u'type': u'controller'}, {u'alias': u'virtio-serial0', u'specParams': {}, u'deviceId': u'c17ebc13-fa7e-4308-937d-77c5e5d4dda9', u'address': {u'slot': u'0x04', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'virtio-serial', u'type': u'controller'}, {u'alias': u'video0', u'specParams': {u'vram': u'16384'}, u'deviceId': u'240119c6-b3c2-4d08-881b-39ff6fd8ff16', u'address': {u'slot': u'0x02', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'vga', u'type': u'video'}, {u'device': u'vnc', u'specParams': {u'displayNetwork': u'ovirtmgmt', u'keyMap': u'de', u'displayIp': u'10.157.8.40'}, u'type': u'graphics', u
 'deviceId': u'00000026-0026-0026-0026-000000000175', u'port': u'5907'}, {u'nicModel': u'pv', u'macAddr': u'00:16:36:4f:bd:df', u'linkActive': True, u'network': u'VMs', u'filterParameters': [], u'alias': u'net0', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, u'deviceId': u'f4a97f85-b60b-4989-81c0-0b3dc1a25be4', u'address': {u'slot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', u'name': u'vnet16'}, {u'nicModel': u'pv', u'macAddr': u'00:1a:4a:bd:ed:22', u'linkActive': True, u'network': u'Backup', u'filterParameters': [], u'alias': u'net1', u'filter': u'vdsm-no-mac-spoofing', u'specParams': {u'inbound': {}, u'outbound': {}}, u'deviceId': u'84ce9f2d-fe1b-4529-9998-27d44573947f', u'address': {u'slot': u'0x07', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'bridge', u'type': u'interface', u'name': u'vnet17'}, {u'index': u
 '2', u'iface': u'ide', u'name': u'hdc', u'alias': u'ide0-1-0', u'specParams': {u'path': u''}, u'readonly': u'True', u'deviceId': u'd9cd7283-a7df-493f-8903-295baf2c8f37', u'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, u'device': u'cdrom', u'shared': u'false', u'path': u'', u'type': u'disk'}, {u'poolID': u'5849b030-626e-47cb-ad90-3ce782d831b3', u'volumeInfo': {u'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'volType': u'path'}, u'index': 0, u'iface': u'virtio', u'apparentsize': u'53687091200', u'alias': u'virtio-disk0', u'imageID': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', u'readonly': u'False', u'shared': u'false', u'truesize': u'53687091200', u'type': u'disk', u'domainID': u'68b8aaff-770d-4a08-800b-0c15e94efaa8', u'reqsize': u'0', u'format': u'raw', u'deviceId': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', u'address': {u'sl
 ot': u'0x05', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, u'device': u'disk', u'path': u'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'propagateErrors': u'off', u'optional': u'false', u'name': u'vda', u'bootOrder': u'1', u'volumeID': u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'diskType': u'block', u'specParams': {}, u'discard': False, u'volumeChain': [{u'domainID': u'68b8aaff-770d-4a08-800b-0c15e94efaa8', u'leaseOffset': 164626432, u'volumeID': u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', u'leasePath': u'/dev/68b8aaff-770d-4a08-800b-0c15e94efaa8/leases', u'imageID': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', u'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289'}]}, {u'device': u'ide', u'alias': u'ide', u'type': u'controller
 ', u'address': {u'slot': u'0x01', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'}}, {u'device': u'unix', u'alias': u'channel0', u'type': u'channel', u'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'1'}}, {u'device': u'unix', u'alias': u'channel1', u'type': u'channel', u'address': {u'bus': u'0', u'controller': u'0', u'type': u'virtio-serial', u'port': u'2'}}, {u'device': u'tablet', u'alias': u'input0', u'type': u'input', u'address': {u'bus': u'0', u'type': u'usb', u'port': u'1'}}], u'memGuaranteedSize': 1024, u'maxVCpus': u'16', u'guestIPs': u'10.157.11.88', u'statusTime': u'12083235990', u'maxMemSlots': 16}, recover=False) from=::ffff:10.157.8.40,35732 (api:46)
2018-06-28 12:25:49,278+0200 INFO  (jsonrpc/4) [vdsm.api] FINISH __init__ return=None from=::ffff:10.157.8.40,35732 (api:52)
2018-06-28 12:25:49,281+0200 INFO  (vm/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') VM wrapper has started (vm:1968)
2018-06-28 12:25:49,282+0200 WARN  (vm/a54af7cd) [virt.vm] (vmId='a54af7cd-3b89-43c1-82b3-ae0c08d103d3') Unknown type found, device: '{u'device': u'tablet', u'alias': u'input0', u'type': u'input', u'address': {u'bus': u'0', u'type': u'usb', u'port': u'1'}}' found (vm:452)
2018-06-28 12:25:49,282+0200 INFO  (vm/a54af7cd) [vdsm.api] START getVolumeSize(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', volUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', options=None) from=internal, task_id=83e1bc92-a406-4b05-abc1-ef6c476435e5 (api:46)
2018-06-28 12:25:49,354+0200 INFO  (vm/a54af7cd) [vdsm.api] FINISH getVolumeSize return={'truesize': '53687091200', 'apparentsize': '53687091200'} from=internal, task_id=83e1bc92-a406-4b05-abc1-ef6c476435e5 (api:52)
2018-06-28 12:25:49,355+0200 INFO  (vm/a54af7cd) [vds] prepared volume path:  (clientIF:380)
2018-06-28 12:25:49,356+0200 INFO  (vm/a54af7cd) [vdsm.api] START prepareImage(sdUUID=u'68b8aaff-770d-4a08-800b-0c15e94efaa8', spUUID=u'5849b030-626e-47cb-ad90-3ce782d831b3', imgUUID=u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3', leafUUID=u'fbbd2aac-cb7a-471b-b95f-270ce6d00289', allowIllegal=False) from=internal, task_id=186f0bc0-58e0-48a6-b0bc-c7b9b7dfb19e (api:46)
2018-06-28 12:25:49,428+0200 INFO  (vm/a54af7cd) [storage.LVM] Activating lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['fbbd2aac-cb7a-471b-b95f-270ce6d00289'] (lvm:1295)
2018-06-28 12:25:49,720+0200 INFO  (vm/a54af7cd) [storage.LVM] Refreshing lvs: vg=68b8aaff-770d-4a08-800b-0c15e94efaa8 lvs=['leases'] (lvm:1291)
2018-06-28 12:25:49,720+0200 INFO  (vm/a54af7cd) [storage.LVM] Refreshing LVs (vg=68b8aaff-770d-4a08-800b-0c15e94efaa8, lvs=['leases']) (lvm:1319)
2018-06-28 12:25:49,812+0200 INFO  (vm/a54af7cd) [vdsm.api] FINISH prepareImage return={'info': {'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'volType': 'path'}, 'path': u'/rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'imgVolumesInfo': [{'domainID': u'68b8aaff-770d-4a08-800b-0c15e94efaa8', 'leaseOffset': 164626432, 'path': u'/rhev/data-center/mnt/blockSD/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'volumeID': 'fbbd2aac-cb7a-471b-b95f-270ce6d00289', 'leasePath': '/dev/68b8aaff-770d-4a08-800b-0c15e94efaa8/leases', 'imageID': u'1fe4d656-8f59-4221-a859-2f7bcbdb43c3'}]} from=internal, task_id=186f0bc0-58e0-48a6-b0bc-c7b9b7dfb19e (api:52)
2018-06-28 12:25:49,814+0200 INFO  (vm/a54af7cd) [vds] prepared volume path: /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3/68b8aaff-770d-4a08-800b-0c15e94efaa8/images/1fe4d656-8f59-4221-a859-2f7bcbdb43c3/fbbd2aac-cb7a-471b-b95f-270ce6d00289 (clientIF:380)
2018-06-28 12:25:49,857+0200 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call VM.migrationCreate succeeded in 0.60 seconds (__init__:539)
2018-06-28 12:25:55,791+0200 INFO  (itmap/0) [IOProcessClient] Starting client ioprocess-78498 (__init__:330)
2018-06-28 12:25:55,803+0200 INFO  (ioprocess/3512) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:25:55,804+0200 INFO  (itmap/1) [IOProcessClient] Starting client ioprocess-78499 (__init__:330)
2018-06-28 12:25:55,812+0200 INFO  (itmap/2) [IOProcessClient] Starting client ioprocess-78500 (__init__:330)
2018-06-28 12:25:55,817+0200 INFO  (ioprocess/3527) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:25:55,822+0200 INFO  (ioprocess/3533) [IOProcess] Starting ioprocess (__init__:452)
2018-06-28 12:25:55,832+0200 INFO  (monitor/48055e2) [storage.StorageDomain] Resource namespace 01_img_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:758)
2018-06-28 12:25:55,832+0200 INFO  (monitor/48055e2) [storage.StorageDomain] Resource namespace 02_vol_48055e27-f1ca-466a-8a2c-e191c34f0226 already registered (sd:767)
2018-06-28 12:25:55,836+0200 INFO  (monitor/b5ae41a) [storage.StorageDomain] Resource namespace 01_img_b5ae41ac-7318-4748-9346-b08d8e5a9248 already registered (sd:758)
2018-06-28 12:25:55,836+0200 INFO  (monitor/b5ae41a) [storage.StorageDomain] Resource namespace 02_vol_b5ae41ac-7318-4748-9346-b08d8e5a9248 already registered (sd:767)
2018-06-28 12:25:58,400+0200 INFO  (jsonrpc/5) [vdsm.api] START setBalloonTarget(target=9817245) from=::1,46990 (api:46)
2018-06-28 12:25:58,417+0200 INFO  (jsonrpc/5) [vdsm.api] FINISH setBalloonTarget return={'status': {'message': 'Done', 'code': 0}} from=::1,46990 (api:52)
2018-06-28 12:25:58,417+0200 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call VM.setBalloonTarget succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:58,658+0200 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.02 seconds (__init__:539)
2018-06-28 12:25:59,959+0200 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded in 0.01 seconds (__init__:539)
2018-06-28 12:25:59,979+0200 ERROR (jsonrpc/6) [jsonrpc.JsonRpcServer] Internal server error (__init__:577)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 572, in _handle_request
    res = method(**params)
  File "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 202, in _dynamicMethod
    result = fn(*methodArgs)
  File "/usr/share/vdsm/API.py", line 1454, in getAllVmIoTunePolicies
    io_tune_policies_dict = self._cif.getAllVmIoTunePolicies()
  File "/usr/share/vdsm/clientIF.py", line 454, in getAllVmIoTunePolicies
    'current_values': v.getIoTune()}
  File "/usr/share/vdsm/virt/vm.py", line 2859, in getIoTune
    result = self.getIoTuneResponse()
  File "/usr/share/vdsm/virt/vm.py", line 2878, in getIoTuneResponse
    res = self._dom.blockIoTune(
  File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 47, in __getattr__
    % self.vmid)
NotConnectedError: VM u'a54af7cd-3b89-43c1-82b3-ae0c08d103d3' was not started yet or was shut down
2018-06-28 12:25:59,981+0200 INFO  (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call Host.getAllVmIoTunePolicies failed (error -32603) in 0.00 seconds (__init__:539)
2018-06-28 12:26:02,275+0200 INFO  (periodic/6160) [vdsm.api] START repoStats(options=None) from=internal, task_id=0fc8eaea-80b5-4a7d-aa70-78681613e5c6 (api:46)
2018-06-28 12:26:02,276+0200 INFO  (periodic/6160) [vdsm.api] FINISH repoStats return={u'48055e27-f1ca-466a-8a2c-e191c34f0226': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000506027', 'lastCheck': '0.9', 'valid': True}, u'b5ae41ac-7318-4748-9346-b08d8e5a9248': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000616951', 'lastCheck': '4.0', 'valid': True}, u'68b8aaff-770d-4a08-800b-0c15e94efaa8': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000293051', 'lastCheck': '4.1', 'valid': True}, u'8924ce27-14b9-4ef8-ad10-8c0ebb83e2e5': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000381327', 'lastCheck': '1.9', 'valid': True}} from=internal, task_id=0fc8eaea-80b5-4a7d-aa70-78681613e5c6 (api:52)

[ovirt-users] Re: Unable to do Live Migration

rni＠chef.net