RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 884703 - [vdsm] [TEXT] VM migration with SPICE USB device is failing with bad ERROR message
Summary: [vdsm] [TEXT] VM migration with SPICE USB device is failing with bad ERROR me...
Keywords:
Status: CLOSED DUPLICATE of bug 889551
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: vdsm
Version: 6.3
Hardware: x86_64
OS: Linux
unspecified
low
Target Milestone: rc
: ---
Assignee: Arik
QA Contact: Haim
URL:
Whiteboard: virt
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-12-06 15:34 UTC by Jiri Belka
Modified: 2013-01-13 16:29 UTC (History)
11 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-01-13 16:29:14 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
engine.log, server.log, vdsm.log.2, libvirt.log.1 (1.54 MB, application/x-xz)
2012-12-07 08:38 UTC, Jiri Belka 		no flags Details
View All

Description Jiri Belka 2012-12-06 15:34:02 UTC 
Description of problem:

I tried (by mistake) migrate a VM with USB 'Native' support and got useless failure message:

VM rhel6_ws_32bit is down. Exit message: Domain not found: no domain with matching uuid '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c'.

'Migration is NOT currently supported using SPICE Native USB redirection
Advanced Parameters' is visible in VM->Edit->Console popup but failure message tells nothing to the user.

I would expect some useful failure message.

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

SI24.5 + vdsm44.1

How reproducible:
100%

Steps to Reproduce:
1. Have a VM with USB 'Native' support.
2. Try to migrate.
3. Check in Web admin portal the failure message.
  
Actual results:

Useless failure message.

Expected results:

Useful failure message.

Additional info:

See logs below which make issue even more confusing.

web admin portal
================

2012-Dec-06, 16:09
VM rhel6_ws_32bit is down. Exit message: Domain not found: no domain with matching uuid '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c'.
   
2012-Dec-06, 16:09
Starting migration of VM rhel6_ws_32bit from Host dell-r210ii-04 to Host dell-r210ii-03 (User: admin@internal.).

engine.log
==========

2012-12-06 16:09:39,757 INFO  [org.ovirt.engine.core.bll.MigrateVmCommand] (pool-3-thread-50) [791542cc] Running command: MigrateVmCommand internal: false. Entities affected :  ID: 2545aff1-dde2-4ce1-9de6-da6e82e8fa5c Type: VM
2012-12-06 16:09:39,770 INFO  [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (pool-3-thread-50) [791542cc] START, MigrateVDSCommand(HostName = dell-r210ii-04, HostId = fb65e1d2-3a3a-11e2-9003-001a4a013f3c, vmId=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c, srcHost=dell-r210ii-04.rhev.lab.eng.brq.redhat.com, dstVdsId=fe170110-34a7-11e2-b21d-001a4a013f3c, dstHost=dell-r210ii-03.rhev.lab.eng.brq.redhat.com:54321, migrationMethod=ONLINE), log id: 362aff5c
2012-12-06 16:09:39,771 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (pool-3-thread-50) [791542cc] VdsBroker::migrate::Entered (vm_guid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c, srcHost=dell-r210ii-04.rhev.lab.eng.brq.redhat.com, dstHost=dell-r210ii-03.rhev.lab.eng.brq.redhat.com:54321,  method=online
2012-12-06 16:09:39,771 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (pool-3-thread-50) [791542cc] START, MigrateBrokerVDSCommand(HostName = dell-r210ii-04, HostId = fb65e1d2-3a3a-11e2-9003-001a4a013f3c, vmId=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c, srcHost=dell-r210ii-04.rhev.lab.eng.brq.redhat.com, dstVdsId=fe170110-34a7-11e2-b21d-001a4a013f3c, dstHost=dell-r210ii-03.rhev.lab.eng.brq.redhat.com:54321, migrationMethod=ONLINE), log id: 53d44458
2012-12-06 16:09:39,792 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (pool-3-thread-50) [791542cc] FINISH, MigrateBrokerVDSCommand, log id: 53d44458
2012-12-06 16:09:39,807 INFO  [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (pool-3-thread-50) [791542cc] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 362aff5c
2012-12-06 16:09:47,043 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-62) START, DestroyVDSCommand(HostName = dell-r210ii-03, HostId = fe170110-34a7-11e2-b21d-001a4a013f3c, vmId=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c, force=false, secondsToWait=0, gracefully=false), log id: 1fc630ff
2012-12-06 16:09:51,663 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (QuartzScheduler_Worker-62) Failed in DestroyVDS method
2012-12-06 16:09:51,663 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (QuartzScheduler_Worker-62) Error code noVM and error message VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Virtual machine does not exist
2012-12-06 16:09:51,664 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (QuartzScheduler_Worker-62) Command org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand return value 
 Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusOnlyReturnForXmlRpc
mStatus                       Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusForXmlRpc
mCode                         1
mMessage                      Virtual machine does not exist


2012-12-06 16:09:51,664 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (QuartzScheduler_Worker-62) HostName = dell-r210ii-03
2012-12-06 16:09:51,664 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (QuartzScheduler_Worker-62) Command DestroyVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Virtual machine does not exist
2012-12-06 16:09:51,664 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-62) FINISH, DestroyVDSCommand, log id: 1fc630ff
2012-12-06 16:09:51,710 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-62) vds::refreshVmList vm id 2545aff1-dde2-4ce1-9de6-da6e82e8fa5c status = Down on vds dell-r210ii-03 ignoring it in the refresh until migration is done
2012-12-06 16:09:52,960 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-30) VM rhel6_ws_32bit 2545aff1-dde2-4ce1-9de6-da6e82e8fa5c moved from MigratingFrom --> Up
2012-12-06 16:09:52,960 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-30) adding VM 2545aff1-dde2-4ce1-9de6-da6e82e8fa5c to re-run list
2012-12-06 16:09:52,973 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-30) Rerun vm 2545aff1-dde2-4ce1-9de6-da6e82e8fa5c. Called from vds dell-r210ii-04
2012-12-06 16:10:00,000 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-42) Checking autorecoverable hosts
2012-12-06 16:10:00,004 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-42) Autorecovering 0 hosts
2012-12-06 16:10:00,004 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-42) Checking autorecoverable hosts done
2012-12-06 16:10:00,004 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-42) Autorecovering storage domains is disabled, skipping

