Created attachment 1281192 [details]
logs_engine_hosts

Description of problem:
Failed to migrate VM in pause mode.

Version-Release number of selected component (if applicable):
RHVM Version: 4.1.2.2-0.1.el7
Host:
OS Version:RHEL - 7.3 - 7.el7
Kernel Version:3.10.0 - 327.28.3.el7.x86_64
KVM Version:2.6.0 - 28.el7_3.9
LIBVIRT Version:libvirt-2.0.0-10.el7_3.5
VDSM Version:vdsm-4.19.15-1.el7ev

How reproducible:
all the time


Steps to Reproduce:
1. Start Vm in pause mode
2. Migrate VM


Actual results:
VM stays on source host, Vm stuck in status 'migrating'.
 

Expected results:
Vm will migrate to second host

Additional info:

Engine log:
2017-05-22 22:49:05,138+03 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-42) [6c557a94-e013-42fd-a6f5-e6b99e8faf41] EVENT_ID: VM_MIGRATION_START(62), Correlation ID: 6c557a94-e013-42fd-a6f5-e6b99e8faf41, Job ID: dac9f0e3-47cc-496c-b9fc-149d20d7ee42, Call Stack: null, Custom Event ID: -1, Message: Migration started (VM: migration_bz, Source: host_mixed_2, Destination: host_mixed_1, User: admin@internal-authz).
2017-05-22 22:49:06,073+03 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-10) [] VM '1660ced8-76eb-40f7-b2f4-ed76d2f82a45'(migration_bz) was unexpectedly detected as 'Paused' on VDS '6201ba3e-056b-47a3-a96f-3e592a76f5dd'(host_mixed_1) (expected on 'af8f8d26-bf17-4fc6-bf53-f7bda9f6691f')
2017-05-22 22:49:06,076+03 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (ForkJoinPool-1-worker-10) [] VMs initialization finished for Host: 'host_mixed_1:6201ba3e-056b-47a3-a96f-3e592a76f5dd'


Source host:

2017-05-22 22:49:02,753+0300 INFO  (jsonrpc/0) [vdsm.api] START migrate(params={'incomingLimit': 2, 'tunneled': 'false', 'dstqemu': '10.35.160.165', 'autoConverge': 'false', 'src': 'puma43.scl.lab.tlv.redhat.com', 'enableGuestEvents': False, 'dst': 'puma42.scl.lab.tlv.redhat.com:54321', 'vmId': '1660ced8-76eb-40f7-b2f4-ed76d2f82a45', 'abortOnError': 'true', 'outgoingLimit': 2, 'compressed': 'false', 'method': 'online', 'mode': 'remote'}) (api:39)
2017-05-22 22:49:02,754+0300 INFO  (jsonrpc/0) [vdsm.api] FINISH migrate return={'status': {'message': 'Migration in progress', 'code': 0}, 'progress': 0} (api:45)
2017-05-22 22:49:02,754+0300 INFO  (jsonrpc/0) [jsonrpc.JsonRpcServer] RPC call VM.migrate succeeded in 0.00 seconds (__init__:533)
2017-05-22 22:49:03,192+0300 INFO  (migsrc/1660ced8) [virt.vm] (vmId='1660ced8-76eb-40f7-b2f4-ed76d2f82a45') Creation of destination VM took: 0 seconds (migration:455)
2017-05-22 22:49:03,192+0300 INFO  (migsrc/1660ced8) [virt.vm] (vmId='1660ced8-76eb-40f7-b2f4-ed76d2f82a45') starting migration to qemu+tls://puma42.scl.lab.tlv.redhat.com/system with miguri tcp://10.35.160.165 (migration:480)
2017-05-22 22:49:05,112+0300 INFO  (migsrc/1660ced8) [virt.vm] (vmId='1660ced8-76eb-40f7-b2f4-ed76d2f82a45') migration took 1 seconds to complete (migration:492)
2017-05-22 22:49:05,115+0300 INFO  (migsrc/1660ced8) [virt.vm] (vmId='1660ced8-76eb-40f7-b2f4-ed76d2f82a45') Changed state to Down: Migration succeeded (code=4) (vm:1222)
2017-05-22 22:49:05,115+0300 INFO  (migsrc/1660ced8) [virt.vm] (vmId='1660ced8-76eb-40f7-b2f4-ed76d2f82a45') Stopping connection (guestagent:430)
2017-05-22 22:49:06,073+0300 INFO  (jsonrpc/7) [dispatcher] Run and protect: repoStats(options=None) (logUtils:51)
2017-05-22 22:49:06,073+0300 INFO  (jsonrpc/7) [dispatcher] Run and protect: repoStats, Return response: {'d31037e5-0d45-4306-975b-73eea845ae86': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000326181', 'lastCheck': '2.1', 'valid': True}, '62430d5b-8c57-4147-92dc-1ea907963ff9': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000275031', 'lastCheck': '0.9', 'valid': True}, 'ae085d06-f174-4986-9985-d948f5dc7a5c': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000412139', 'lastCheck': '0.8', 'valid': True}, 'bbb7e15c-7884-4d52-8bc4-d2de58e21a78': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000263982', 'lastCheck': '4.5', 'valid': True}} (logUtils:54)
2017-05-22 22:49:06,083+0300 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Host.getStats succeeded in 0.01 seconds (__init__:533)
2017-05-22 22:49:06,085+0300 INFO  (jsonrpc/1) [vdsm.api] START destroy(gracefulAttempts=1) (api:39)