5:58 a.m.
And this is the vdsm log from vmhost04:
Thread-6320715::DEBUG::2017-03-24
11:38:02,224::migration::188::virt.vm::(_setupVdsConnection)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Initiating connection with
destination
Thread-6320715::DEBUG::2017-03-24
11:38:02,239::migration::200::virt.vm::(_setupVdsConnection)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Destination server is:
vm08.ovirt.internal:54321
Thread-6320715::DEBUG::2017-03-24
11:38:02,241::migration::246::virt.vm::(_prepareGuest)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration started
Thread-6320715::DEBUG::2017-03-24
11:38:02,253::guestagent::502::virt.vm::(send_lifecycle_event)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::send_lifecycle_event
before_migration called
Thread-6320715::DEBUG::2017-03-24
11:38:02,319::migration::353::virt.vm::(run)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::migration semaphore acquired
after 2 seconds
Thread-6320715::INFO::2017-03-24
11:38:02,950::migration::407::virt.vm::(_startUnderlyingMigration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Creation of destination VM
took: 0 seconds
Thread-6320715::INFO::2017-03-24
11:38:02,951::migration::429::virt.vm::(_startUnderlyingMigration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::starting migration to
qemu+tls://vm08.ovirt.internal/system with miguri tcp://192.168.10.107
Thread-6320715::DEBUG::2017-03-24
11:38:02,951::migration::494::virt.vm::(_perform_with_conv_schedule)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::performing migration with conv
schedule
Thread-6320717::DEBUG::2017-03-24
11:38:02,952::migration::620::virt.vm::(run)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::starting migration monitor
thread
Thread-6320717::DEBUG::2017-03-24
11:38:02,952::migration::739::virt.vm::(_execute_action_with_params)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Setting downtime to 100
Thread-6320717::INFO::2017-03-24
11:38:12,959::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 10 seconds
elapsed, 8% of data processed, total data: 16456MB, processed data: 483MB,
remaining data: 15157MB, transfer speed 52MBps, zero pages: 209524MB,
compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:38:22,963::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 20 seconds
elapsed, 13% of data processed, total data: 16456MB, processed data:
1003MB, remaining data: 14469MB, transfer speed 51MBps, zero pages:
252844MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:38:32,966::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 30 seconds
elapsed, 16% of data processed, total data: 16456MB, processed data:
1524MB, remaining data: 13839MB, transfer speed 52MBps, zero pages:
281344MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:38:42,969::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 40 seconds
elapsed, 42% of data processed, total data: 16456MB, processed data:
2040MB, remaining data: 9685MB, transfer speed 52MBps, zero pages:
1214867MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:38:52,973::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 50 seconds
elapsed, 46% of data processed, total data: 16456MB, processed data:
2560MB, remaining data: 8944MB, transfer speed 52MBps, zero pages:
1271798MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:39:02,976::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 60 seconds
elapsed, 51% of data processed, total data: 16456MB, processed data:
3080MB, remaining data: 8148MB, transfer speed 52MBps, zero pages:
1342711MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:39:12,979::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 70 seconds
elapsed, 56% of data processed, total data: 16456MB, processed data:
3600MB, remaining data: 7353MB, transfer speed 52MBps, zero pages:
1413447MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:39:22,984::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 80 seconds
elapsed, 59% of data processed, total data: 16456MB, processed data:
4120MB, remaining data: 6755MB, transfer speed 52MBps, zero pages:
1433707MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:39:32,987::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 90 seconds
elapsed, 64% of data processed, total data: 16456MB, processed data:
4641MB, remaining data: 6032MB, transfer speed 52MBps, zero pages:
1486003MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:39:42,990::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 100
seconds elapsed, 67% of data processed, total data: 16456MB, processed
data: 5161MB, remaining data: 5457MB, transfer speed 52MBps, zero pages:
1500433MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:39:52,993::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 110
seconds elapsed, 71% of data processed, total data: 16456MB, processed
data: 5681MB, remaining data: 4836MB, transfer speed 52MBps, zero pages:
1526530MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:40:02,996::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 120
seconds elapsed, 75% of data processed, total data: 16456MB, processed
data: 6201MB, remaining data: 4220MB, transfer speed 52MBps, zero pages:
1551477MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:40:12,999::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 130
seconds elapsed, 79% of data processed, total data: 16456MB, processed
data: 6721MB, remaining data: 3574MB, transfer speed 52MBps, zero pages:
1583895MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:40:23,002::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 140
seconds elapsed, 82% of data processed, total data: 16456MB, processed
data: 7242MB, remaining data: 2979MB, transfer speed 52MBps, zero pages:
1603409MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:40:33,005::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 150
seconds elapsed, 86% of data processed, total data: 16456MB, processed
data: 7762MB, remaining data: 2382MB, transfer speed 52MBps, zero pages:
1623448MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:40:43,008::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 160
seconds elapsed, 90% of data processed, total data: 16456MB, processed
data: 8282MB, remaining data: 1736MB, transfer speed 52MBps, zero pages:
1655832MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:40:53,011::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 170
seconds elapsed, 93% of data processed, total data: 16456MB, processed
data: 8802MB, remaining data: 1166MB, transfer speed 52MBps, zero pages:
1668937MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:41:03,014::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 180
seconds elapsed, 97% of data processed, total data: 16456MB, processed
data: 9322MB, remaining data: 581MB, transfer speed 52MBps, zero pages:
1685861MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
Thread-6320717::INFO::2017-03-24
11:41:13,019::migration::712::virt.vm::(monitor_migration)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Migration Progress: 190
seconds elapsed, 98% of data processed, total data: 16456MB, processed
data: 9842MB, remaining data: 386MB, transfer speed 52MBps, zero pages:
1718676MB, compressed: 0MB, dirty rate: -1, memory iteration: -1
libvirtEventLoop::DEBUG::2017-03-24
11:41:21,007::vm::4291::virt.vm::(onLibvirtLifecycleEvent)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::event Suspended detail 0
opaque None
libvirtEventLoop::INFO::2017-03-24
11:41:21,025::vm::4815::virt.vm::(_logGuestCpuStatus)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::CPU stopped: onSuspend
libvirtEventLoop::DEBUG::2017-03-24
11:41:21,069::vm::4291::virt.vm::(onLibvirtLifecycleEvent)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::event Resumed detail 0 opaque
None
libvirtEventLoop::INFO::2017-03-24
11:41:21,069::vm::4815::virt.vm::(_logGuestCpuStatus)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::CPU running: onResume
Thread-6320715::DEBUG::2017-03-24
11:41:21,224::migration::715::virt.vm::(stop)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::stopping migration monitor
thread
Thread-6320715::ERROR::2017-03-24
11:41:21,225::migration::252::virt.vm::(_recover)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::operation failed: migration
job: unexpectedly failed
Thread-6320717::DEBUG::2017-03-24
11:41:21,226::migration::629::virt.vm::(run)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::stopped migration monitor
thread
Thread-6320715::DEBUG::2017-03-24
11:41:21,257::guestagent::502::virt.vm::(send_lifecycle_event)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::send_lifecycle_event
after_migration called
Thread-6320715::DEBUG::2017-03-24
11:41:21,284::__init__::209::jsonrpc.Notification::(emit) Sending event
{"params": {"notify_time": 19498739270,
"4f627cc1-9b52-4eef-bf3a-c02e8a6303b8": {"status": "Migration
Source"}},
"jsonrpc": "2.0", "method":
"|virt|VM_status|4f627cc1-9b52-4eef-bf3a-c02e8a6303b8"}
Thread-6320715::ERROR::2017-03-24
11:41:21,285::migration::381::virt.vm::(run)
vmId=`4f627cc1-9b52-4eef-bf3a-c02e8a6303b8`::Failed to migrate
jsonrpc.Executor/6::DEBUG::2017-03-24
11:41:29,161::__init__::530::jsonrpc.JsonRpcServer::(_handle_request)
Calling 'VM.getMigrationStatus' in bridge with {u'vmID':
u'4f627cc1-9b52-4eef-bf3a-c02e8a6303b8'}
2017-03-24 11:54 GMT+01:00 Davide Ferrari <davide(a)billymob.com>:
Helo
I have a VM on a host that seems it cannot be live-migrated away. I'm
trying to migrate it to another (superior) cluster but please consider:
- VM isn't receiving too much tarffic and is not doing much at all
- I've already successfully live migrated other VMs from this host to the
same other cluster
looking through engine.log I cannot see anything interesting a aprt from
the generic ( I grepped for the job ID)
2017-03-24 10:30:52,186 INFO [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-42)
[20518310] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Migration started (VM:
druid-co01., Source: vmhost04, Destination: vmhost06, User:
admin@internal-authz).
2017-03-24 10:34:28,072 WARN [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-2)
[6d6a3a53] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Failed to migrate VM
druid-co01. to Host vmhost06 . Trying to migrate to another Host.
2017-03-24 10:34:28,676 INFO [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-2)
[6d6a3a53] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Migration started (VM:
druid-co01., Source: vmhost04, Destination: vmhost11, User:
admin@internal-authz).
2017-03-24 10:37:59,097 WARN [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-40)
[779e9773] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Failed to migrate VM
druid-co01. to Host vmhost11 . Trying to migrate to another Host.
2017-03-24 10:38:00,626 INFO [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-40)
[779e9773] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Migration started (VM:
druid-co01, Source: vmhost04, Destination: vmhost08, User:
admin@internal-authz).
2017-03-24 10:41:29,441 WARN [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-42)
[6f032492] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Failed to migrate VM
druid-co01 to Host vmhost08 . Trying to migrate to another Host.
2017-03-24 10:41:29,488 ERROR [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-42)
[6f032492] Correlation ID: 20518310, Job ID: 039f0694-3e05-4f93-993d-9e7383047873,
Call Stack: null, Custom Event ID: -1, Message: Migration failed (VM:
druid-co01, Source: vmhost04).
--
Davide Ferrari
Senior Systems Engineer
--
Davide Ferrari
Senior Systems Engineer