vdsm.log
========

Thread-3058::DEBUG::2012-12-06 16:09:07,372::task::588::TaskManager.Task::(_updateState) Task=`e5ca3f13-0fea-4de1-bf1e-46cfcb3cc142`::moving from state init -> state preparing
Thread-3058::INFO::2012-12-06 16:09:07,373::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3058::INFO::2012-12-06 16:09:07,373::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00119090080261', 'lastCheck': '0.7', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.000998973846436', 'lastCheck': '0.7', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00122690200806', 'lastCheck': '9.1', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00117588043213', 'lastCheck': '0.7', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00128102302551', 'lastCheck': '9.3', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00176692008972', 'lastCheck': '9.8', 'code': 0, 'valid': True}}
Thread-3058::DEBUG::2012-12-06 16:09:07,373::task::1172::TaskManager.Task::(prepare) Task=`e5ca3f13-0fea-4de1-bf1e-46cfcb3cc142`::finished: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00119090080261', 'lastCheck': '0.7', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.000998973846436', 'lastCheck': '0.7', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00122690200806', 'lastCheck': '9.1', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00117588043213', 'lastCheck': '0.7', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00128102302551', 'lastCheck': '9.3', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00176692008972', 'lastCheck': '9.8', 'code': 0, 'valid': True}}
Thread-3058::DEBUG::2012-12-06 16:09:07,373::task::588::TaskManager.Task::(_updateState) Task=`e5ca3f13-0fea-4de1-bf1e-46cfcb3cc142`::moving from state preparing -> state finished
Thread-3058::DEBUG::2012-12-06 16:09:07,374::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3058::DEBUG::2012-12-06 16:09:07,374::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3058::DEBUG::2012-12-06 16:09:07,374::task::978::TaskManager.Task::(_decref) Task=`e5ca3f13-0fea-4de1-bf1e-46cfcb3cc142`::ref 0 aborting False
Thread-3059::DEBUG::2012-12-06 16:09:07,397::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3064::DEBUG::2012-12-06 16:09:17,665::task::588::TaskManager.Task::(_updateState) Task=`6993d14a-0913-4022-88eb-ffdc28ee330a`::moving from state init -> state preparing
Thread-3064::INFO::2012-12-06 16:09:17,665::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3064::INFO::2012-12-06 16:09:17,665::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00207090377808', 'lastCheck': '1.0', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00102710723877', 'lastCheck': '1.0', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00112295150757', 'lastCheck': '9.4', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00137901306152', 'lastCheck': '1.0', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00107288360596', 'lastCheck': '9.5', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00164318084717', 'lastCheck': '0.1', 'code': 0, 'valid': True}}
Thread-3064::DEBUG::2012-12-06 16:09:17,665::task::1172::TaskManager.Task::(prepare) Task=`6993d14a-0913-4022-88eb-ffdc28ee330a`::finished: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00207090377808', 'lastCheck': '1.0', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00102710723877', 'lastCheck': '1.0', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00112295150757', 'lastCheck': '9.4', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00137901306152', 'lastCheck': '1.0', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00107288360596', 'lastCheck': '9.5', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00164318084717', 'lastCheck': '0.1', 'code': 0, 'valid': True}}
Thread-3064::DEBUG::2012-12-06 16:09:17,666::task::588::TaskManager.Task::(_updateState) Task=`6993d14a-0913-4022-88eb-ffdc28ee330a`::moving from state preparing -> state finished
Thread-3064::DEBUG::2012-12-06 16:09:17,666::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3064::DEBUG::2012-12-06 16:09:17,666::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3064::DEBUG::2012-12-06 16:09:17,666::task::978::TaskManager.Task::(_decref) Task=`6993d14a-0913-4022-88eb-ffdc28ee330a`::ref 0 aborting False
Thread-3065::DEBUG::2012-12-06 16:09:17,688::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
VM Channels Listener::DEBUG::2012-12-06 16:09:27,838::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 82.
Thread-3070::DEBUG::2012-12-06 16:09:27,973::task::588::TaskManager.Task::(_updateState) Task=`93568f18-5643-4655-b84d-62f1b1efb1e6`::moving from state init -> state preparing
Thread-3070::INFO::2012-12-06 16:09:27,973::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3070::INFO::2012-12-06 16:09:27,974::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00197100639343', 'lastCheck': '1.3', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00104403495789', 'lastCheck': '1.3', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00123906135559', 'lastCheck': '9.7', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00113487243652', 'lastCheck': '1.3', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00124287605286', 'lastCheck': '9.8', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.0016028881073', 'lastCheck': '0.4', 'code': 0, 'valid': True}}
Thread-3070::DEBUG::2012-12-06 16:09:27,974::task::1172::TaskManager.Task::(prepare) Task=`93568f18-5643-4655-b84d-62f1b1efb1e6`::finished: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00197100639343', 'lastCheck': '1.3', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00104403495789', 'lastCheck': '1.3', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00123906135559', 'lastCheck': '9.7', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00113487243652', 'lastCheck': '1.3', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00124287605286', 'lastCheck': '9.8', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.0016028881073', 'lastCheck': '0.4', 'code': 0, 'valid': True}}
Thread-3070::DEBUG::2012-12-06 16:09:27,974::task::588::TaskManager.Task::(_updateState) Task=`93568f18-5643-4655-b84d-62f1b1efb1e6`::moving from state preparing -> state finished
Thread-3070::DEBUG::2012-12-06 16:09:27,974::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3070::DEBUG::2012-12-06 16:09:27,975::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3070::DEBUG::2012-12-06 16:09:27,975::task::978::TaskManager.Task::(_decref) Task=`93568f18-5643-4655-b84d-62f1b1efb1e6`::ref 0 aborting False
Thread-3071::DEBUG::2012-12-06 16:09:27,998::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3076::DEBUG::2012-12-06 16:09:38,341::task::588::TaskManager.Task::(_updateState) Task=`55ce20da-dad1-4981-b396-af2142b67992`::moving from state init -> state preparing
Thread-3076::INFO::2012-12-06 16:09:38,341::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3076::INFO::2012-12-06 16:09:38,341::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00218081474304', 'lastCheck': '1.6', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00118112564087', 'lastCheck': '1.6', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.0011248588562', 'lastCheck': '0.0', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.0010199546814', 'lastCheck': '1.7', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00100517272949', 'lastCheck': '0.2', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00123715400696', 'lastCheck': '0.7', 'code': 0, 'valid': True}}
Thread-3076::DEBUG::2012-12-06 16:09:38,341::task::1172::TaskManager.Task::(prepare) Task=`55ce20da-dad1-4981-b396-af2142b67992`::finished: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00218081474304', 'lastCheck': '1.6', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00118112564087', 'lastCheck': '1.6', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.0011248588562', 'lastCheck': '0.0', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.0010199546814', 'lastCheck': '1.7', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00100517272949', 'lastCheck': '0.2', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00123715400696', 'lastCheck': '0.7', 'code': 0, 'valid': True}}
Thread-3076::DEBUG::2012-12-06 16:09:38,342::task::588::TaskManager.Task::(_updateState) Task=`55ce20da-dad1-4981-b396-af2142b67992`::moving from state preparing -> state finished
Thread-3076::DEBUG::2012-12-06 16:09:38,342::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3076::DEBUG::2012-12-06 16:09:38,342::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3076::DEBUG::2012-12-06 16:09:38,342::task::978::TaskManager.Task::(_decref) Task=`55ce20da-dad1-4981-b396-af2142b67992`::ref 0 aborting False
Thread-3077::DEBUG::2012-12-06 16:09:38,365::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3078::DEBUG::2012-12-06 16:09:39,792::BindingXMLRPC::894::vds::(wrapper) client [10.34.63.75]::call vmMigrate with ({'src': 'dell-r210ii-04.rhev.lab.eng.brq.redhat.com', 'dst': 'dell-r210ii-03.rhev.lab.eng.brq.redhat.com:54321', 'vmId': '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c', 'method': 'online'},) {} flowID [791542cc]
Thread-3078::DEBUG::2012-12-06 16:09:39,792::API::421::vds::(migrate) {'src': 'dell-r210ii-04.rhev.lab.eng.brq.redhat.com', 'dst': 'dell-r210ii-03.rhev.lab.eng.brq.redhat.com:54321', 'vmId': '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c', 'method': 'online'}
Thread-3079::DEBUG::2012-12-06 16:09:39,793::vm::125::vm.Vm::(_setupVdsConnection) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Destination server is: dell-r210ii-03.rhev.lab.eng.brq.redhat.com:54321
Thread-3078::DEBUG::2012-12-06 16:09:39,793::BindingXMLRPC::900::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}}
Thread-3079::DEBUG::2012-12-06 16:09:39,793::vm::127::vm.Vm::(_setupVdsConnection) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Initiating connection with destination
Thread-3081::DEBUG::2012-12-06 16:09:40,553::BindingXMLRPC::894::vds::(wrapper) client [10.34.63.75]::call vmGetStats with ('2545aff1-dde2-4ce1-9de6-da6e82e8fa5c',) {}
Thread-3081::DEBUG::2012-12-06 16:09:40,553::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3081::DEBUG::2012-12-06 16:09:40,554::BindingXMLRPC::900::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Source', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '9243', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-1', 'hash': '-8436048150441222498', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:e0:3f:82', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '16106127360', 'writeLatency': '5343479', 'imageID': '12d760eb-ab9a-4d23-a835-7ee826f843e2', 'flushLatency': '56494', 'readRate': '0.00', 'truesize': '4398075904', 'writeRate': '2241.69'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.30', 'cpuIdle': '97.16', 'elapsedTime': '704', 'vmType': 'kvm', 'cpuSys': '2.40', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
Thread-3083::DEBUG::2012-12-06 16:09:42,614::BindingXMLRPC::894::vds::(wrapper) client [10.34.63.75]::call vmGetStats with ('2545aff1-dde2-4ce1-9de6-da6e82e8fa5c',) {} flowID [452cf2ea]
Thread-3083::DEBUG::2012-12-06 16:09:42,615::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3083::DEBUG::2012-12-06 16:09:42,615::BindingXMLRPC::900::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Source', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '9243', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-1', 'hash': '-8436048150441222498', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:e0:3f:82', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '16106127360', 'writeLatency': '5343479', 'imageID': '12d760eb-ab9a-4d23-a835-7ee826f843e2', 'flushLatency': '56494', 'readRate': '0.00', 'truesize': '4398075904', 'writeRate': '2241.69'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.36', 'cpuIdle': '97.16', 'elapsedTime': '706', 'vmType': 'kvm', 'cpuSys': '2.40', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
Thread-3085::DEBUG::2012-12-06 16:09:44,674::BindingXMLRPC::894::vds::(wrapper) client [10.34.63.75]::call vmGetStats with ('2545aff1-dde2-4ce1-9de6-da6e82e8fa5c',) {}
Thread-3085::DEBUG::2012-12-06 16:09:44,674::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3085::DEBUG::2012-12-06 16:09:44,674::BindingXMLRPC::900::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Source', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '9243', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-1', 'hash': '-8436048150441222498', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:e0:3f:82', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c', 'displayType': 'qxl', 'cpuUser': '0.44', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '16106127360', 'writeLatency': '5343479', 'imageID': '12d760eb-ab9a-4d23-a835-7ee826f843e2', 'flushLatency': '56494', 'readRate': '0.00', 'truesize': '4398075904', 'writeRate': '2241.69'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.42', 'cpuIdle': '97.16', 'elapsedTime': '708', 'vmType': 'kvm', 'cpuSys': '2.40', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
Thread-3079::DEBUG::2012-12-06 16:09:44,851::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3079::DEBUG::2012-12-06 16:09:44,936::vm::175::vm.Vm::(_prepareGuest) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::migration Process begins
Thread-3079::DEBUG::2012-12-06 16:09:45,019::vm::239::vm.Vm::(run) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::migration semaphore acquired
Thread-3079::DEBUG::2012-12-06 16:09:45,274::libvirtvm::454::vm.Vm::(_startUnderlyingMigration) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::starting migration to qemu+tls://dell-r210ii-03.rhev.lab.eng.brq.redhat.com/system
Thread-3086::DEBUG::2012-12-06 16:09:45,275::libvirtvm::352::vm.Vm::(run) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::migration downtime thread started
Thread-3087::DEBUG::2012-12-06 16:09:45,275::libvirtvm::380::vm.Vm::(run) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::starting migration monitor thread
libvirtEventLoop::DEBUG::2012-12-06 16:09:46,534::libvirtvm::2683::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::event Resumed detail 1 opaque None
Thread-3079::DEBUG::2012-12-06 16:09:46,577::libvirtvm::367::vm.Vm::(cancel) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::canceling migration downtime thread
Thread-3079::DEBUG::2012-12-06 16:09:46,577::libvirtvm::417::vm.Vm::(stop) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::stopping migration monitor thread
Thread-3086::DEBUG::2012-12-06 16:09:46,577::libvirtvm::364::vm.Vm::(run) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::migration downtime thread exiting
Thread-3079::ERROR::2012-12-06 16:09:46,578::vm::181::vm.Vm::(_recover) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::internal error unable to execute QEMU command 'migrate': An undefined error has ocurred
Thread-3089::DEBUG::2012-12-06 16:09:48,765::task::588::TaskManager.Task::(_updateState) Task=`d5567790-1f57-4ffb-8c16-ff746d0d9120`::moving from state init -> state preparing
Thread-3089::INFO::2012-12-06 16:09:48,765::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3089::INFO::2012-12-06 16:09:48,766::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00184011459351', 'lastCheck': '2.1', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.000970125198364', 'lastCheck': '2.1', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.000998973846436', 'lastCheck': '0.4', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00106811523438', 'lastCheck': '2.1', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.0010359287262', 'lastCheck': '0.6', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00136995315552', 'lastCheck': '1.1', 'code': 0, 'valid': True}}
Thread-3089::DEBUG::2012-12-06 16:09:48,766::task::1172::TaskManager.Task::(prepare) Task=`d5567790-1f57-4ffb-8c16-ff746d0d9120`::finished: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.00184011459351', 'lastCheck': '2.1', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.000970125198364', 'lastCheck': '2.1', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.000998973846436', 'lastCheck': '0.4', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00106811523438', 'lastCheck': '2.1', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.0010359287262', 'lastCheck': '0.6', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00136995315552', 'lastCheck': '1.1', 'code': 0, 'valid': True}}
Thread-3089::DEBUG::2012-12-06 16:09:48,766::task::588::TaskManager.Task::(_updateState) Task=`d5567790-1f57-4ffb-8c16-ff746d0d9120`::moving from state preparing -> state finished
Thread-3089::DEBUG::2012-12-06 16:09:48,766::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3089::DEBUG::2012-12-06 16:09:48,766::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3089::DEBUG::2012-12-06 16:09:48,767::task::978::TaskManager.Task::(_decref) Task=`d5567790-1f57-4ffb-8c16-ff746d0d9120`::ref 0 aborting False
Thread-3090::DEBUG::2012-12-06 16:09:48,789::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3079::ERROR::2012-12-06 16:09:51,776::vm::262::vm.Vm::(run) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Failed to migrate
Thread-3093::DEBUG::2012-12-06 16:09:52,956::BindingXMLRPC::894::vds::(wrapper) client [10.34.63.75]::call vmGetStats with ('2545aff1-dde2-4ce1-9de6-da6e82e8fa5c',) {}
Thread-3093::DEBUG::2012-12-06 16:09:52,956::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available
Thread-3093::DEBUG::2012-12-06 16:09:52,956::BindingXMLRPC::900::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '9243', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-1', 'hash': '-8436048150441222498', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:e0:3f:82', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '2545aff1-dde2-4ce1-9de6-da6e82e8fa5c', 'displayType': 'qxl', 'cpuUser': '0.80', 'disks': {u'vda': {'readLatency': '0', 'apparentsize': '16106127360', 'writeLatency': '5343479', 'imageID': '12d760eb-ab9a-4d23-a835-7ee826f843e2', 'flushLatency': '56494', 'readRate': '0.00', 'truesize': '4398075904', 'writeRate': '2241.69'}, u'hdc': {'flushLatency': '0', 'readLatency': '0', 'writeLatency': '0'}}, 'monitorResponse': '0', 'statsAge': '0.68', 'cpuIdle': '97.14', 'elapsedTime': '717', 'vmType': 'kvm', 'cpuSys': '2.06', 'appsList': [], 'guestIPs': '', 'nice': ''}]}
VM Channels Listener::DEBUG::2012-12-06 16:09:57,873::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 82.
Thread-3096::DEBUG::2012-12-06 16:09:59,045::task::588::TaskManager.Task::(_updateState) Task=`50828b2c-c8e9-48a6-b206-9a729ec64fc0`::moving from state init -> state preparing
Thread-3096::INFO::2012-12-06 16:09:59,045::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-3096::INFO::2012-12-06 16:09:59,046::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.0022120475769', 'lastCheck': '2.3', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00159192085266', 'lastCheck': '2.3', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00129985809326', 'lastCheck': '0.7', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00123000144958', 'lastCheck': '2.4', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00117015838623', 'lastCheck': '0.9', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00166511535645', 'lastCheck': '1.4', 'code': 0, 'valid': True}}
Thread-3096::DEBUG::2012-12-06 16:09:59,046::task::1172::TaskManager.Task::(prepare) Task=`50828b2c-c8e9-48a6-b206-9a729ec64fc0`::finished: {'a7e5f59c-2877-475b-8afc-f760ba63defb': {'delay': '0.0022120475769', 'lastCheck': '2.3', 'code': 0, 'valid': True}, 'aa6e2974-a8ed-48fc-b168-7d9fb69aad53': {'delay': '0.00159192085266', 'lastCheck': '2.3', 'code': 0, 'valid': True}, 'f586a7a5-7fb6-46b8-8ecb-3dfebdc82b54': {'delay': '0.00129985809326', 'lastCheck': '0.7', 'code': 0, 'valid': True}, '131d564c-52d1-4bba-8d60-39e889a8bc08': {'delay': '0.00123000144958', 'lastCheck': '2.4', 'code': 0, 'valid': True}, 'abd2d773-3619-456c-9d50-fdee1139bb86': {'delay': '0.00117015838623', 'lastCheck': '0.9', 'code': 0, 'valid': True}, '91078fd3-4579-4d67-ba45-2f76982e8f5d': {'delay': '0.00166511535645', 'lastCheck': '1.4', 'code': 0, 'valid': True}}
Thread-3096::DEBUG::2012-12-06 16:09:59,046::task::588::TaskManager.Task::(_updateState) Task=`50828b2c-c8e9-48a6-b206-9a729ec64fc0`::moving from state preparing -> state finished
Thread-3096::DEBUG::2012-12-06 16:09:59,046::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-3096::DEBUG::2012-12-06 16:09:59,046::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-3096::DEBUG::2012-12-06 16:09:59,046::task::978::TaskManager.Task::(_decref) Task=`50828b2c-c8e9-48a6-b206-9a729ec64fc0`::ref 0 aborting False
Thread-3097::DEBUG::2012-12-06 16:09:59,069::libvirtvm::267::vm.Vm::(_getDiskStats) vmId=`2545aff1-dde2-4ce1-9de6-da6e82e8fa5c`::Disk hdc stats not available


libvirt.log
============

2012-12-06 07:15:09.093+0000: 29792: debug : virDomainInterfaceStats:7223 : dom=0x7fc5600b81d0, (VM: name=rhel6_ws_64bit, uuid=6931ca39-6a2e-4972-8c1d-4d4a4a64c844), path=vnet1, stats=0x7fc5bb5fc330, size=64
2012-12-06 07:15:09.097+0000: 11988: debug : virDomainInterfaceStats:7223 : dom=0x7fc59401b3c0, (VM: name=winxp_updated, uuid=c21e3426-0c01-48b8-8ff7-f6c76e918d80), path=vnet2, stats=0x7fc5b8df8330, size=64
2012-12-06 10:15:09.100+0000: 30117: debug : virDomainGetCPUStats:18676 : dom=0x7fc56000db40, (VM: name=f17, uuid=9baf6e06-3c55-41f5-ad68-10a4da6e821d), params=(nil), nparams=0, start_cpu=-1, ncpus=1, flags=0
2012-12-06 10:15:09.106+0000: 30117: debug : virDomainGetCPUStats:18676 : dom=0x7fc56000db40, (VM: name=f17, uuid=9baf6e06-3c55-41f5-ad68-10a4da6e821d), params=0x7fc58c0fd870, nparams=3, start_cpu=-1, ncpus=1, flags=0
2012-12-06 10:15:09.113+0000: 30117: debug : virDomainInterfaceStats:7223 : dom=0x7fc56000db40, (VM: name=f17, uuid=9baf6e06-3c55-41f5-ad68-10a4da6e821d), path=vnet3, stats=0x7fc59f5fc330, size=64
2012-12-06 10:15:09.586+0000: 29792: debug : virDomainInterfaceStats:7223 : dom=0x7fc5600b81d0, (VM: name=rhel6_ws_64bit, uuid=6931ca39-6a2e-4972-8c1d-4d4a4a64c844), path=vnet1, stats=0x7fc5bb5fc330, size=64
2012-12-06 10:15:09.589+0000: 11988: debug : virDomainInterfaceStats:7223 : dom=0x7fc59401b3c0, (VM: name=winxp_updated, uuid=c21e3426-0c01-48b8-8ff7-f6c76e918d80), path=vnet2, stats=0x7fc5b8df8330, size=64
2012-12-06 11:15:09.213+0000: 1834: debug : virDomainInterfaceStats:7223 : dom=0x7fc5880458c0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet3, stats=0x7fc5b97f9330, size=64
2012-12-06 11:15:09.858+0000: 11988: debug : virDomainInterfaceStats:7223 : dom=0x7fc59401b3c0, (VM: name=winxp_updated, uuid=c21e3426-0c01-48b8-8ff7-f6c76e918d80), path=vnet2, stats=0x7fc5b8df8330, size=64
2012-12-06 15:09:00.075+0000: 9250: debug : virDomainQemuMonitorCommand:78 : domain=0x7ff67c0122e0, cmd={"execute": "query-blockstats"}, result=0x7ff6a0df8a00, flags=0
2012-12-06 15:09:00.151+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:05.154+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:10.158+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:15.213+0000: 9250: debug : virDomainGetCPUStats:18676 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), params=(nil), nparams=0, start_cpu=-1, ncpus=1, flags=0
2012-12-06 15:09:15.219+0000: 9250: debug : virDomainGetCPUStats:18676 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), params=0x7ff68c013fc0, nparams=3, start_cpu=-1, ncpus=1, flags=0
2012-12-06 15:09:15.224+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:20.227+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:25.230+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:30.234+0000: 9250: debug : virDomainGetCPUStats:18676 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), params=(nil), nparams=0, start_cpu=-1, ncpus=1, flags=0
2012-12-06 15:09:30.240+0000: 9250: debug : virDomainGetCPUStats:18676 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), params=0x7ff68c011550, nparams=3, start_cpu=-1, ncpus=1, flags=0
2012-12-06 15:09:30.245+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:35.248+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:40.251+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:44.851+0000: 10143: debug : virDomainGetXMLDesc:4379 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), flags=0
2012-12-06 15:09:44.940+0000: 10143: debug : virDomainGetXMLDesc:4379 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), flags=0
2012-12-06 15:09:45.022+0000: 10143: debug : virDomainGetXMLDesc:4379 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), flags=0
2012-12-06 15:09:45.094+0000: 10143: debug : virDomainGetXMLDesc:4379 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), flags=0
2012-12-06 15:09:45.255+0000: 9250: debug : virDomainGetCPUStats:18676 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), params=(nil), nparams=0, start_cpu=-1, ncpus=1, flags=0
2012-12-06 15:09:45.260+0000: 9250: debug : virDomainGetCPUStats:18676 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), params=0x7ff68c0111f0, nparams=3, start_cpu=-1, ncpus=1, flags=0
2012-12-06 15:09:45.266+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:45.275+0000: 10143: debug : virDomainMigrateToURI2:5710 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), dconnuri=qemu+tls://dell-r210ii-03.rhev.lab.eng.brq.redhat.com/system, miguri=tcp://dell-r210ii-03.rhev.lab.eng.brq.redhat.com, dxml=(null), flags=3, dname=(null), bandwidth=0
2012-12-06 15:09:45.278+0000: 10143: debug : virDomainMigrateToURI2:5728 : Using peer2peer migration
2012-12-06 15:09:45.278+0000: 10143: debug : virDomainMigratePeer2Peer:4969 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), xmlin=(null), flags=3, dname=(null), dconnuri=qemu+tls://dell-r210ii-03.rhev.lab.eng.brq.redhat.com/system, uri=tcp://dell-r210ii-03.rhev.lab.eng.brq.redhat.com, bandwidth=0
2012-12-06 15:09:45.281+0000: 10143: debug : virDomainMigratePeer2Peer:4997 : Using migration protocol 3
2012-12-06 15:09:46.534+0000: 10143: debug : virDomainFree:2313 : dom=0x7ff6800f5170, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c)
2012-12-06 15:09:46.534+0000: 2711: debug : virDomainRef:2355 : dom=0x7ff700003f60, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), refs=1
2012-12-06 15:09:46.534+0000: 2711: debug : virDomainGetUUIDString:3442 : dom=0x7ff700003f60, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), buf=0x7ff708593090
2012-12-06 15:09:46.534+0000: 2711: debug : virDomainGetUUID:3407 : dom=0x7ff700003f60, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), uuid=0x7ff708593040
2012-12-06 15:09:46.535+0000: 2711: debug : virDomainFree:2313 : dom=0x7ff700003f60, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c)
2012-12-06 15:09:46.535+0000: 2711: debug : virDomainFree:2313 : dom=0x7ff700003f60, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c)
2012-12-06 15:09:46.577+0000: 10143: error : virNetClientProgramDispatchError:174 : internal error unable to execute QEMU command 'migrate': An undefined error has ocurred
2012-12-06 15:09:46.578+0000: 10152: debug : virDomainGetJobInfo:16400 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), info=0x7ff6a3ffdd70
2012-12-06 15:09:50.272+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64
2012-12-06 15:09:51.669+0000: 10143: debug : virDomainGetXMLDesc:4379 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), flags=0
2012-12-06 15:09:55.276+0000: 9250: debug : virDomainInterfaceStats:7223 : dom=0x7ff67c0122e0, (VM: name=rhel6_ws_32bit, uuid=2545aff1-dde2-4ce1-9de6-da6e82e8fa5c), path=vnet0, stats=0x7ff6a0df8330, size=64

dumpxml
=======

<domain type='kvm' id='8'>
  <name>rhel6_ws_32bit</name>
  <uuid>2545aff1-dde2-4ce1-9de6-da6e82e8fa5c</uuid>
  <memory unit='KiB'>1048576</memory>
  <currentMemory unit='KiB'>1048576</currentMemory>
  <vcpu placement='static'>2</vcpu>
  <cputune>
    <shares>1020</shares>
  </cputune>
  <sysinfo type='smbios'>
    <system>
      <entry name='manufacturer'>Red Hat</entry>
      <entry name='product'>RHEV Hypervisor</entry>
      <entry name='version'>6Server-6.3.0.3.el6</entry>
      <entry name='serial'>4C4C4544-0058-3410-8058-C2C04F38354A_D0:67:E5:EE:65:09</entry>
      <entry name='uuid'>2545aff1-dde2-4ce1-9de6-da6e82e8fa5c</entry>
    </system>
  </sysinfo>
  <os>
    <type arch='x86_64' machine='rhel6.3.0'>hvm</type>
    <boot dev='hd'/>
    <smbios mode='sysinfo'/>
  </os>
  <features>
    <acpi/>
  </features>
  <cpu mode='custom' match='exact'>
    <model fallback='allow'>Conroe</model>
    <topology sockets='2' cores='1' threads='1'/>
  </cpu>
  <clock offset='variable' adjustment='-1'>
    <timer name='rtc' tickpolicy='catchup'/>
  </clock>
  <on_poweroff>destroy</on_poweroff>
  <on_reboot>restart</on_reboot>
  <on_crash>destroy</on_crash>
  <devices>
    <emulator>/usr/libexec/qemu-kvm</emulator>
    <disk type='file' device='cdrom'>
      <driver name='qemu' type='raw'/>
      <source startupPolicy='optional'/>
      <target dev='hdc' bus='ide'/>
      <readonly/>
      <serial></serial>
      <alias name='ide0-1-0'/>
      <address type='drive' controller='0' bus='1' target='0' unit='0'/>
    </disk>
    <disk type='file' device='disk' snapshot='no'>
      <driver name='qemu' type='raw' cache='none' error_policy='stop' io='threads'/>
      <source file='/rhev/data-center/08d10f90-3257-11e2-a035-001a4a013f3c/aa6e2974-a8ed-48fc-b168-7d9fb69aad53/images/12d760eb-ab9a-4d23-a835-7ee826f843e2/b8d92c04-9115-4e9b-a12c-226f87b2dfba'>
        <seclabel relabel='no'/>
      </source>
      <target dev='vda' bus='virtio'/>
      <serial>12d760eb-ab9a-4d23-a835-7ee826f843e2</serial>
      <alias name='virtio-disk0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>
    </disk>
    <controller type='usb' index='0' model='ich9-ehci1'>
      <alias name='usb0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x7'/>
    </controller>
    <controller type='usb' index='0' model='ich9-uhci1'>
      <alias name='usb0'/>
      <master startport='0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0' multifunction='on'/>
    </controller>
    <controller type='usb' index='0' model='ich9-uhci2'>
      <alias name='usb0'/>
      <master startport='2'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x1'/>
    </controller>
    <controller type='usb' index='0' model='ich9-uhci3'>
      <alias name='usb0'/>
      <master startport='4'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x2'/>
    </controller>
    <controller type='ide' index='0'>
      <alias name='ide0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>
    </controller>
    <controller type='virtio-serial' index='0'>
      <alias name='virtio-serial0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x07' function='0x0'/>
    </controller>
    <interface type='bridge'>
      <mac address='00:1a:4a:e0:3f:82'/>
      <source bridge='rhevm'/>
      <target dev='vnet0'/>
      <model type='virtio'/>
      <filterref filter='vdsm-no-mac-spoofing'/>
      <alias name='net0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
    </interface>
    <channel type='unix'>
      <source mode='bind' path='/var/lib/libvirt/qemu/channels/rhel6_ws_32bit.com.redhat.rhevm.vdsm'/>
      <target type='virtio' name='com.redhat.rhevm.vdsm'/>
      <alias name='channel0'/>
      <address type='virtio-serial' controller='0' bus='0' port='1'/>
    </channel>
    <channel type='unix'>
      <source mode='bind' path='/var/lib/libvirt/qemu/channels/rhel6_ws_32bit.org.qemu.guest_agent.0'/>
      <target type='virtio' name='org.qemu.guest_agent.0'/>
      <alias name='channel1'/>
      <address type='virtio-serial' controller='0' bus='0' port='2'/>
    </channel>
    <channel type='spicevmc'>
      <target type='virtio' name='com.redhat.spice.0'/>
      <alias name='channel2'/>
      <address type='virtio-serial' controller='0' bus='0' port='3'/>
    </channel>
    <input type='mouse' bus='ps2'/>
    <graphics type='spice' port='5900' tlsPort='5901' autoport='yes' listen='0' keymap='en-us' passwdValidTo='1970-01-01T00:00:01'>
      <listen type='address' address='0'/>
      <channel name='main' mode='secure'/>
      <channel name='display' mode='secure'/>
      <channel name='inputs' mode='secure'/>
      <channel name='cursor' mode='secure'/>
      <channel name='playback' mode='secure'/>
      <channel name='record' mode='secure'/>
      <channel name='smartcard' mode='secure'/>
      <channel name='usbredir' mode='secure'/>
    </graphics>
    <sound model='ich6'>
      <alias name='sound0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>
    </sound>
    <video>
      <model type='qxl' vram='65536' heads='1'/>
      <alias name='video0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>
    </video>
    <redirdev bus='usb' type='spicevmc'>
      <alias name='redir0'/>
    </redirdev>
    <redirdev bus='usb' type='spicevmc'>
      <alias name='redir1'/>
    </redirdev>
    <redirdev bus='usb' type='spicevmc'>
      <alias name='redir2'/>
    </redirdev>
    <redirdev bus='usb' type='spicevmc'>
      <alias name='redir3'/>
    </redirdev>
    <memballoon model='virtio'>
      <alias name='balloon0'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x08' function='0x0'/>
    </memballoon>
  </devices>
  <seclabel type='dynamic' model='selinux' relabel='yes'>
    <label>system_u:system_r:svirt_t:s0:c156,c605</label>
    <imagelabel>system_u:object_r:svirt_image_t:s0:c156,c605</imagelabel>
  </seclabel>
</domain>
Comment 1 Haim 2012-12-06 17:44:38 UTC 
bug is in vdsm and not backend (so move component)
please attach all related logs in a tar file (so they can be downloadable and analyzed).
Comment 2 Jiri Belka 2012-12-07 08:38:46 UTC 
Created attachment 659232 [details]
engine.log, server.log, vdsm.log.2, libvirt.log.1
Comment 4 RHEL Program Management 2012-12-14 08:52:24 UTC 
This request was not resolved in time for the current release.
Red Hat invites you to ask your support representative to
propose this request, if still desired, for consideration in
the next release of Red Hat Enterprise Linux.
Comment 5 Michal Skrivanek 2013-01-13 16:29:14 UTC 

*** This bug has been marked as a duplicate of bug 889551 ***
Note You need to log in before you can comment on or make changes to this bug.