Re: [Users] oVirt 3.1 - VM Migration Issue
On 01/03/2013 05:07 PM, Tom Brown wrote:
interesting, please search for migrationCreate command on desination host and search for ERROR afterwords, what do you see?
----- Original Message -----
From: "Tom Brown" <tom@ng23.net> To: users@ovirt.org Sent: Thursday, January 3, 2013 4:12:05 PM Subject: [Users] oVirt 3.1 - VM Migration Issue
Hi
I seem to have an issue with a single VM and migration, other VM's can migrate OK - When migrating from the GUI it appears to just hang but in the engine.log i see the following
2013-01-03 14:03:10,359 INFO [org.ovirt.engine.core.bll.VdsSelector] (ajp--0.0.0.0-8009-59) Checking for a specific VDS only - id:a2d84a1e-3e18-11e2-8851-3cd92b4c8e89, name:ovirt-node.domain-name, host_name(ip):10.192.42.165 2013-01-03 14:03:10,411 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (pool-3-thread-48) [4d32917d] Running command: MigrateVmToServerCommand internal: false. Entities affected : ID: 9dc63ce4-0f76-4963-adfe-6f8eb1a44806 Type: VM 2013-01-03 14:03:10,413 INFO [org.ovirt.engine.core.bll.VdsSelector] (pool-3-thread-48) [4d32917d] Checking for a specific VDS only - id:a2d84a1e-3e18-11e2-8851-3cd92b4c8e89, name:ovirt-node.domain-name, host_name(ip):10.192.42.165 2013-01-03 14:03:11,028 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (pool-3-thread-48) [4d32917d] START, MigrateVDSCommand(vdsId = 1a52b722-43a1-11e2-af96-3cd92b4c8e89, vmId=9dc63ce4-0f76-4963-adfe-6f8eb1a44806, srcHost=10.192.42.196, dstVdsId=a2d84a1e-3e18-11e2-8851-3cd92b4c8e89, dstHost=10.192.42.165:54321, migrationMethod=ONLINE), log id: 5011789b 2013-01-03 14:03:11,030 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (pool-3-thread-48) [4d32917d] VdsBroker::migrate::Entered (vm_guid=9dc63ce4-0f76-4963-adfe-6f8eb1a44806, srcHost=10.192.42.196, dstHost=10.192.42.165:54321, method=online 2013-01-03 14:03:11,031 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (pool-3-thread-48) [4d32917d] START, MigrateBrokerVDSCommand(vdsId = 1a52b722-43a1-11e2-af96-3cd92b4c8e89, vmId=9dc63ce4-0f76-4963-adfe-6f8eb1a44806, srcHost=10.192.42.196, dstVdsId=a2d84a1e-3e18-11e2-8851-3cd92b4c8e89, dstHost=10.192.42.165:54321, migrationMethod=ONLINE), log id: 7cd53864 2013-01-03 14:03:11,041 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (pool-3-thread-48) [4d32917d] FINISH, MigrateBrokerVDSCommand, log id: 7cd53864 2013-01-03 14:03:11,086 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (pool-3-thread-48) [4d32917d] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 5011789b 2013-01-03 14:03:11,606 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-29) vds::refreshVmList vm id 9dc63ce4-0f76-4963-adfe-6f8eb1a44806 is migrating to vds ovirt-node.domain-name ignoring it in the refresh till migration is done 2013-01-03 14:03:12,836 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-36) VM test002.domain-name 9dc63ce4-0f76-4963-adfe-6f8eb1a44806 moved from MigratingFrom --> Up 2013-01-03 14:03:12,837 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-36) adding VM 9dc63ce4-0f76-4963-adfe-6f8eb1a44806 to re-run list 2013-01-03 14:03:12,852 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-36) Rerun vm 9dc63ce4-0f76-4963-adfe-6f8eb1a44806. Called from vds ovirt-node002.domain-name 2013-01-03 14:03:12,855 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-3-thread-48) START, MigrateStatusVDSCommand(vdsId = 1a52b722-43a1-11e2-af96-3cd92b4c8e89, vmId=9dc63ce4-0f76-4963-adfe-6f8eb1a44806), log id: 4721a1f3 2013-01-03 14:03:12,864 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-48) Failed in MigrateStatusVDS method 2013-01-03 14:03:12,865 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-48) Error code migrateErr and error message VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Fatal error during migration 2013-01-03 14:03:12,865 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-48) Command org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand return value Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusOnlyReturnForXmlRpc mStatus Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusForXmlRpc mCode 12 mMessage Fatal error during migration
2013-01-03 14:03:12,866 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-3-thread-48) Vds: ovirt-node002.itvonline.ads 2013-01-03 14:03:12,867 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (pool-3-thread-48) Command MigrateStatusVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Fatal error during migration 2013-01-03 14:03:12,867 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (pool-3-thread-48) FINISH, MigrateStatusVDSCommand, log id: 4721a1f3
Does anyone have any idea what this might be? I am using 3.1 from dreyou as these are CentOS 6 nodes
any clue on which log on the new host ? I see the following in messages
VDSM is the virtualization agent. look at /var/log/vdsm/vdsm.log
Jan 3 16:03:20 ovirt-node vdsm Storage.LVM WARNING lvm vgs failed: 5 [] [' Volume group "ab686999-f320-4a61-ae07-e99c2f858996" not found'] Jan 3 16:03:20 ovirt-node vdsm Storage.StorageDomain WARNING Resource namespace ab686999-f320-4a61-ae07-e99c2f858996_imageNS already registered Jan 3 16:03:20 ovirt-node vdsm Storage.StorageDomain WARNING Resource namespace ab686999-f320-4a61-ae07-e99c2f858996_volumeNS already registered Jan 3 16:03:58 ovirt-node vdsm vm.Vm WARNING vmId=`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}' found Jan 3 16:03:58 ovirt-node vdsm vm.Vm WARNING vmId=`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}' found Jan 3 16:03:59 ovirt-node kernel: device vnet2 entered promiscuous mode Jan 3 16:03:59 ovirt-node kernel: ovirtmgmt: port 4(vnet2) entering forwarding state Jan 3 16:03:59 ovirt-node kernel: ovirtmgmt: port 4(vnet2) entering disabled state Jan 3 16:03:59 ovirt-node kernel: device vnet2 left promiscuous mode Jan 3 16:03:59 ovirt-node kernel: ovirtmgmt: port 4(vnet2) entering disabled state
and the following in the qemu log for that VM on the new node
2013-01-03 16:03:59.706+0000: starting up LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin QEMU_AUDIO_DRV=none /usr/libexec/qemu-kvm -S -M rhel6.3.0 -cpu Nehalem -enable-kvm -m 1024 -smp 1,sockets=1,cores=1,threads=1 -name test002.itvonline.ads -uuid 9dc63ce4-0f76-4963-adfe-6f8eb1a44806 -smbios type=1,manufacturer=oVirt,product=oVirt Node,version=6-3.el6.centos.9,serial=55414E03-C241-11DF-BBDA-64093408D485_d4:85:64:09:34:08,uuid=9dc63ce4-0f76-4963-adfe-6f8eb1a44806 -nodefconfig -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/test002.itvonline.ads.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=2013-01-03T16:03:58,driftfix=slew -no-shutdown -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x4 -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -drive if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,serial= -device ide-drive,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0,bootindex=1 -drive file=/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5 dda7/2a1939bd-9fa3-4896-b8a9-46234172aae7/images/e8711e5d-2f06-4c0f-b5c6-fa0806d7448f/0d93c51f-f838-4143-815c-9b3457d1a934,if=none,id=drive-virtio-disk0,format=raw,serial=e8711e5d-2f06-4c0f-b5c6-fa0806d7448f,cache=none,werror=stop,rerror=stop,aio=threads -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x5,drive=drive-virtio-disk0,id=virtio-disk0 -netdev tap,fd=32,id=hostnet0,vhost=on,vhostfd=33 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=00:1a:4a:c0:2a:00,bus=pci.0,addr=0x3 -chardev socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/test002.itvonline.ads.com.redhat.rhevm.vdsm,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=com.redhat.rhevm.vdsm -chardev socket,id=charchannel1,path=/var/lib/libvirt/qemu/channels/test002.itvonline.ads.org.qemu.guest_agent.0,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=2,chardev=charchannel1,id=channel1,name=org.qemu.guest_agent.0 -chardev pty,id=charconsole0 -de vice virtconsole,chardev=charconsole0,id=console0 -device usb-tablet,id=input0 -vnc 10.192.42.165:4,password -k en-us -vga qxl -global qxl-vga.vram_size=67108864 -incoming tcp:0.0.0.0:49160 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x6 2013-01-03 16:03:59.955+0000: shutting down
but thats about it?
thanks
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
--Apple-Mail=_B91DF312-1386-4884-ADD0-7FF314F05FC2 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=iso-8859-1
VDSM is the virtualization agent. look at /var/log/vdsm/vdsm.log
many thanks - attached is the snip of that log when i try the migration thanks --Apple-Mail=_B91DF312-1386-4884-ADD0-7FF314F05FC2 Content-Disposition: attachment; filename=migrate.log Content-Type: application/octet-stream; x-unix-mode=0644; name="migrate.log" Content-Transfer-Encoding: quoted-printable Thread-2390720::DEBUG::2013-01-07=20= 12:13:11,241::task::568::TaskManager.Task::(_updateState)=20= Task=3D`325ab4a5-c999-4d9f-8aa8-0d1a4e4124cd`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390720::INFO::2013-01-07=20= 12:13:11,242::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-2390720::INFO::2013-01-07=20= 12:13:11,242::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00224804878235',=20'lastCheck':=20'4.4',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00211691856384',=20'lastCheck':=20'7.2',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00240302085876',=20'lastCheck':=20'7.0',=20'code':=200,=20'valid':=20= True}}=0AThread-2390720::DEBUG::2013-01-07=20= 12:13:11,242::task::1151::TaskManager.Task::(prepare)=20= Task=3D`325ab4a5-c999-4d9f-8aa8-0d1a4e4124cd`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00224804878235',=20'lastCheck':=20'4.4',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00211691856384',=20'lastCheck':=20'7.2',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00240302085876',=20'lastCheck':=20'7.0',=20'code':=200,=20'valid':=20= True}}=0AThread-2390720::DEBUG::2013-01-07=20= 12:13:11,242::task::568::TaskManager.Task::(_updateState)=20= Task=3D`325ab4a5-c999-4d9f-8aa8-0d1a4e4124cd`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390720::DEBUG::2013-01-07=20= 12:13:11,242::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390720::DEBUG::2013-01-07=20= 12:13:11,243::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390720::DEBUG::2013-01-07=20= 12:13:11,243::task::957::TaskManager.Task::(_decref)=20= Task=3D`325ab4a5-c999-4d9f-8aa8-0d1a4e4124cd`::ref=200=20aborting=20= False=0AThread-2390721::DEBUG::2013-01-07=20= 12:13:11,256::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`a08884f6-d634-4d1d-a0ef-f77cd96f0953`::Disk=20vda=20latency=20= not=20available=0AThread-2390722::DEBUG::2013-01-07=20= 12:13:12,808::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390722::DEBUG::2013-01-07=20= 12:13:12,808::task::568::TaskManager.Task::(_updateState)=20= Task=3D`054ac6c0-f5df-48ed-8db5-a0678f9d37c3`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390722::INFO::2013-01-07=20= 12:13:12,808::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390722::INFO::2013-01-07=20= 12:13:12,809::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus,=20Return=20response:=20{'spm_st':=20{'spmId':=201,=20= 'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390722::DEBUG::2013-01-07=20= 12:13:12,809::task::1151::TaskManager.Task::(prepare)=20= Task=3D`054ac6c0-f5df-48ed-8db5-a0678f9d37c3`::finished:=20{'spm_st':=20= {'spmId':=201,=20'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390722::DEBUG::2013-01-07=20= 12:13:12,809::task::568::TaskManager.Task::(_updateState)=20= Task=3D`054ac6c0-f5df-48ed-8db5-a0678f9d37c3`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390722::DEBUG::2013-01-07=20= 12:13:12,809::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390722::DEBUG::2013-01-07=20= 12:13:12,809::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390722::DEBUG::2013-01-07=20= 12:13:12,810::task::957::TaskManager.Task::(_decref)=20= Task=3D`054ac6c0-f5df-48ed-8db5-a0678f9d37c3`::ref=200=20aborting=20= False=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,820::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,820::task::568::TaskManager.Task::(_updateState)=20= Task=3D`c345b3e5-5fe1-4237-a388-fa119898c5dd`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390723::INFO::2013-01-07=20= 12:13:12,820::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,821::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`7db748b2-= ebf7-4233-878f-e8c6547e51d9`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,821::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20for=20lock=20type=20= 'shared'=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,821::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,821::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`7db748b2-= ebf7-4233-878f-e8c6547e51d9`::Granted=20request=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,822::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`c345b3e5-5fe1-4237-a388-fa119898c5dd`::_resourcesAcquired:=20= Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7=20(shared)=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,822::task::957::TaskManager.Task::(_decref)=20= Task=3D`c345b3e5-5fe1-4237-a388-fa119898c5dd`::ref=201=20aborting=20= False=0AThread-2390723::INFO::2013-01-07=20= 12:13:12,826::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo,=20Return=20response:=20{'info':=20{'spm_id':=201,=20= 'master_uuid':=20'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20= 'Default',=20'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,826::task::1151::TaskManager.Task::(prepare)=20= Task=3D`c345b3e5-5fe1-4237-a388-fa119898c5dd`::finished:=20{'info':=20= {'spm_id':=201,=20'master_uuid':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20'Default',=20= 'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,826::task::568::TaskManager.Task::(_updateState)=20= Task=3D`c345b3e5-5fe1-4237-a388-fa119898c5dd`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,826::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7':=20<=20ResourceRef=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,826::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,827::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,827::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20= (0=20active=20users)=0AThread-2390723::DEBUG::2013-01-07=20= 12:13:12,827::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,827::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20Clearing=20records.=0A= Thread-2390723::DEBUG::2013-01-07=20= 12:13:12,827::task::957::TaskManager.Task::(_decref)=20= Task=3D`c345b3e5-5fe1-4237-a388-fa119898c5dd`::ref=200=20aborting=20= False=0AThread-2390726::DEBUG::2013-01-07=20= 12:13:16,575::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.196]::call=20vmGetStats=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-2390726::DEBUG::2013-01-07=20= 12:13:16,580::BindingXMLRPC::890::vds::(wrapper)=20return=20vmGetStats=20= with=20{'status':=20{'message':=20'Virtual=20machine=20does=20not=20= exist',=20'code':=201}}=0AThread-2390727::DEBUG::2013-01-07=20= 12:13:16,972::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.196]::call=20vmMigrationCreate=20with=20({'username':=20= 'Unknown',=20'acpiEnable':=20'true',=20'emulatedMachine':=20'pc',=20= 'afterMigrationStatus':=20'Up',=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'transparentHugePages':=20= 'true',=20'displaySecurePort':=20'5905',=20'timeOffset':=20-2,=20= 'cpuType':=20'Nehalem',=20'custom':=20{},=20'pauseCode':=20'NOERR',=20= 'migrationDest':=20'libvirt',=20'smp':=20'1',=20'vmType':=20'kvm',=20= 'spiceSslCipherSuite':=20'DEFAULT',=20'_srcDomXML':=20"<domain=20= type=3D'kvm'=20id=3D'4'>\n=20=20<name>test004.domainname</name>\n=20=20= <uuid>cfb17b98-1476-4fbf-9fab-7c7f48b60adf</uuid>\n=20=20<memory=20= unit=3D'KiB'>1048576</memory>\n=20=20<currentMemory=20= unit=3D'KiB'>1048576</currentMemory>\n=20=20<vcpu=20= placement=3D'static'>1</vcpu>\n=20=20<cputune>\n=20=20=20=20= <shares>1020</shares>\n=20=20</cputune>\n=20=20<sysinfo=20= type=3D'smbios'>\n=20=20=20=20<system>\n=20=20=20=20=20=20<entry=20= name=3D'manufacturer'>oVirt</entry>\n=20=20=20=20=20=20<entry=20= name=3D'product'>oVirt=20Node</entry>\n=20=20=20=20=20=20<entry=20= name=3D'version'>6-3.el6.centos.9</entry>\n=20=20=20=20=20=20<entry=20= name=3D'serial'>55414E03-C241-11DF-BBDA-64093408D485_d4:85:64:09:34:08</en= try>\n=20=20=20=20=20=20<entry=20= name=3D'uuid'>cfb17b98-1476-4fbf-9fab-7c7f48b60adf</entry>\n=20=20=20=20= </system>\n=20=20</sysinfo>\n=20=20<os>\n=20=20=20=20<type=20= arch=3D'x86_64'=20machine=3D'rhel6.3.0'>hvm</type>\n=20=20=20=20<boot=20= dev=3D'hd'/>\n=20=20=20=20<smbios=20mode=3D'sysinfo'/>\n=20=20</os>\n=20=20= <features>\n=20=20=20=20<acpi/>\n=20=20</features>\n=20=20<cpu=20= mode=3D'custom'=20match=3D'exact'>\n=20=20=20=20<model=20= fallback=3D'allow'>Nehalem</model>\n=20=20=20=20<topology=20sockets=3D'1'=20= cores=3D'1'=20threads=3D'1'/>\n=20=20</cpu>\n=20=20<clock=20= offset=3D'variable'=20adjustment=3D'-2'>\n=20=20=20=20<timer=20= name=3D'rtc'=20tickpolicy=3D'catchup'/>\n=20=20</clock>\n=20=20= <on_poweroff>destroy</on_poweroff>\n=20=20= <on_reboot>restart</on_reboot>\n=20=20<on_crash>destroy</on_crash>\n=20=20= <devices>\n=20=20=20=20<emulator>/usr/libexec/qemu-kvm</emulator>\n=20=20= =20=20<disk=20type=3D'file'=20device=3D'cdrom'>\n=20=20=20=20=20=20= <driver=20name=3D'qemu'=20type=3D'raw'/>\n=20=20=20=20=20=20<source=20= file=3D'/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f3= 20-4a61-ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobb= ler-base.iso'=20startupPolicy=3D'optional'/>\n=20=20=20=20=20=20<target=20= dev=3D'hdc'=20bus=3D'ide'/>\n=20=20=20=20=20=20<readonly/>\n=20=20=20=20=20= =20<serial></serial>\n=20=20=20=20=20=20<alias=20name=3D'ide0-1-0'/>\n=20= =20=20=20=20=20<address=20type=3D'drive'=20controller=3D'0'=20bus=3D'1'=20= target=3D'0'=20unit=3D'0'/>\n=20=20=20=20</disk>\n=20=20=20=20<disk=20= type=3D'file'=20device=3D'disk'=20snapshot=3D'no'>\n=20=20=20=20=20=20= <driver=20name=3D'qemu'=20type=3D'raw'=20cache=3D'none'=20= error_policy=3D'stop'=20io=3D'threads'/>\n=20=20=20=20=20=20<source=20= file=3D'/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9f= a3-4896-b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e= 7b27-cdbb-4dc7-ba7b-4285719615d4'/>\n=20=20=20=20=20=20<target=20= dev=3D'vda'=20bus=3D'virtio'/>\n=20=20=20=20=20=20= <serial>12a6472f-9ab9-436a-8508-b6721cb2b227</serial>\n=20=20=20=20=20=20= <alias=20name=3D'virtio-disk0'/>\n=20=20=20=20=20=20<address=20= type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x05'=20= function=3D'0x0'/>\n=20=20=20=20</disk>\n=20=20=20=20<controller=20= type=3D'usb'=20index=3D'0'>\n=20=20=20=20=20=20<alias=20name=3D'usb0'/>\n=20= =20=20=20=20=20<address=20type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20= slot=3D'0x01'=20function=3D'0x2'/>\n=20=20=20=20</controller>\n=20=20=20=20= <controller=20type=3D'ide'=20index=3D'0'>\n=20=20=20=20=20=20<alias=20= name=3D'ide0'/>\n=20=20=20=20=20=20<address=20type=3D'pci'=20= domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x01'=20function=3D'0x1'/>\n=20= =20=20=20</controller>\n=20=20=20=20<controller=20type=3D'virtio-serial'=20= index=3D'0'>\n=20=20=20=20=20=20<alias=20name=3D'virtio-serial0'/>\n=20=20= =20=20=20=20<address=20type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20= slot=3D'0x04'=20function=3D'0x0'/>\n=20=20=20=20</controller>\n=20=20=20=20= <interface=20type=3D'bridge'>\n=20=20=20=20=20=20<mac=20= address=3D'00:1a:4a:c0:2a:05'/>\n=20=20=20=20=20=20<source=20= bridge=3D'ovirtmgmt'/>\n=20=20=20=20=20=20<target=20dev=3D'vnet2'/>\n=20=20= =20=20=20=20<model=20type=3D'virtio'/>\n=20=20=20=20=20=20<alias=20= name=3D'net0'/>\n=20=20=20=20=20=20<address=20type=3D'pci'=20= domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x03'=20function=3D'0x0'/>\n=20= =20=20=20</interface>\n=20=20=20=20<console=20type=3D'pty'=20= tty=3D'/dev/pts/2'>\n=20=20=20=20=20=20<source=20path=3D'/dev/pts/2'/>\n=20= =20=20=20=20=20<target=20type=3D'virtio'=20port=3D'0'/>\n=20=20=20=20=20=20= <alias=20name=3D'console0'/>\n=20=20=20=20</console>\n=20=20=20=20= <channel=20type=3D'unix'>\n=20=20=20=20=20=20<source=20mode=3D'bind'=20= path=3D'/var/lib/libvirt/qemu/channels/test004.domainname.redhat.rhevm.vds= m'/>\n=20=20=20=20=20=20<target=20type=3D'virtio'=20= name=3D'com.redhat.rhevm.vdsm'/>\n=20=20=20=20=20=20<alias=20= name=3D'channel0'/>\n=20=20=20=20=20=20<address=20type=3D'virtio-serial'=20= controller=3D'0'=20bus=3D'0'=20port=3D'1'/>\n=20=20=20=20</channel>\n=20=20= =20=20<channel=20type=3D'unix'>\n=20=20=20=20=20=20<source=20mode=3D'bind'= =20= path=3D'/var/lib/libvirt/qemu/channels/test004.domainname.org.qemu.guest_a= gent.0'/>\n=20=20=20=20=20=20<target=20type=3D'virtio'=20= name=3D'org.qemu.guest_agent.0'/>\n=20=20=20=20=20=20<alias=20= name=3D'channel1'/>\n=20=20=20=20=20=20<address=20type=3D'virtio-serial'=20= controller=3D'0'=20bus=3D'0'=20port=3D'2'/>\n=20=20=20=20</channel>\n=20=20= =20=20<channel=20type=3D'spicevmc'>\n=20=20=20=20=20=20<target=20= type=3D'virtio'=20name=3D'com.redhat.spice.0'/>\n=20=20=20=20=20=20= <alias=20name=3D'channel2'/>\n=20=20=20=20=20=20<address=20= type=3D'virtio-serial'=20controller=3D'0'=20bus=3D'0'=20port=3D'3'/>\n=20= =20=20=20</channel>\n=20=20=20=20<input=20type=3D'mouse'=20bus=3D'ps2'/>\n= =20=20=20=20<graphics=20type=3D'spice'=20port=3D'5904'=20tlsPort=3D'5905'=20= autoport=3D'yes'=20keymap=3D'en-us'=20= passwdValidTo=3D'2012-12-19T15:52:56'=20connected=3D'disconnect'>\n=20=20= =20=20=20=20<listen=20type=3D'network'=20address=3D'10.192.42.196'=20= network=3D'vdsm-ovirtmgmt'/>\n=20=20=20=20=20=20<channel=20name=3D'main'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'display'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'inputs'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'cursor'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'playback'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'record'=20= mode=3D'secure'/>\n=20=20=20=20</graphics>\n=20=20=20=20<video>\n=20=20=20= =20=20=20<model=20type=3D'qxl'=20vram=3D'65536'=20heads=3D'1'/>\n=20=20=20= =20=20=20<alias=20name=3D'video0'/>\n=20=20=20=20=20=20<address=20= type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x02'=20= function=3D'0x0'/>\n=20=20=20=20</video>\n=20=20=20=20<memballoon=20= model=3D'virtio'>\n=20=20=20=20=20=20<alias=20name=3D'balloon0'/>\n=20=20= =20=20=20=20<address=20type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20= slot=3D'0x06'=20function=3D'0x0'/>\n=20=20=20=20</memballoon>\n=20=20= </devices>\n=20=20<seclabel=20type=3D'none'/>\n</domain>\n",=20= 'memSize':=201024,=20'elapsedTimeOffset':=201626932.6551721096,=20= 'vmName':=20'test004.domainname',=20'nice':=20'0',=20'status':=20'Up',=20= 'clientIp':=20'',=20'displayIp':=20'10.192.42.196',=20'displayPort':=20= '5904',=20'smpCoresPerSocket':=20'1',=20'spiceSecureChannels':=20= 'smain,sinputs,scursor,splayback,srecord,sdisplay',=20'nicModel':=20= 'rtl8139,pv',=20'keyboardLayout':=20'en-us',=20'kvmEnable':=20'true',=20= 'pitReinjection':=20'false',=20'displayNetwork':=20'ovirtmgmt',=20= 'devices':=20[{'specParams':=20{'vram':=20'65536'},=20'alias':=20= 'video0',=20'deviceId':=20'0f10b02a-f6bc-432d-bc49-478facf49730',=20= 'address':=20{'slot':=20'0x02',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x0'},=20'device':=20= 'qxl',=20'type':=20'video'},=20{'nicModel':=20'pv',=20'macAddr':=20= '00:1a:4a:c0:2a:05',=20'network':=20'ovirtmgmt',=20'alias':=20'net0',=20= 'specParams':=20{},=20'deviceId':=20= '376d1987-d374-486d-8a62-d48ab0a47eb1',=20'address':=20{'slot':=20= '0x03',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20= 'function':=20'0x0'},=20'device':=20'bridge',=20'type':=20'interface',=20= 'name':=20'vnet2'},=20{'target':=201048576,=20'specParams':=20{'model':=20= 'virtio'},=20'alias':=20'balloon0',=20'deviceId':=20= '72aaa60a-34e5-41e1-80ea-d9b1c3a1b4e2',=20'address':=20{'slot':=20= '0x06',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20= 'function':=20'0x0'},=20'device':=20'memballoon',=20'type':=20= 'balloon'},=20{'index':=20'2',=20'iface':=20'ide',=20'name':=20'hdc',=20= 'alias':=20'ide0-1-0',=20'shared':=20'false',=20'specParams':=20{'path':=20= 'cobbler-base.iso'},=20'readonly':=20'True',=20'deviceId':=20= '58cff440-2f4d-4bbe-94d9-d7c12df85c4d',=20'address':=20{'bus':=20'1',=20= 'controller':=20'0',=20'type':=20'drive',=20'target':=20'0',=20'unit':=20= '0'},=20'device':=20'cdrom',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobbler-bas= e.iso',=20'type':=20'disk'},=20{'poolID':=20= 'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20'index':=200,=20'iface':=20= 'virtio',=20'apparentsize':=20'21474836480',=20'alias':=20= 'virtio-disk0',=20'imageID':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'readonly':=20'False',=20'shared':=20'false',=20'truesize':=20'0',=20= 'type':=20'disk',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'reqsize':=20'0',=20'format':=20= 'raw',=20'deviceId':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'address':=20{'slot':=20'0x05',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x0'},=20'device':=20= 'disk',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'propagateErrors':=20'off',=20'optional':=20= 'false',=20'name':=20'vda',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'specParams':=20{},=20= 'volumeChain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]},=20{'device':=20'usb',=20= 'alias':=20'usb0',=20'type':=20'controller',=20'address':=20{'slot':=20= '0x01',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20= 'function':=20'0x2'}},=20{'device':=20'ide',=20'alias':=20'ide0',=20= 'type':=20'controller',=20'address':=20{'slot':=20'0x01',=20'bus':=20= '0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20= '0x1'}},=20{'device':=20'virtio-serial',=20'alias':=20'virtio-serial0',=20= 'type':=20'controller',=20'address':=20{'slot':=20'0x04',=20'bus':=20= '0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20= '0x0'}},=20{'device':=20'unix',=20'alias':=20'channel0',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'1'}},=20{'device':=20'unix',=20= 'alias':=20'channel1',=20'type':=20'channel',=20'address':=20{'bus':=20= '0',=20'controller':=20'0',=20'type':=20'virtio-serial',=20'port':=20= '2'}},=20{'device':=20'spicevmc',=20'alias':=20'channel2',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'3'}}],=20'guestIPs':=20'',=20= 'display':=20'qxl'},)=20{}=0AThread-2390727::DEBUG::2013-01-07=20= 12:13:16,972::API::467::vds::(migrationCreate)=20Migration=20create=0A= Thread-2390727::INFO::2013-01-07=20= 12:13:16,973::clientIF::331::vds::(createVm)=20vmContainerLock=20= acquired=20by=20vm=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,977::vm::590::vm.Vm::(_startUnderlyingVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Start=0A= Thread-2390727::DEBUG::2013-01-07=20= 12:13:16,977::clientIF::345::vds::(createVm)=20Total=20desktops=20after=20= creation=20of=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=20is=202=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,977::vm::594::vm.Vm::(_startUnderlyingVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::_ongoingCreations=20= acquired=0AThread-2390727::DEBUG::2013-01-07=20= 12:13:16,978::libvirtvm::2611::vm.Vm::(waitForMigrationDestinationPrepare)= =20vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20= destination:=20waiting=20for=20VM=20creation=0A= Thread-2390728::INFO::2013-01-07=20= 12:13:16,978::libvirtvm::1356::vm.Vm::(_run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::VM=20wrapper=20has=20= started=0AThread-2390727::DEBUG::2013-01-07=20= 12:13:16,978::libvirtvm::2617::vm.Vm::(waitForMigrationDestinationPrepare)= =20vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20= destination:=20waiting=2042s=20for=20path=20preparation=0A= Thread-2390728::WARNING::2013-01-07=20= 12:13:16,978::vm::416::vm.Vm::(getConfDevices)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Unknown=20type=20found,=20= device:=20'{'device':=20'unix',=20'alias':=20'channel0',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'1'}}'=20found=0A= Thread-2390728::WARNING::2013-01-07=20= 12:13:16,979::vm::416::vm.Vm::(getConfDevices)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Unknown=20type=20found,=20= device:=20'{'device':=20'unix',=20'alias':=20'channel1',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'2'}}'=20found=0A= Thread-2390728::WARNING::2013-01-07=20= 12:13:16,979::vm::416::vm.Vm::(getConfDevices)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Unknown=20type=20found,=20= device:=20'{'device':=20'spicevmc',=20'alias':=20'channel2',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'3'}}'=20found=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,979::task::568::TaskManager.Task::(_updateState)=20= Task=3D`7466be2f-f364-49e5-a71d-cdfcbed33fe9`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390728::INFO::2013-01-07=20= 12:13:16,980::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= volUUID=3D'732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20options=3DNone)=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,982::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,985::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-2390728::INFO::2013-01-07=20= 12:13:16,986::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize,=20Return=20response:=20{'truesize':=20'2936401920',=20= 'apparentsize':=20'21474836480'}=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,986::task::1151::TaskManager.Task::(prepare)=20= Task=3D`7466be2f-f364-49e5-a71d-cdfcbed33fe9`::finished:=20{'truesize':=20= '2936401920',=20'apparentsize':=20'21474836480'}=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,987::task::568::TaskManager.Task::(_updateState)=20= Task=3D`7466be2f-f364-49e5-a71d-cdfcbed33fe9`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,987::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,987::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,987::task::957::TaskManager.Task::(_decref)=20= Task=3D`7466be2f-f364-49e5-a71d-cdfcbed33fe9`::ref=200=20aborting=20= False=0AThread-2390728::INFO::2013-01-07=20= 12:13:16,987::clientIF::313::vds::(prepareVolumePath)=20prepared=20= volume=20path:=20= /rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61-= ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobbler-base= .iso=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,988::task::568::TaskManager.Task::(_updateState)=20= Task=3D`c8efa769-fc10-4a04-8b52-45fb26da83c2`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390728::INFO::2013-01-07=20= 12:13:16,988::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= prepareImage(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= volUUID=3D'732e7b27-cdbb-4dc7-ba7b-4285719615d4')=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,988::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7`ReqID=3D`60d2d596-= 761a-4d67-92be-69d29b2ec4f3`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,988::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20for=20lock=20type=20= 'shared'=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,989::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,989::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7`ReqID=3D`60d2d596-= 761a-4d67-92be-69d29b2ec4f3`::Granted=20request=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,989::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`c8efa769-fc10-4a04-8b52-45fb26da83c2`::_resourcesAcquired:=20= Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7=20(shared)=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,989::task::957::TaskManager.Task::(_decref)=20= Task=3D`c8efa769-fc10-4a04-8b52-45fb26da83c2`::ref=201=20aborting=20= False=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,990::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-2390728::INFO::2013-01-07=20= 12:13:16,995::image::322::Storage.Image::(getChain)=20= sdUUID=3D2a1939bd-9fa3-4896-b8a9-46234172aae7=20= imgUUID=3D12a6472f-9ab9-436a-8508-b6721cb2b227=20= chain=3D[<storage.fileVolume.FileVolume=20object=20at=200x7f7d946190d0>]=20= =0AThread-2390728::INFO::2013-01-07=20= 12:13:16,996::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= prepareImage,=20Return=20response:=20{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'chain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]}=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,997::task::1151::TaskManager.Task::(prepare)=20= Task=3D`c8efa769-fc10-4a04-8b52-45fb26da83c2`::finished:=20{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'chain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]}=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,997::task::568::TaskManager.Task::(_updateState)=20= Task=3D`c8efa769-fc10-4a04-8b52-45fb26da83c2`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,997::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7':=20<=20ResourceRef=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,997::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,997::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,998::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20= (0=20active=20users)=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:16,998::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,998::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7',=20Clearing=20records.=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:16,998::task::957::TaskManager.Task::(_decref)=20= Task=3D`c8efa769-fc10-4a04-8b52-45fb26da83c2`::ref=200=20aborting=20= False=0AThread-2390728::INFO::2013-01-07=20= 12:13:16,998::clientIF::313::vds::(prepareVolumePath)=20prepared=20= volume=20path:=20= /rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896-= b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cdb= b-4dc7-ba7b-4285719615d4=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:17,002::misc::83::Storage.Misc.excCmd::(<lambda>)=20'/usr/bin/sudo=20= -n=20/sbin/service=20ksmtuned=20retune'=20(cwd=20None)=0A= Thread-2390727::DEBUG::2013-01-07=20= 12:13:17,003::API::480::vds::(migrationCreate)=20Destination=20VM=20= creation=20succeeded=0AThread-2390727::DEBUG::2013-01-07=20= 12:13:17,010::BindingXMLRPC::890::vds::(wrapper)=20return=20= vmMigrationCreate=20with=20{'status':=20{'message':=20'Done',=20'code':=20= 0},=20'migrationPort':=200,=20'params':=20{'status':=20'Migration=20= Destination',=20'acpiEnable':=20'true',=20'emulatedMachine':=20'pc',=20= 'afterMigrationStatus':=20'Up',=20'pid':=20'0',=20= 'transparentHugePages':=20'true',=20'displaySecurePort':=20'-1',=20= 'timeOffset':=20-2,=20'cpuType':=20'Nehalem',=20'smp':=20'1',=20= 'pauseCode':=20'NOERR',=20'migrationDest':=20'libvirt',=20'custom':=20= {},=20'vmType':=20'kvm',=20'spiceSslCipherSuite':=20'DEFAULT',=20= 'memSize':=201024,=20'vmName':=20'test004.domainname',=20'nice':=20'0',=20= 'username':=20'Unknown',=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'displayIp':=20= '10.192.42.165',=20'keyboardLayout':=20'en-us',=20'displayPort':=20'-1',=20= 'guestIPs':=20'',=20'spiceSecureChannels':=20= 'smain,sinputs,scursor,splayback,srecord,sdisplay',=20'nicModel':=20= 'rtl8139,pv',=20'smpCoresPerSocket':=20'1',=20'kvmEnable':=20'true',=20= 'pitReinjection':=20'false',=20'displayNetwork':=20'ovirtmgmt',=20= 'devices':=20[{'device':=20'usb',=20'alias':=20'usb0',=20'type':=20= 'controller',=20'address':=20{'slot':=20'0x01',=20'bus':=20'0x00',=20= 'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20'0x2'}},=20= {'device':=20'ide',=20'alias':=20'ide0',=20'type':=20'controller',=20= 'address':=20{'slot':=20'0x01',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x1'}},=20{'device':=20= 'virtio-serial',=20'alias':=20'virtio-serial0',=20'type':=20= 'controller',=20'address':=20{'slot':=20'0x04',=20'bus':=20'0x00',=20= 'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20'0x0'}},=20= {'specParams':=20{'vram':=20'65536'},=20'alias':=20'video0',=20= 'deviceId':=20'0f10b02a-f6bc-432d-bc49-478facf49730',=20'address':=20= {'slot':=20'0x02',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20= 'pci',=20'function':=20'0x0'},=20'device':=20'qxl',=20'type':=20= 'video'},=20{'nicModel':=20'pv',=20'macAddr':=20'00:1a:4a:c0:2a:05',=20= 'network':=20'ovirtmgmt',=20'alias':=20'net0',=20'specParams':=20{},=20= 'deviceId':=20'376d1987-d374-486d-8a62-d48ab0a47eb1',=20'address':=20= {'slot':=20'0x03',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20= 'pci',=20'function':=20'0x0'},=20'device':=20'bridge',=20'type':=20= 'interface',=20'name':=20'vnet2'},=20{'target':=201048576,=20= 'specParams':=20{'model':=20'virtio'},=20'alias':=20'balloon0',=20= 'deviceId':=20'72aaa60a-34e5-41e1-80ea-d9b1c3a1b4e2',=20'address':=20= {'slot':=20'0x06',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20= 'pci',=20'function':=20'0x0'},=20'device':=20'memballoon',=20'type':=20= 'balloon'},=20{'index':=20'2',=20'iface':=20'ide',=20'name':=20'hdc',=20= 'alias':=20'ide0-1-0',=20'shared':=20'false',=20'specParams':=20{'path':=20= 'cobbler-base.iso'},=20'readonly':=20'True',=20'deviceId':=20= '58cff440-2f4d-4bbe-94d9-d7c12df85c4d',=20'address':=20{'bus':=20'1',=20= 'controller':=20'0',=20'type':=20'drive',=20'target':=20'0',=20'unit':=20= '0'},=20'device':=20'cdrom',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobbler-bas= e.iso',=20'type':=20'disk'},=20{'poolID':=20= 'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20'index':=200,=20'iface':=20= 'virtio',=20'apparentsize':=20'21474836480',=20'alias':=20= 'virtio-disk0',=20'imageID':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'readonly':=20'False',=20'shared':=20'false',=20'truesize':=20= '2936401920',=20'type':=20'disk',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'reqsize':=20'0',=20'format':=20= 'raw',=20'deviceId':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'address':=20{'slot':=20'0x05',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x0'},=20'device':=20= 'disk',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'propagateErrors':=20'off',=20'optional':=20= 'false',=20'name':=20'vda',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'specParams':=20{},=20= 'volumeChain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]},=20{'device':=20'unix',=20= 'alias':=20'channel0',=20'type':=20'channel',=20'address':=20{'bus':=20= '0',=20'controller':=20'0',=20'type':=20'virtio-serial',=20'port':=20= '1'}},=20{'device':=20'unix',=20'alias':=20'channel1',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'2'}},=20{'device':=20'spicevmc',=20= 'alias':=20'channel2',=20'type':=20'channel',=20'address':=20{'bus':=20= '0',=20'controller':=20'0',=20'type':=20'virtio-serial',=20'port':=20= '3'}}],=20'clientIp':=20'',=20'display':=20'qxl'}}=0A= Thread-2390728::DEBUG::2013-01-07=20= 12:13:17,035::misc::83::Storage.Misc.excCmd::(<lambda>)=20SUCCESS:=20= <err>=20=3D=20'';=20<rc>=20=3D=200=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:17,036::vm::611::vm.Vm::(_startUnderlyingVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::_ongoingCreations=20= released=0AThread-2390728::DEBUG::2013-01-07=20= 12:13:17,036::libvirtvm::1669::vm.Vm::(_waitForIncomingMigrationFinish)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Waiting=20300=20seconds=20= for=20end=20of=20migration=0AThread-12621::DEBUG::2013-01-07=20= 12:13:17,148::task::568::TaskManager.Task::(_updateState)=20= Task=3D`3d3eb9e9-9c85-410e-a679-cf50f2ac763e`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-12621::INFO::2013-01-07=20= 12:13:17,149::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'024845f8-ebda-4f74-85c4-c8525eb3ce87',=20= volUUID=3D'cec87811-89c8-4daa-a49b-ee870c79db73',=20options=3DNone)=0A= Thread-12621::DEBUG::2013-01-07=20= 12:13:17,150::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20cec87811-89c8-4daa-a49b-ee870c79db73=0A= Thread-12621::DEBUG::2013-01-07=20= 12:13:17,169::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20cec87811-89c8-4daa-a49b-ee870c79db73=0A= Thread-12621::INFO::2013-01-07=20= 12:13:17,171::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize,=20Return=20response:=20{'truesize':=20'10737422336',=20= 'apparentsize':=20'10737418240'}=0AThread-12621::DEBUG::2013-01-07=20= 12:13:17,171::task::1151::TaskManager.Task::(prepare)=20= Task=3D`3d3eb9e9-9c85-410e-a679-cf50f2ac763e`::finished:=20{'truesize':=20= '10737422336',=20'apparentsize':=20'10737418240'}=0A= Thread-12621::DEBUG::2013-01-07=20= 12:13:17,171::task::568::TaskManager.Task::(_updateState)=20= Task=3D`3d3eb9e9-9c85-410e-a679-cf50f2ac763e`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-12621::DEBUG::2013-01-07=20= 12:13:17,171::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-12621::DEBUG::2013-01-07=20= 12:13:17,171::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-12621::DEBUG::2013-01-07=20= 12:13:17,172::task::957::TaskManager.Task::(_decref)=20= Task=3D`3d3eb9e9-9c85-410e-a679-cf50f2ac763e`::ref=200=20aborting=20= False=0AThread-2390731::DEBUG::2013-01-07=20= 12:13:17,393::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.207]::call=20vmGetStats=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-2390731::DEBUG::2013-01-07=20= 12:13:17,393::BindingXMLRPC::890::vds::(wrapper)=20return=20vmGetStats=20= with=20{'status':=20{'message':=20'Done',=20'code':=200},=20'statsList':=20= [{'status':=20'Migration=20Destination',=20'hash':=20'0',=20= 'acpiEnable':=20'true',=20'pid':=20'0',=20'displayIp':=20= '10.192.42.165',=20'displayPort':=20'-1',=20'displaySecurePort':=20'-1',=20= 'timeOffset':=20-2,=20'pauseCode':=20'NOERR',=20'kvmEnable':=20'true',=20= 'network':=20{},=20'vmId':=20'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20= 'displayType':=20'qxl',=20'disks':=20{},=20'monitorResponse':=20'0',=20= 'elapsedTime':=20'1626933',=20'vmType':=20'kvm',=20'clientIp':=20''}]}=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,685::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.196]::call=20vmDestroy=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-2390732::INFO::2013-01-07=20= 12:13:17,685::API::308::vds::(destroy)=20vmContainerLock=20acquired=20by=20= vm=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,686::libvirtvm::2209::vm.Vm::(destroy)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::destroy=20Called=0A= Thread-2390732::INFO::2013-01-07=20= 12:13:17,686::libvirtvm::2160::vm.Vm::(releaseVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Release=20VM=20resources=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,686::misc::83::Storage.Misc.excCmd::(<lambda>)=20'/usr/bin/sudo=20= -n=20/sbin/service=20ksmtuned=20retune'=20(cwd=20None)=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,726::misc::83::Storage.Misc.excCmd::(<lambda>)=20SUCCESS:=20= <err>=20=3D=20'';=20<rc>=20=3D=200=0AThread-2390732::DEBUG::2013-01-07=20= 12:13:17,727::task::568::TaskManager.Task::(_updateState)=20= Task=3D`d8fca4ca-621a-4652-8c2c-fae51778e6d1`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390732::INFO::2013-01-07=20= 12:13:17,727::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= inappropriateDevices(thiefId=3D'cfb17b98-1476-4fbf-9fab-7c7f48b60adf')=0A= Thread-2390732::INFO::2013-01-07=20= 12:13:17,729::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= inappropriateDevices,=20Return=20response:=20None=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,730::task::1151::TaskManager.Task::(prepare)=20= Task=3D`d8fca4ca-621a-4652-8c2c-fae51778e6d1`::finished:=20None=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,730::task::568::TaskManager.Task::(_updateState)=20= Task=3D`d8fca4ca-621a-4652-8c2c-fae51778e6d1`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390732::DEBUG::2013-01-07=20= 12:13:17,730::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,730::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390732::DEBUG::2013-01-07=20= 12:13:17,730::task::957::TaskManager.Task::(_decref)=20= Task=3D`d8fca4ca-621a-4652-8c2c-fae51778e6d1`::ref=200=20aborting=20= False=0AThread-2390732::DEBUG::2013-01-07=20= 12:13:17,731::libvirtvm::2203::vm.Vm::(deleteVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Total=20desktops=20after=20= destroy=20of=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=20is=201=0A= Thread-2390732::DEBUG::2013-01-07=20= 12:13:17,731::BindingXMLRPC::890::vds::(wrapper)=20return=20vmDestroy=20= with=20{'status':=20{'message':=20'Machine=20destroyed',=20'code':=200}}=0A= Thread-2390734::DEBUG::2013-01-07=20= 12:13:21,438::task::568::TaskManager.Task::(_updateState)=20= Task=3D`1d0b3f03-6f40-48c1-8813-e272d6fc7af4`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390734::INFO::2013-01-07=20= 12:13:21,438::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-2390734::INFO::2013-01-07=20= 12:13:21,439::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00211310386658',=20'lastCheck':=20'4.6',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00226402282715',=20'lastCheck':=20'7.3',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00216794013977',=20'lastCheck':=20'7.2',=20'code':=200,=20'valid':=20= True}}=0AThread-2390734::DEBUG::2013-01-07=20= 12:13:21,439::task::1151::TaskManager.Task::(prepare)=20= Task=3D`1d0b3f03-6f40-48c1-8813-e272d6fc7af4`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00211310386658',=20'lastCheck':=20'4.6',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00226402282715',=20'lastCheck':=20'7.3',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00216794013977',=20'lastCheck':=20'7.2',=20'code':=200,=20'valid':=20= True}}=0AThread-2390734::DEBUG::2013-01-07=20= 12:13:21,439::task::568::TaskManager.Task::(_updateState)=20= Task=3D`1d0b3f03-6f40-48c1-8813-e272d6fc7af4`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390734::DEBUG::2013-01-07=20= 12:13:21,439::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390734::DEBUG::2013-01-07=20= 12:13:21,439::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390734::DEBUG::2013-01-07=20= 12:13:21,439::task::957::TaskManager.Task::(_decref)=20= Task=3D`1d0b3f03-6f40-48c1-8813-e272d6fc7af4`::ref=200=20aborting=20= False=0AThread-2390735::DEBUG::2013-01-07=20= 12:13:21,453::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`a08884f6-d634-4d1d-a0ef-f77cd96f0953`::Disk=20vda=20latency=20= not=20available=0AThread-2390736::DEBUG::2013-01-07=20= 12:13:22,932::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390736::DEBUG::2013-01-07=20= 12:13:22,932::task::568::TaskManager.Task::(_updateState)=20= Task=3D`c8bd5b6e-553b-49b7-b4ac-ae89b70f4ad6`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390736::INFO::2013-01-07=20= 12:13:22,932::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390736::INFO::2013-01-07=20= 12:13:22,933::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus,=20Return=20response:=20{'spm_st':=20{'spmId':=201,=20= 'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390736::DEBUG::2013-01-07=20= 12:13:22,933::task::1151::TaskManager.Task::(prepare)=20= Task=3D`c8bd5b6e-553b-49b7-b4ac-ae89b70f4ad6`::finished:=20{'spm_st':=20= {'spmId':=201,=20'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390736::DEBUG::2013-01-07=20= 12:13:22,933::task::568::TaskManager.Task::(_updateState)=20= Task=3D`c8bd5b6e-553b-49b7-b4ac-ae89b70f4ad6`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390736::DEBUG::2013-01-07=20= 12:13:22,933::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390736::DEBUG::2013-01-07=20= 12:13:22,933::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390736::DEBUG::2013-01-07=20= 12:13:22,934::task::957::TaskManager.Task::(_decref)=20= Task=3D`c8bd5b6e-553b-49b7-b4ac-ae89b70f4ad6`::ref=200=20aborting=20= False=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,944::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,944::task::568::TaskManager.Task::(_updateState)=20= Task=3D`0488b8ac-6c6a-4d18-ad09-f2bacdb5126e`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390737::INFO::2013-01-07=20= 12:13:22,944::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,945::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`7bed9027-= 0cb9-4317-af0b-5beaec3bb02b`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,945::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20for=20lock=20type=20= 'shared'=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,945::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,946::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`7bed9027-= 0cb9-4317-af0b-5beaec3bb02b`::Granted=20request=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,946::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`0488b8ac-6c6a-4d18-ad09-f2bacdb5126e`::_resourcesAcquired:=20= Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7=20(shared)=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,946::task::957::TaskManager.Task::(_decref)=20= Task=3D`0488b8ac-6c6a-4d18-ad09-f2bacdb5126e`::ref=201=20aborting=20= False=0AThread-2390737::INFO::2013-01-07=20= 12:13:22,951::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo,=20Return=20response:=20{'info':=20{'spm_id':=201,=20= 'master_uuid':=20'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20= 'Default',=20'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,951::task::1151::TaskManager.Task::(prepare)=20= Task=3D`0488b8ac-6c6a-4d18-ad09-f2bacdb5126e`::finished:=20{'info':=20= {'spm_id':=201,=20'master_uuid':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20'Default',=20= 'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,951::task::568::TaskManager.Task::(_updateState)=20= Task=3D`0488b8ac-6c6a-4d18-ad09-f2bacdb5126e`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,951::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7':=20<=20ResourceRef=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,951::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,952::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,952::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20= (0=20active=20users)=0AThread-2390737::DEBUG::2013-01-07=20= 12:13:22,952::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,952::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20Clearing=20records.=0A= Thread-2390737::DEBUG::2013-01-07=20= 12:13:22,952::task::957::TaskManager.Task::(_decref)=20= Task=3D`0488b8ac-6c6a-4d18-ad09-f2bacdb5126e`::ref=200=20aborting=20= False=0AThread-2390742::DEBUG::2013-01-07=20= 12:13:31,612::task::568::TaskManager.Task::(_updateState)=20= Task=3D`e0222004-6205-4369-b072-b3ce4dea1ac4`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390742::INFO::2013-01-07=20= 12:13:31,612::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-2390742::INFO::2013-01-07=20= 12:13:31,613::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00247502326965',=20'lastCheck':=20'4.8',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.002277135849',=20'lastCheck':=20'7.5',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00219702720642',=20'lastCheck':=20'7.4',=20'code':=200,=20'valid':=20= True}}=0AThread-2390742::DEBUG::2013-01-07=20= 12:13:31,613::task::1151::TaskManager.Task::(prepare)=20= Task=3D`e0222004-6205-4369-b072-b3ce4dea1ac4`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00247502326965',=20'lastCheck':=20'4.8',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.002277135849',=20'lastCheck':=20'7.5',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00219702720642',=20'lastCheck':=20'7.4',=20'code':=200,=20'valid':=20= True}}=0AThread-2390742::DEBUG::2013-01-07=20= 12:13:31,613::task::568::TaskManager.Task::(_updateState)=20= Task=3D`e0222004-6205-4369-b072-b3ce4dea1ac4`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390742::DEBUG::2013-01-07=20= 12:13:31,613::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390742::DEBUG::2013-01-07=20= 12:13:31,613::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390742::DEBUG::2013-01-07=20= 12:13:31,614::task::957::TaskManager.Task::(_decref)=20= Task=3D`e0222004-6205-4369-b072-b3ce4dea1ac4`::ref=200=20aborting=20= False=0AThread-2390743::DEBUG::2013-01-07=20= 12:13:31,626::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`a08884f6-d634-4d1d-a0ef-f77cd96f0953`::Disk=20vda=20latency=20= not=20available=0AThread-2390744::DEBUG::2013-01-07=20= 12:13:33,032::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390744::DEBUG::2013-01-07=20= 12:13:33,032::task::568::TaskManager.Task::(_updateState)=20= Task=3D`984bf1f7-c605-49df-91f1-ebf69624a5e1`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390744::INFO::2013-01-07=20= 12:13:33,032::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390744::INFO::2013-01-07=20= 12:13:33,033::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus,=20Return=20response:=20{'spm_st':=20{'spmId':=201,=20= 'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390744::DEBUG::2013-01-07=20= 12:13:33,033::task::1151::TaskManager.Task::(prepare)=20= Task=3D`984bf1f7-c605-49df-91f1-ebf69624a5e1`::finished:=20{'spm_st':=20= {'spmId':=201,=20'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390744::DEBUG::2013-01-07=20= 12:13:33,033::task::568::TaskManager.Task::(_updateState)=20= Task=3D`984bf1f7-c605-49df-91f1-ebf69624a5e1`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390744::DEBUG::2013-01-07=20= 12:13:33,033::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390744::DEBUG::2013-01-07=20= 12:13:33,033::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390744::DEBUG::2013-01-07=20= 12:13:33,033::task::957::TaskManager.Task::(_decref)=20= Task=3D`984bf1f7-c605-49df-91f1-ebf69624a5e1`::ref=200=20aborting=20= False=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,044::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,044::task::568::TaskManager.Task::(_updateState)=20= Task=3D`fdc15232-1311-4ca5-aed0-01716d137963`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390745::INFO::2013-01-07=20= 12:13:33,044::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,045::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`bfe0adcf-= 6b5d-4970-9916-7bcbdc083569`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,045::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20for=20lock=20type=20= 'shared'=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,045::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,045::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`bfe0adcf-= 6b5d-4970-9916-7bcbdc083569`::Granted=20request=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,046::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`fdc15232-1311-4ca5-aed0-01716d137963`::_resourcesAcquired:=20= Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7=20(shared)=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,046::task::957::TaskManager.Task::(_decref)=20= Task=3D`fdc15232-1311-4ca5-aed0-01716d137963`::ref=201=20aborting=20= False=0AThread-2390745::INFO::2013-01-07=20= 12:13:33,049::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo,=20Return=20response:=20{'info':=20{'spm_id':=201,=20= 'master_uuid':=20'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20= 'Default',=20'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,050::task::1151::TaskManager.Task::(prepare)=20= Task=3D`fdc15232-1311-4ca5-aed0-01716d137963`::finished:=20{'info':=20= {'spm_id':=201,=20'master_uuid':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20'Default',=20= 'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,050::task::568::TaskManager.Task::(_updateState)=20= Task=3D`fdc15232-1311-4ca5-aed0-01716d137963`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,050::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7':=20<=20ResourceRef=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,050::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,050::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,051::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20= (0=20active=20users)=0AThread-2390745::DEBUG::2013-01-07=20= 12:13:33,051::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,051::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20Clearing=20records.=0A= Thread-2390745::DEBUG::2013-01-07=20= 12:13:33,051::task::957::TaskManager.Task::(_decref)=20= Task=3D`fdc15232-1311-4ca5-aed0-01716d137963`::ref=200=20aborting=20= False=0AThread-2390750::DEBUG::2013-01-07=20= 12:13:41,773::task::568::TaskManager.Task::(_updateState)=20= Task=3D`bce4c21e-17ac-4aaa-9ff5-6685b8e6dae7`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390750::INFO::2013-01-07=20= 12:13:41,774::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-2390750::INFO::2013-01-07=20= 12:13:41,774::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00256395339966',=20'lastCheck':=20'4.9',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00182700157166',=20'lastCheck':=20'7.7',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00169897079468',=20'lastCheck':=20'7.5',=20'code':=200,=20'valid':=20= True}}=0AThread-2390750::DEBUG::2013-01-07=20= 12:13:41,774::task::1151::TaskManager.Task::(prepare)=20= Task=3D`bce4c21e-17ac-4aaa-9ff5-6685b8e6dae7`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00256395339966',=20'lastCheck':=20'4.9',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00182700157166',=20'lastCheck':=20'7.7',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00169897079468',=20'lastCheck':=20'7.5',=20'code':=200,=20'valid':=20= True}}=0AThread-2390750::DEBUG::2013-01-07=20= 12:13:41,774::task::568::TaskManager.Task::(_updateState)=20= Task=3D`bce4c21e-17ac-4aaa-9ff5-6685b8e6dae7`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390750::DEBUG::2013-01-07=20= 12:13:41,775::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390750::DEBUG::2013-01-07=20= 12:13:41,775::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390750::DEBUG::2013-01-07=20= 12:13:41,775::task::957::TaskManager.Task::(_decref)=20= Task=3D`bce4c21e-17ac-4aaa-9ff5-6685b8e6dae7`::ref=200=20aborting=20= False=0AThread-2390751::DEBUG::2013-01-07=20= 12:13:41,788::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`a08884f6-d634-4d1d-a0ef-f77cd96f0953`::Disk=20vda=20latency=20= not=20available=0AThread-2390752::DEBUG::2013-01-07=20= 12:13:43,131::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390752::DEBUG::2013-01-07=20= 12:13:43,132::task::568::TaskManager.Task::(_updateState)=20= Task=3D`7368bb35-b085-4fde-858d-d7945df1f6a5`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390752::INFO::2013-01-07=20= 12:13:43,132::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390752::INFO::2013-01-07=20= 12:13:43,132::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus,=20Return=20response:=20{'spm_st':=20{'spmId':=201,=20= 'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390752::DEBUG::2013-01-07=20= 12:13:43,132::task::1151::TaskManager.Task::(prepare)=20= Task=3D`7368bb35-b085-4fde-858d-d7945df1f6a5`::finished:=20{'spm_st':=20= {'spmId':=201,=20'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2390752::DEBUG::2013-01-07=20= 12:13:43,133::task::568::TaskManager.Task::(_updateState)=20= Task=3D`7368bb35-b085-4fde-858d-d7945df1f6a5`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390752::DEBUG::2013-01-07=20= 12:13:43,133::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2390752::DEBUG::2013-01-07=20= 12:13:43,133::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390752::DEBUG::2013-01-07=20= 12:13:43,133::task::957::TaskManager.Task::(_decref)=20= Task=3D`7368bb35-b085-4fde-858d-d7945df1f6a5`::ref=200=20aborting=20= False=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,143::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,144::task::568::TaskManager.Task::(_updateState)=20= Task=3D`98135fe0-6b39-4fab-b347-98543cf54bc6`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2390753::INFO::2013-01-07=20= 12:13:43,144::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,144::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`0867c186-= db83-4573-b843-63d2737ffaff`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,144::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20for=20lock=20type=20= 'shared'=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,145::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,145::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`0867c186-= db83-4573-b843-63d2737ffaff`::Granted=20request=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,145::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`98135fe0-6b39-4fab-b347-98543cf54bc6`::_resourcesAcquired:=20= Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7=20(shared)=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,145::task::957::TaskManager.Task::(_decref)=20= Task=3D`98135fe0-6b39-4fab-b347-98543cf54bc6`::ref=201=20aborting=20= False=0AThread-2390753::INFO::2013-01-07=20= 12:13:43,149::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo,=20Return=20response:=20{'info':=20{'spm_id':=201,=20= 'master_uuid':=20'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20= 'Default',=20'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,149::task::1151::TaskManager.Task::(prepare)=20= Task=3D`98135fe0-6b39-4fab-b347-98543cf54bc6`::finished:=20{'info':=20= {'spm_id':=201,=20'master_uuid':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20'Default',=20= 'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,149::task::568::TaskManager.Task::(_updateState)=20= Task=3D`98135fe0-6b39-4fab-b347-98543cf54bc6`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,149::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7':=20<=20ResourceRef=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,150::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,150::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,150::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20= (0=20active=20users)=0AThread-2390753::DEBUG::2013-01-07=20= 12:13:43,150::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,150::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20Clearing=20records.=0A= Thread-2390753::DEBUG::2013-01-07=20= 12:13:43,151::task::957::TaskManager.Task::(_decref)=20= Task=3D`98135fe0-6b39-4fab-b347-98543cf54bc6`::ref=200=20aborting=20= False=0A= --Apple-Mail=_B91DF312-1386-4884-ADD0-7FF314F05FC2--
On 01/07/2013 01:18 PM, Tom Brown wrote:
VDSM is the virtualization agent. look at /var/log/vdsm/vdsm.log many thanks - attached is the snip of that log when i try the migration
thanks
can you attach the same snip from the src VDSM 10.192.42.196 as well?
--Apple-Mail=_C82D1F4B-8BD2-4AB4-8D7E-7DAE9D5676F1 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=iso-8859-1
can you attach the same snip from the src VDSM 10.192.42.196 as well?
The log is pretty chatty therefore i did another migration attempt and = snipd'd the new=20= --Apple-Mail=_C82D1F4B-8BD2-4AB4-8D7E-7DAE9D5676F1 Content-Disposition: attachment; filename=migrate-dest.log Content-Type: application/octet-stream; name="migrate-dest.log" Content-Transfer-Encoding: quoted-printable Thread-2456765::DEBUG::2013-01-08=20= 10:42:20,119::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2456765::DEBUG::2013-01-08=20= 10:42:20,119::task::568::TaskManager.Task::(_updateState)=20= Task=3D`d9cc7d0f-4fa3-4374-9b65-232df90c5b73`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2456765::INFO::2013-01-08=20= 10:42:20,119::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2456765::INFO::2013-01-08=20= 10:42:20,120::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getSpmStatus,=20Return=20response:=20{'spm_st':=20{'spmId':=201,=20= 'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2456765::DEBUG::2013-01-08=20= 10:42:20,120::task::1151::TaskManager.Task::(prepare)=20= Task=3D`d9cc7d0f-4fa3-4374-9b65-232df90c5b73`::finished:=20{'spm_st':=20= {'spmId':=201,=20'spmStatus':=20'SPM',=20'spmLver':=200}}=0A= Thread-2456765::DEBUG::2013-01-08=20= 10:42:20,120::task::568::TaskManager.Task::(_updateState)=20= Task=3D`d9cc7d0f-4fa3-4374-9b65-232df90c5b73`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2456765::DEBUG::2013-01-08=20= 10:42:20,120::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2456765::DEBUG::2013-01-08=20= 10:42:20,120::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2456765::DEBUG::2013-01-08=20= 10:42:20,121::task::957::TaskManager.Task::(_decref)=20= Task=3D`d9cc7d0f-4fa3-4374-9b65-232df90c5b73`::ref=200=20aborting=20= False=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,131::BindingXMLRPC::161::vds::(wrapper)=20[10.192.42.207]=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,131::task::568::TaskManager.Task::(_updateState)=20= Task=3D`e84910c4-d6fb-4907-a445-0751d91d715f`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2456766::INFO::2013-01-08=20= 10:42:20,132::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo(spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= options=3DNone)=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,132::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`f3f58cc3-= e5b9-4a3f-8370-b812e40d62cb`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,132::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20for=20lock=20type=20= 'shared'=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,132::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,133::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7`ReqID=3D`f3f58cc3-= e5b9-4a3f-8370-b812e40d62cb`::Granted=20request=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,133::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`e84910c4-d6fb-4907-a445-0751d91d715f`::_resourcesAcquired:=20= Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7=20(shared)=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,133::task::957::TaskManager.Task::(_decref)=20= Task=3D`e84910c4-d6fb-4907-a445-0751d91d715f`::ref=201=20aborting=20= False=0AThread-2456766::INFO::2013-01-08=20= 10:42:20,137::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getStoragePoolInfo,=20Return=20response:=20{'info':=20{'spm_id':=201,=20= 'master_uuid':=20'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20= 'Default',=20'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,137::task::1151::TaskManager.Task::(prepare)=20= Task=3D`e84910c4-d6fb-4907-a445-0751d91d715f`::finished:=20{'info':=20= {'spm_id':=201,=20'master_uuid':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'name':=20'Default',=20= 'version':=20'0',=20'domains':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7:Active,ab686999-f320-4a61-ae07-e99c2= f858996:Active,9cff8858-9188-42eb-b089-22f89719394d:Active',=20= 'pool_status':=20'connected',=20'isoprefix':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111',=20= 'type':=20'NFS',=20'master_ver':=201,=20'lver':=200},=20'dominfo':=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'status':=20= 'Active',=20'diskfree':=20'177508712448',=20'alerts':=20[],=20= 'disktotal':=20'211379027968'},=20= '9cff8858-9188-42eb-b089-22f89719394d':=20{'status':=20'Active',=20= 'diskfree':=20'177508712448',=20'alerts':=20[],=20'disktotal':=20= '211379027968'}}}=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,137::task::568::TaskManager.Task::(_updateState)=20= Task=3D`e84910c4-d6fb-4907-a445-0751d91d715f`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,137::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7':=20<=20ResourceRef=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,138::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,138::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,138::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20= (0=20active=20users)=0AThread-2456766::DEBUG::2013-01-08=20= 10:42:20,138::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,138::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20Clearing=20records.=0A= Thread-2456766::DEBUG::2013-01-08=20= 10:42:20,139::task::957::TaskManager.Task::(_decref)=20= Task=3D`e84910c4-d6fb-4907-a445-0751d91d715f`::ref=200=20aborting=20= False=0AThread-2456768::DEBUG::2013-01-08=20= 10:42:20,892::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.196]::call=20vmGetStats=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-2456768::DEBUG::2013-01-08=20= 10:42:20,892::BindingXMLRPC::890::vds::(wrapper)=20return=20vmGetStats=20= with=20{'status':=20{'message':=20'Virtual=20machine=20does=20not=20= exist',=20'code':=201}}=0AThread-2456769::DEBUG::2013-01-08=20= 10:42:21,294::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.196]::call=20vmMigrationCreate=20with=20({'username':=20= 'Unknown',=20'acpiEnable':=20'true',=20'emulatedMachine':=20'pc',=20= 'afterMigrationStatus':=20'Up',=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'transparentHugePages':=20= 'true',=20'displaySecurePort':=20'5905',=20'timeOffset':=20-2,=20= 'cpuType':=20'Nehalem',=20'custom':=20{},=20'pauseCode':=20'NOERR',=20= 'migrationDest':=20'libvirt',=20'smp':=20'1',=20'vmType':=20'kvm',=20= 'spiceSslCipherSuite':=20'DEFAULT',=20'_srcDomXML':=20"<domain=20= type=3D'kvm'=20id=3D'4'>\n=20=20<name>test004.domainname.ads</name>\n=20=20= <uuid>cfb17b98-1476-4fbf-9fab-7c7f48b60adf</uuid>\n=20=20<memory=20= unit=3D'KiB'>1048576</memory>\n=20=20<currentMemory=20= unit=3D'KiB'>1048576</currentMemory>\n=20=20<vcpu=20= placement=3D'static'>1</vcpu>\n=20=20<cputune>\n=20=20=20=20= <shares>1020</shares>\n=20=20</cputune>\n=20=20<sysinfo=20= type=3D'smbios'>\n=20=20=20=20<system>\n=20=20=20=20=20=20<entry=20= name=3D'manufacturer'>oVirt</entry>\n=20=20=20=20=20=20<entry=20= name=3D'product'>oVirt=20Node</entry>\n=20=20=20=20=20=20<entry=20= name=3D'version'>6-3.el6.centos.9</entry>\n=20=20=20=20=20=20<entry=20= name=3D'serial'>55414E03-C241-11DF-BBDA-64093408D485_d4:85:64:09:34:08</en= try>\n=20=20=20=20=20=20<entry=20= name=3D'uuid'>cfb17b98-1476-4fbf-9fab-7c7f48b60adf</entry>\n=20=20=20=20= </system>\n=20=20</sysinfo>\n=20=20<os>\n=20=20=20=20<type=20= arch=3D'x86_64'=20machine=3D'rhel6.3.0'>hvm</type>\n=20=20=20=20<boot=20= dev=3D'hd'/>\n=20=20=20=20<smbios=20mode=3D'sysinfo'/>\n=20=20</os>\n=20=20= <features>\n=20=20=20=20<acpi/>\n=20=20</features>\n=20=20<cpu=20= mode=3D'custom'=20match=3D'exact'>\n=20=20=20=20<model=20= fallback=3D'allow'>Nehalem</model>\n=20=20=20=20<topology=20sockets=3D'1'=20= cores=3D'1'=20threads=3D'1'/>\n=20=20</cpu>\n=20=20<clock=20= offset=3D'variable'=20adjustment=3D'-2'>\n=20=20=20=20<timer=20= name=3D'rtc'=20tickpolicy=3D'catchup'/>\n=20=20</clock>\n=20=20= <on_poweroff>destroy</on_poweroff>\n=20=20= <on_reboot>restart</on_reboot>\n=20=20<on_crash>destroy</on_crash>\n=20=20= <devices>\n=20=20=20=20<emulator>/usr/libexec/qemu-kvm</emulator>\n=20=20= =20=20<disk=20type=3D'file'=20device=3D'cdrom'>\n=20=20=20=20=20=20= <driver=20name=3D'qemu'=20type=3D'raw'/>\n=20=20=20=20=20=20<source=20= file=3D'/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f3= 20-4a61-ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobb= ler-base.iso'=20startupPolicy=3D'optional'/>\n=20=20=20=20=20=20<target=20= dev=3D'hdc'=20bus=3D'ide'/>\n=20=20=20=20=20=20<readonly/>\n=20=20=20=20=20= =20<serial></serial>\n=20=20=20=20=20=20<alias=20name=3D'ide0-1-0'/>\n=20= =20=20=20=20=20<address=20type=3D'drive'=20controller=3D'0'=20bus=3D'1'=20= target=3D'0'=20unit=3D'0'/>\n=20=20=20=20</disk>\n=20=20=20=20<disk=20= type=3D'file'=20device=3D'disk'=20snapshot=3D'no'>\n=20=20=20=20=20=20= <driver=20name=3D'qemu'=20type=3D'raw'=20cache=3D'none'=20= error_policy=3D'stop'=20io=3D'threads'/>\n=20=20=20=20=20=20<source=20= file=3D'/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9f= a3-4896-b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e= 7b27-cdbb-4dc7-ba7b-4285719615d4'/>\n=20=20=20=20=20=20<target=20= dev=3D'vda'=20bus=3D'virtio'/>\n=20=20=20=20=20=20= <serial>12a6472f-9ab9-436a-8508-b6721cb2b227</serial>\n=20=20=20=20=20=20= <alias=20name=3D'virtio-disk0'/>\n=20=20=20=20=20=20<address=20= type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x05'=20= function=3D'0x0'/>\n=20=20=20=20</disk>\n=20=20=20=20<controller=20= type=3D'usb'=20index=3D'0'>\n=20=20=20=20=20=20<alias=20name=3D'usb0'/>\n=20= =20=20=20=20=20<address=20type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20= slot=3D'0x01'=20function=3D'0x2'/>\n=20=20=20=20</controller>\n=20=20=20=20= <controller=20type=3D'ide'=20index=3D'0'>\n=20=20=20=20=20=20<alias=20= name=3D'ide0'/>\n=20=20=20=20=20=20<address=20type=3D'pci'=20= domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x01'=20function=3D'0x1'/>\n=20= =20=20=20</controller>\n=20=20=20=20<controller=20type=3D'virtio-serial'=20= index=3D'0'>\n=20=20=20=20=20=20<alias=20name=3D'virtio-serial0'/>\n=20=20= =20=20=20=20<address=20type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20= slot=3D'0x04'=20function=3D'0x0'/>\n=20=20=20=20</controller>\n=20=20=20=20= <interface=20type=3D'bridge'>\n=20=20=20=20=20=20<mac=20= address=3D'00:1a:4a:c0:2a:05'/>\n=20=20=20=20=20=20<source=20= bridge=3D'ovirtmgmt'/>\n=20=20=20=20=20=20<target=20dev=3D'vnet2'/>\n=20=20= =20=20=20=20<model=20type=3D'virtio'/>\n=20=20=20=20=20=20<alias=20= name=3D'net0'/>\n=20=20=20=20=20=20<address=20type=3D'pci'=20= domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x03'=20function=3D'0x0'/>\n=20= =20=20=20</interface>\n=20=20=20=20<console=20type=3D'pty'=20= tty=3D'/dev/pts/2'>\n=20=20=20=20=20=20<source=20path=3D'/dev/pts/2'/>\n=20= =20=20=20=20=20<target=20type=3D'virtio'=20port=3D'0'/>\n=20=20=20=20=20=20= <alias=20name=3D'console0'/>\n=20=20=20=20</console>\n=20=20=20=20= <channel=20type=3D'unix'>\n=20=20=20=20=20=20<source=20mode=3D'bind'=20= path=3D'/var/lib/libvirt/qemu/channels/test004.domainname.ads.com.redhat.r= hevm.vdsm'/>\n=20=20=20=20=20=20<target=20type=3D'virtio'=20= name=3D'com.redhat.rhevm.vdsm'/>\n=20=20=20=20=20=20<alias=20= name=3D'channel0'/>\n=20=20=20=20=20=20<address=20type=3D'virtio-serial'=20= controller=3D'0'=20bus=3D'0'=20port=3D'1'/>\n=20=20=20=20</channel>\n=20=20= =20=20<channel=20type=3D'unix'>\n=20=20=20=20=20=20<source=20mode=3D'bind'= =20= path=3D'/var/lib/libvirt/qemu/channels/test004.domainname.ads.org.qemu.gue= st_agent.0'/>\n=20=20=20=20=20=20<target=20type=3D'virtio'=20= name=3D'org.qemu.guest_agent.0'/>\n=20=20=20=20=20=20<alias=20= name=3D'channel1'/>\n=20=20=20=20=20=20<address=20type=3D'virtio-serial'=20= controller=3D'0'=20bus=3D'0'=20port=3D'2'/>\n=20=20=20=20</channel>\n=20=20= =20=20<channel=20type=3D'spicevmc'>\n=20=20=20=20=20=20<target=20= type=3D'virtio'=20name=3D'com.redhat.spice.0'/>\n=20=20=20=20=20=20= <alias=20name=3D'channel2'/>\n=20=20=20=20=20=20<address=20= type=3D'virtio-serial'=20controller=3D'0'=20bus=3D'0'=20port=3D'3'/>\n=20= =20=20=20</channel>\n=20=20=20=20<input=20type=3D'mouse'=20bus=3D'ps2'/>\n= =20=20=20=20<graphics=20type=3D'spice'=20port=3D'5904'=20tlsPort=3D'5905'=20= autoport=3D'yes'=20keymap=3D'en-us'=20= passwdValidTo=3D'2012-12-19T15:52:56'=20connected=3D'disconnect'>\n=20=20= =20=20=20=20<listen=20type=3D'network'=20address=3D'10.192.42.196'=20= network=3D'vdsm-ovirtmgmt'/>\n=20=20=20=20=20=20<channel=20name=3D'main'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'display'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'inputs'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'cursor'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'playback'=20= mode=3D'secure'/>\n=20=20=20=20=20=20<channel=20name=3D'record'=20= mode=3D'secure'/>\n=20=20=20=20</graphics>\n=20=20=20=20<video>\n=20=20=20= =20=20=20<model=20type=3D'qxl'=20vram=3D'65536'=20heads=3D'1'/>\n=20=20=20= =20=20=20<alias=20name=3D'video0'/>\n=20=20=20=20=20=20<address=20= type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20slot=3D'0x02'=20= function=3D'0x0'/>\n=20=20=20=20</video>\n=20=20=20=20<memballoon=20= model=3D'virtio'>\n=20=20=20=20=20=20<alias=20name=3D'balloon0'/>\n=20=20= =20=20=20=20<address=20type=3D'pci'=20domain=3D'0x0000'=20bus=3D'0x00'=20= slot=3D'0x06'=20function=3D'0x0'/>\n=20=20=20=20</memballoon>\n=20=20= </devices>\n=20=20<seclabel=20type=3D'none'/>\n</domain>\n",=20= 'memSize':=201024,=20'elapsedTimeOffset':=201707876.9180860519,=20= 'vmName':=20'test004.domainname.ads',=20'nice':=20'0',=20'status':=20= 'Up',=20'clientIp':=20'',=20'displayIp':=20'10.192.42.196',=20= 'displayPort':=20'5904',=20'smpCoresPerSocket':=20'1',=20= 'spiceSecureChannels':=20= 'smain,sinputs,scursor,splayback,srecord,sdisplay',=20'nicModel':=20= 'rtl8139,pv',=20'keyboardLayout':=20'en-us',=20'kvmEnable':=20'true',=20= 'pitReinjection':=20'false',=20'displayNetwork':=20'ovirtmgmt',=20= 'devices':=20[{'specParams':=20{'vram':=20'65536'},=20'alias':=20= 'video0',=20'deviceId':=20'0f10b02a-f6bc-432d-bc49-478facf49730',=20= 'address':=20{'slot':=20'0x02',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x0'},=20'device':=20= 'qxl',=20'type':=20'video'},=20{'nicModel':=20'pv',=20'macAddr':=20= '00:1a:4a:c0:2a:05',=20'network':=20'ovirtmgmt',=20'alias':=20'net0',=20= 'specParams':=20{},=20'deviceId':=20= '376d1987-d374-486d-8a62-d48ab0a47eb1',=20'address':=20{'slot':=20= '0x03',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20= 'function':=20'0x0'},=20'device':=20'bridge',=20'type':=20'interface',=20= 'name':=20'vnet2'},=20{'target':=201048576,=20'specParams':=20{'model':=20= 'virtio'},=20'alias':=20'balloon0',=20'deviceId':=20= '72aaa60a-34e5-41e1-80ea-d9b1c3a1b4e2',=20'address':=20{'slot':=20= '0x06',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20= 'function':=20'0x0'},=20'device':=20'memballoon',=20'type':=20= 'balloon'},=20{'index':=20'2',=20'iface':=20'ide',=20'name':=20'hdc',=20= 'alias':=20'ide0-1-0',=20'shared':=20'false',=20'specParams':=20{'path':=20= 'cobbler-base.iso'},=20'readonly':=20'True',=20'deviceId':=20= '58cff440-2f4d-4bbe-94d9-d7c12df85c4d',=20'address':=20{'bus':=20'1',=20= 'controller':=20'0',=20'type':=20'drive',=20'target':=20'0',=20'unit':=20= '0'},=20'device':=20'cdrom',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobbler-bas= e.iso',=20'type':=20'disk'},=20{'poolID':=20= 'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20'index':=200,=20'iface':=20= 'virtio',=20'apparentsize':=20'21474836480',=20'alias':=20= 'virtio-disk0',=20'imageID':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'readonly':=20'False',=20'shared':=20'false',=20'truesize':=20'0',=20= 'type':=20'disk',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'reqsize':=20'0',=20'format':=20= 'raw',=20'deviceId':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'address':=20{'slot':=20'0x05',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x0'},=20'device':=20= 'disk',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'propagateErrors':=20'off',=20'optional':=20= 'false',=20'name':=20'vda',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'specParams':=20{},=20= 'volumeChain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]},=20{'device':=20'usb',=20= 'alias':=20'usb0',=20'type':=20'controller',=20'address':=20{'slot':=20= '0x01',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20= 'function':=20'0x2'}},=20{'device':=20'ide',=20'alias':=20'ide0',=20= 'type':=20'controller',=20'address':=20{'slot':=20'0x01',=20'bus':=20= '0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20= '0x1'}},=20{'device':=20'virtio-serial',=20'alias':=20'virtio-serial0',=20= 'type':=20'controller',=20'address':=20{'slot':=20'0x04',=20'bus':=20= '0x00',=20'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20= '0x0'}},=20{'device':=20'unix',=20'alias':=20'channel0',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'1'}},=20{'device':=20'unix',=20= 'alias':=20'channel1',=20'type':=20'channel',=20'address':=20{'bus':=20= '0',=20'controller':=20'0',=20'type':=20'virtio-serial',=20'port':=20= '2'}},=20{'device':=20'spicevmc',=20'alias':=20'channel2',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'3'}}],=20'guestIPs':=20'',=20= 'display':=20'qxl'},)=20{}=0AThread-2456769::DEBUG::2013-01-08=20= 10:42:21,294::API::467::vds::(migrationCreate)=20Migration=20create=0A= Thread-2456769::INFO::2013-01-08=20= 10:42:21,329::clientIF::331::vds::(createVm)=20vmContainerLock=20= acquired=20by=20vm=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,334::vm::590::vm.Vm::(_startUnderlyingVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Start=0A= Thread-2456769::DEBUG::2013-01-08=20= 10:42:21,335::clientIF::345::vds::(createVm)=20Total=20desktops=20after=20= creation=20of=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=20is=202=0A= Thread-2456769::DEBUG::2013-01-08=20= 10:42:21,335::libvirtvm::2611::vm.Vm::(waitForMigrationDestinationPrepare)= =20vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20= destination:=20waiting=20for=20VM=20creation=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,335::vm::594::vm.Vm::(_startUnderlyingVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::_ongoingCreations=20= acquired=0AThread-2456770::INFO::2013-01-08=20= 10:42:21,335::libvirtvm::1356::vm.Vm::(_run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::VM=20wrapper=20has=20= started=0AThread-2456769::DEBUG::2013-01-08=20= 10:42:21,336::libvirtvm::2617::vm.Vm::(waitForMigrationDestinationPrepare)= =20vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20= destination:=20waiting=2042s=20for=20path=20preparation=0A= Thread-2456770::WARNING::2013-01-08=20= 10:42:21,336::vm::416::vm.Vm::(getConfDevices)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Unknown=20type=20found,=20= device:=20'{'device':=20'unix',=20'alias':=20'channel0',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'1'}}'=20found=0A= Thread-2456770::WARNING::2013-01-08=20= 10:42:21,336::vm::416::vm.Vm::(getConfDevices)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Unknown=20type=20found,=20= device:=20'{'device':=20'unix',=20'alias':=20'channel1',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'2'}}'=20found=0A= Thread-2456770::WARNING::2013-01-08=20= 10:42:21,336::vm::416::vm.Vm::(getConfDevices)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Unknown=20type=20found,=20= device:=20'{'device':=20'spicevmc',=20'alias':=20'channel2',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'3'}}'=20found=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,337::task::568::TaskManager.Task::(_updateState)=20= Task=3D`6f77554d-92e5-4ea2-89e4-3a594a4bbc0f`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2456770::INFO::2013-01-08=20= 10:42:21,337::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= volUUID=3D'732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20options=3DNone)=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,339::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,342::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-2456770::INFO::2013-01-08=20= 10:42:21,343::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize,=20Return=20response:=20{'truesize':=20'2936401920',=20= 'apparentsize':=20'21474836480'}=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,343::task::1151::TaskManager.Task::(prepare)=20= Task=3D`6f77554d-92e5-4ea2-89e4-3a594a4bbc0f`::finished:=20{'truesize':=20= '2936401920',=20'apparentsize':=20'21474836480'}=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,344::task::568::TaskManager.Task::(_updateState)=20= Task=3D`6f77554d-92e5-4ea2-89e4-3a594a4bbc0f`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,344::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,344::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,344::task::957::TaskManager.Task::(_decref)=20= Task=3D`6f77554d-92e5-4ea2-89e4-3a594a4bbc0f`::ref=200=20aborting=20= False=0AThread-2456770::INFO::2013-01-08=20= 10:42:21,344::clientIF::313::vds::(prepareVolumePath)=20prepared=20= volume=20path:=20= /rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61-= ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobbler-base= .iso=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,345::task::568::TaskManager.Task::(_updateState)=20= Task=3D`023694dd-13d1-4507-8a25-9997e00a0067`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2456770::INFO::2013-01-08=20= 10:42:21,345::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= prepareImage(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= volUUID=3D'732e7b27-cdbb-4dc7-ba7b-4285719615d4')=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,345::resourceManager::175::ResourceManager.Request::(__init__)=20= ResName=3D`Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7`ReqID=3D`dc05f7b7-= 01b4-41e6-8dfc-5879d8a45e1c`::Request=20was=20made=20in=20= '/usr/share/vdsm/storage/resourceManager.py'=20line=20'174'=20at=20= '__init__'=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,345::resourceManager::486::ResourceManager::(registerResource)=20= Trying=20to=20register=20resource=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20for=20lock=20type=20= 'shared'=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,346::resourceManager::528::ResourceManager::(registerResource)=20= Resource=20'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20is=20free.=20= Now=20locking=20as=20'shared'=20(1=20active=20user)=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,346::resourceManager::212::ResourceManager.Request::(grant)=20= ResName=3D`Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7`ReqID=3D`dc05f7b7-= 01b4-41e6-8dfc-5879d8a45e1c`::Granted=20request=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,346::task::794::TaskManager.Task::(resourceAcquired)=20= Task=3D`023694dd-13d1-4507-8a25-9997e00a0067`::_resourcesAcquired:=20= Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7=20(shared)=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,346::task::957::TaskManager.Task::(_decref)=20= Task=3D`023694dd-13d1-4507-8a25-9997e00a0067`::ref=201=20aborting=20= False=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,347::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-2456770::INFO::2013-01-08=20= 10:42:21,368::image::322::Storage.Image::(getChain)=20= sdUUID=3D2a1939bd-9fa3-4896-b8a9-46234172aae7=20= imgUUID=3D12a6472f-9ab9-436a-8508-b6721cb2b227=20= chain=3D[<storage.fileVolume.FileVolume=20object=20at=200x7f7d946190d0>]=20= =0AThread-2456770::INFO::2013-01-08=20= 10:42:21,370::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= prepareImage,=20Return=20response:=20{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'chain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]}=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,370::task::1151::TaskManager.Task::(prepare)=20= Task=3D`023694dd-13d1-4507-8a25-9997e00a0067`::finished:=20{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'chain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]}=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,370::task::568::TaskManager.Task::(_updateState)=20= Task=3D`023694dd-13d1-4507-8a25-9997e00a0067`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,370::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20= {'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7':=20<=20ResourceRef=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7',=20isValid:=20'True'=20= obj:=20'None'>}=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,370::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,370::resourceManager::538::ResourceManager::(releaseResource)=20= Trying=20to=20release=20resource=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,371::resourceManager::553::ResourceManager::(releaseResource)=20= Released=20resource=20'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20= (0=20active=20users)=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,371::resourceManager::558::ResourceManager::(releaseResource)=20= Resource=20'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7'=20is=20free,=20= finding=20out=20if=20anyone=20is=20waiting=20for=20it.=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,371::resourceManager::565::ResourceManager::(releaseResource)=20= No=20one=20is=20waiting=20for=20resource=20= 'Storage.2a1939bd-9fa3-4896-b8a9-46234172aae7',=20Clearing=20records.=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,371::task::957::TaskManager.Task::(_decref)=20= Task=3D`023694dd-13d1-4507-8a25-9997e00a0067`::ref=200=20aborting=20= False=0AThread-2456770::INFO::2013-01-08=20= 10:42:21,371::clientIF::313::vds::(prepareVolumePath)=20prepared=20= volume=20path:=20= /rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896-= b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cdb= b-4dc7-ba7b-4285719615d4=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,376::misc::83::Storage.Misc.excCmd::(<lambda>)=20'/usr/bin/sudo=20= -n=20/sbin/service=20ksmtuned=20retune'=20(cwd=20None)=0A= Thread-2456769::DEBUG::2013-01-08=20= 10:42:21,376::API::480::vds::(migrationCreate)=20Destination=20VM=20= creation=20succeeded=0AThread-2456769::DEBUG::2013-01-08=20= 10:42:21,383::BindingXMLRPC::890::vds::(wrapper)=20return=20= vmMigrationCreate=20with=20{'status':=20{'message':=20'Done',=20'code':=20= 0},=20'migrationPort':=200,=20'params':=20{'status':=20'Migration=20= Destination',=20'acpiEnable':=20'true',=20'emulatedMachine':=20'pc',=20= 'afterMigrationStatus':=20'Up',=20'pid':=20'0',=20= 'transparentHugePages':=20'true',=20'displaySecurePort':=20'-1',=20= 'timeOffset':=20-2,=20'cpuType':=20'Nehalem',=20'smp':=20'1',=20= 'pauseCode':=20'NOERR',=20'migrationDest':=20'libvirt',=20'custom':=20= {},=20'vmType':=20'kvm',=20'spiceSslCipherSuite':=20'DEFAULT',=20= 'memSize':=201024,=20'vmName':=20'test004.domainname.ads',=20'nice':=20= '0',=20'username':=20'Unknown',=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'displayIp':=20= '10.192.42.165',=20'keyboardLayout':=20'en-us',=20'displayPort':=20'-1',=20= 'guestIPs':=20'',=20'spiceSecureChannels':=20= 'smain,sinputs,scursor,splayback,srecord,sdisplay',=20'nicModel':=20= 'rtl8139,pv',=20'smpCoresPerSocket':=20'1',=20'kvmEnable':=20'true',=20= 'pitReinjection':=20'false',=20'displayNetwork':=20'ovirtmgmt',=20= 'devices':=20[{'device':=20'usb',=20'alias':=20'usb0',=20'type':=20= 'controller',=20'address':=20{'slot':=20'0x01',=20'bus':=20'0x00',=20= 'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20'0x2'}},=20= {'device':=20'ide',=20'alias':=20'ide0',=20'type':=20'controller',=20= 'address':=20{'slot':=20'0x01',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x1'}},=20{'device':=20= 'virtio-serial',=20'alias':=20'virtio-serial0',=20'type':=20= 'controller',=20'address':=20{'slot':=20'0x04',=20'bus':=20'0x00',=20= 'domain':=20'0x0000',=20'type':=20'pci',=20'function':=20'0x0'}},=20= {'specParams':=20{'vram':=20'65536'},=20'alias':=20'video0',=20= 'deviceId':=20'0f10b02a-f6bc-432d-bc49-478facf49730',=20'address':=20= {'slot':=20'0x02',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20= 'pci',=20'function':=20'0x0'},=20'device':=20'qxl',=20'type':=20= 'video'},=20{'nicModel':=20'pv',=20'macAddr':=20'00:1a:4a:c0:2a:05',=20= 'network':=20'ovirtmgmt',=20'alias':=20'net0',=20'specParams':=20{},=20= 'deviceId':=20'376d1987-d374-486d-8a62-d48ab0a47eb1',=20'address':=20= {'slot':=20'0x03',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20= 'pci',=20'function':=20'0x0'},=20'device':=20'bridge',=20'type':=20= 'interface',=20'name':=20'vnet2'},=20{'target':=201048576,=20= 'specParams':=20{'model':=20'virtio'},=20'alias':=20'balloon0',=20= 'deviceId':=20'72aaa60a-34e5-41e1-80ea-d9b1c3a1b4e2',=20'address':=20= {'slot':=20'0x06',=20'bus':=20'0x00',=20'domain':=20'0x0000',=20'type':=20= 'pci',=20'function':=20'0x0'},=20'device':=20'memballoon',=20'type':=20= 'balloon'},=20{'index':=20'2',=20'iface':=20'ide',=20'name':=20'hdc',=20= 'alias':=20'ide0-1-0',=20'shared':=20'false',=20'specParams':=20{'path':=20= 'cobbler-base.iso'},=20'readonly':=20'True',=20'deviceId':=20= '58cff440-2f4d-4bbe-94d9-d7c12df85c4d',=20'address':=20{'bus':=20'1',=20= 'controller':=20'0',=20'type':=20'drive',=20'target':=20'0',=20'unit':=20= '0'},=20'device':=20'cdrom',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/ab686999-f320-4a61= -ae07-e99c2f858996/images/11111111-1111-1111-1111-111111111111/cobbler-bas= e.iso',=20'type':=20'disk'},=20{'poolID':=20= 'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20'index':=200,=20'iface':=20= 'virtio',=20'apparentsize':=20'21474836480',=20'alias':=20= 'virtio-disk0',=20'imageID':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'readonly':=20'False',=20'shared':=20'false',=20'truesize':=20= '2936401920',=20'type':=20'disk',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'reqsize':=20'0',=20'format':=20= 'raw',=20'deviceId':=20'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= 'address':=20{'slot':=20'0x05',=20'bus':=20'0x00',=20'domain':=20= '0x0000',=20'type':=20'pci',=20'function':=20'0x0'},=20'device':=20= 'disk',=20'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'propagateErrors':=20'off',=20'optional':=20= 'false',=20'name':=20'vda',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'specParams':=20{},=20= 'volumeChain':=20[{'path':=20= '/rhev/data-center/bb0beebf-edab-41e2-83b8-16bdbbc5dda7/2a1939bd-9fa3-4896= -b8a9-46234172aae7/images/12a6472f-9ab9-436a-8508-b6721cb2b227/732e7b27-cd= bb-4dc7-ba7b-4285719615d4',=20'domainID':=20= '2a1939bd-9fa3-4896-b8a9-46234172aae7',=20'volumeID':=20= '732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'}]},=20{'device':=20'unix',=20= 'alias':=20'channel0',=20'type':=20'channel',=20'address':=20{'bus':=20= '0',=20'controller':=20'0',=20'type':=20'virtio-serial',=20'port':=20= '1'}},=20{'device':=20'unix',=20'alias':=20'channel1',=20'type':=20= 'channel',=20'address':=20{'bus':=20'0',=20'controller':=20'0',=20= 'type':=20'virtio-serial',=20'port':=20'2'}},=20{'device':=20'spicevmc',=20= 'alias':=20'channel2',=20'type':=20'channel',=20'address':=20{'bus':=20= '0',=20'controller':=20'0',=20'type':=20'virtio-serial',=20'port':=20= '3'}}],=20'clientIp':=20'',=20'display':=20'qxl'}}=0A= Thread-2456770::DEBUG::2013-01-08=20= 10:42:21,422::misc::83::Storage.Misc.excCmd::(<lambda>)=20SUCCESS:=20= <err>=20=3D=20'';=20<rc>=20=3D=200=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,423::vm::611::vm.Vm::(_startUnderlyingVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::_ongoingCreations=20= released=0AThread-2456770::DEBUG::2013-01-08=20= 10:42:21,423::libvirtvm::1669::vm.Vm::(_waitForIncomingMigrationFinish)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Waiting=20300=20seconds=20= for=20end=20of=20migration=0AThread-2456772::DEBUG::2013-01-08=20= 10:42:22,523::task::568::TaskManager.Task::(_updateState)=20= Task=3D`16f59db2-fcff-4f03-b964-1ed70965d150`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2456772::INFO::2013-01-08=20= 10:42:22,523::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-2456772::INFO::2013-01-08=20= 10:42:22,524::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00229406356812',=20'lastCheck':=20'8.0',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00214695930481',=20'lastCheck':=20'6.3',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00227403640747',=20'lastCheck':=20'6.4',=20'code':=200,=20'valid':=20= True}}=0AThread-2456772::DEBUG::2013-01-08=20= 10:42:22,524::task::1151::TaskManager.Task::(prepare)=20= Task=3D`16f59db2-fcff-4f03-b964-1ed70965d150`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00229406356812',=20'lastCheck':=20'8.0',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00214695930481',=20'lastCheck':=20'6.3',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00227403640747',=20'lastCheck':=20'6.4',=20'code':=200,=20'valid':=20= True}}=0AThread-2456772::DEBUG::2013-01-08=20= 10:42:22,524::task::568::TaskManager.Task::(_updateState)=20= Task=3D`16f59db2-fcff-4f03-b964-1ed70965d150`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2456772::DEBUG::2013-01-08=20= 10:42:22,524::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2456772::DEBUG::2013-01-08=20= 10:42:22,524::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2456772::DEBUG::2013-01-08=20= 10:42:22,524::task::957::TaskManager.Task::(_decref)=20= Task=3D`16f59db2-fcff-4f03-b964-1ed70965d150`::ref=200=20aborting=20= False=0AThread-2456773::DEBUG::2013-01-08=20= 10:42:22,537::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`a08884f6-d634-4d1d-a0ef-f77cd96f0953`::Disk=20vda=20latency=20= not=20available=0AThread-2456774::DEBUG::2013-01-08=20= 10:42:22,717::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.196]::call=20vmDestroy=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-2456774::INFO::2013-01-08=20= 10:42:22,717::API::308::vds::(destroy)=20vmContainerLock=20acquired=20by=20= vm=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,718::libvirtvm::2209::vm.Vm::(destroy)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::destroy=20Called=0A= Thread-2456774::INFO::2013-01-08=20= 10:42:22,718::libvirtvm::2160::vm.Vm::(releaseVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Release=20VM=20resources=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,718::misc::83::Storage.Misc.excCmd::(<lambda>)=20'/usr/bin/sudo=20= -n=20/sbin/service=20ksmtuned=20retune'=20(cwd=20None)=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,755::misc::83::Storage.Misc.excCmd::(<lambda>)=20SUCCESS:=20= <err>=20=3D=20'';=20<rc>=20=3D=200=0AThread-2456774::DEBUG::2013-01-08=20= 10:42:22,756::task::568::TaskManager.Task::(_updateState)=20= Task=3D`19304f16-6634-40f2-aeb5-081cb423eb7d`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-2456774::INFO::2013-01-08=20= 10:42:22,756::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= inappropriateDevices(thiefId=3D'cfb17b98-1476-4fbf-9fab-7c7f48b60adf')=0A= Thread-2456774::INFO::2013-01-08=20= 10:42:22,769::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= inappropriateDevices,=20Return=20response:=20None=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,770::task::1151::TaskManager.Task::(prepare)=20= Task=3D`19304f16-6634-40f2-aeb5-081cb423eb7d`::finished:=20None=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,770::task::568::TaskManager.Task::(_updateState)=20= Task=3D`19304f16-6634-40f2-aeb5-081cb423eb7d`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-2456774::DEBUG::2013-01-08=20= 10:42:22,770::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,770::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-2456774::DEBUG::2013-01-08=20= 10:42:22,770::task::957::TaskManager.Task::(_decref)=20= Task=3D`19304f16-6634-40f2-aeb5-081cb423eb7d`::ref=200=20aborting=20= False=0AThread-2456774::DEBUG::2013-01-08=20= 10:42:22,771::libvirtvm::2203::vm.Vm::(deleteVm)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Total=20desktops=20after=20= destroy=20of=20cfb17b98-1476-4fbf-9fab-7c7f48b60adf=20is=201=0A= Thread-2456774::DEBUG::2013-01-08=20= 10:42:22,771::BindingXMLRPC::890::vds::(wrapper)=20return=20vmDestroy=20= with=20{'status':=20{'message':=20'Machine=20destroyed',=20'code':=200}}=0A= --Apple-Mail=_C82D1F4B-8BD2-4AB4-8D7E-7DAE9D5676F1 Content-Disposition: attachment; filename=migrate-src.log Content-Type: application/octet-stream; name="migrate-src.log" Content-Transfer-Encoding: quoted-printable Thread-1484330::DEBUG::2013-01-08=20= 10:40:59,186::task::568::TaskManager.Task::(_updateState)=20= Task=3D`7417efd1-9122-4c1c-8f64-b2df0bcbc07d`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-1484330::INFO::2013-01-08=20= 10:40:59,186::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-1484330::INFO::2013-01-08=20= 10:40:59,186::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00235295295715',=20'lastCheck':=20'1.9',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00221991539001',=20'lastCheck':=20'0.8',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00199294090271',=20'lastCheck':=20'0.8',=20'code':=200,=20'valid':=20= True}}=0AThread-1484330::DEBUG::2013-01-08=20= 10:40:59,186::task::1151::TaskManager.Task::(prepare)=20= Task=3D`7417efd1-9122-4c1c-8f64-b2df0bcbc07d`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00235295295715',=20'lastCheck':=20'1.9',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00221991539001',=20'lastCheck':=20'0.8',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00199294090271',=20'lastCheck':=20'0.8',=20'code':=200,=20'valid':=20= True}}=0AThread-1484330::DEBUG::2013-01-08=20= 10:40:59,186::task::568::TaskManager.Task::(_updateState)=20= Task=3D`7417efd1-9122-4c1c-8f64-b2df0bcbc07d`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-1484330::DEBUG::2013-01-08=20= 10:40:59,186::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-1484330::DEBUG::2013-01-08=20= 10:40:59,187::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-1484330::DEBUG::2013-01-08=20= 10:40:59,187::task::957::TaskManager.Task::(_decref)=20= Task=3D`7417efd1-9122-4c1c-8f64-b2df0bcbc07d`::ref=200=20aborting=20= False=0AThread-1484331::DEBUG::2013-01-08=20= 10:40:59,402::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk=20vda=20latency=20= not=20available=0AThread-1484331::DEBUG::2013-01-08=20= 10:40:59,402::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`7b8f725b-0a67-46d4-a3cf-db43daad0c42`::Disk=20vda=20latency=20= not=20available=0AThread-1484331::DEBUG::2013-01-08=20= 10:40:59,402::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Disk=20vda=20latency=20= not=20available=0AThread-1484331::DEBUG::2013-01-08=20= 10:40:59,403::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`e8683e88-f3f2-4fe9-80f7-f4888d8e7a13`::Disk=20vda=20latency=20= not=20available=0AThread-417786::DEBUG::2013-01-08=20= 10:41:00,312::task::568::TaskManager.Task::(_updateState)=20= Task=3D`966b7fee-f32b-4c1e-914f-b40a8a7ff75b`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-417786::INFO::2013-01-08=20= 10:41:00,312::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'12a6472f-9ab9-436a-8508-b6721cb2b227',=20= volUUID=3D'732e7b27-cdbb-4dc7-ba7b-4285719615d4',=20options=3DNone)=0A= Thread-417786::DEBUG::2013-01-08=20= 10:41:00,314::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-417786::DEBUG::2013-01-08=20= 10:41:00,317::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=20732e7b27-cdbb-4dc7-ba7b-4285719615d4=0A= Thread-417786::INFO::2013-01-08=20= 10:41:00,319::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize,=20Return=20response:=20{'truesize':=20'2936401920',=20= 'apparentsize':=20'21474836480'}=0AThread-417786::DEBUG::2013-01-08=20= 10:41:00,319::task::1151::TaskManager.Task::(prepare)=20= Task=3D`966b7fee-f32b-4c1e-914f-b40a8a7ff75b`::finished:=20{'truesize':=20= '2936401920',=20'apparentsize':=20'21474836480'}=0A= Thread-417786::DEBUG::2013-01-08=20= 10:41:00,319::task::568::TaskManager.Task::(_updateState)=20= Task=3D`966b7fee-f32b-4c1e-914f-b40a8a7ff75b`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-417786::DEBUG::2013-01-08=20= 10:41:00,319::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-417786::DEBUG::2013-01-08=20= 10:41:00,319::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-417786::DEBUG::2013-01-08=20= 10:41:00,320::task::957::TaskManager.Task::(_decref)=20= Task=3D`966b7fee-f32b-4c1e-914f-b40a8a7ff75b`::ref=200=20aborting=20= False=0AThread-1284213::DEBUG::2013-01-08=20= 10:41:00,325::task::568::TaskManager.Task::(_updateState)=20= Task=3D`f9a27440-7e81-4f9a-918b-59db7a0173e9`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-1284213::INFO::2013-01-08=20= 10:41:00,326::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize(sdUUID=3D'2a1939bd-9fa3-4896-b8a9-46234172aae7',=20= spUUID=3D'bb0beebf-edab-41e2-83b8-16bdbbc5dda7',=20= imgUUID=3D'8f2e2e18-0f8b-4e35-bdaf-8c853d8fb090',=20= volUUID=3D'7a569331-46e2-4e53-b8a9-9ef51290125e',=20options=3DNone)=0A= Thread-1284213::DEBUG::2013-01-08=20= 10:41:00,328::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=207a569331-46e2-4e53-b8a9-9ef51290125e=0A= Thread-1284213::DEBUG::2013-01-08=20= 10:41:00,331::fileVolume::558::Storage.Volume::(validateVolumePath)=20= validate=20path=20for=207a569331-46e2-4e53-b8a9-9ef51290125e=0A= Thread-1284213::INFO::2013-01-08=20= 10:41:00,332::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= getVolumeSize,=20Return=20response:=20{'truesize':=20'10737422336',=20= 'apparentsize':=20'10737418240'}=0AThread-1284213::DEBUG::2013-01-08=20= 10:41:00,332::task::1151::TaskManager.Task::(prepare)=20= Task=3D`f9a27440-7e81-4f9a-918b-59db7a0173e9`::finished:=20{'truesize':=20= '10737422336',=20'apparentsize':=20'10737418240'}=0A= Thread-1284213::DEBUG::2013-01-08=20= 10:41:00,332::task::568::TaskManager.Task::(_updateState)=20= Task=3D`f9a27440-7e81-4f9a-918b-59db7a0173e9`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-1284213::DEBUG::2013-01-08=20= 10:41:00,332::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-1284213::DEBUG::2013-01-08=20= 10:41:00,332::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-1284213::DEBUG::2013-01-08=20= 10:41:00,333::task::957::TaskManager.Task::(_decref)=20= Task=3D`f9a27440-7e81-4f9a-918b-59db7a0173e9`::ref=200=20aborting=20= False=0A=0A=0A=0A=0A=0A=0A=0A=0A=0A=0A=0A=0A= Thread-1484336::DEBUG::2013-01-08=20= 10:41:07,659::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.207]::call=20vmMigrate=20with=20({'src':=20'10.192.42.196',=20= 'dst':=20'10.192.42.165:54321',=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'method':=20'online'},)=20{}=20= flowID=20[13b25d64]=0AThread-1484336::DEBUG::2013-01-08=20= 10:41:07,659::API::432::vds::(migrate)=20{'src':=20'10.192.42.196',=20= 'dst':=20'10.192.42.165:54321',=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'method':=20'online'}=0A= Thread-1484337::DEBUG::2013-01-08=20= 10:41:07,660::vm::125::vm.Vm::(_setupVdsConnection)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Destination=20server=20= is:=2010.192.42.165:54321=0AThread-1484336::DEBUG::2013-01-08=20= 10:41:07,660::BindingXMLRPC::890::vds::(wrapper)=20return=20vmMigrate=20= with=20{'status':=20{'message':=20'Migration=20process=20starting',=20= 'code':=200}}=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:07,660::vm::127::vm.Vm::(_setupVdsConnection)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Initiating=20connection=20= with=20destination=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:07,752::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk=20vda=20latency=20= not=20available=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:07,835::vm::173::vm.Vm::(_prepareGuest)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20Process=20= begins=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:07,927::vm::237::vm.Vm::(run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20semaphore=20= acquired=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:08,251::libvirtvm::449::vm.Vm::(_startUnderlyingMigration)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting=20migration=20to=20= qemu+tls://10.192.42.165/system=0AThread-1484338::DEBUG::2013-01-08=20= 10:41:08,251::libvirtvm::335::vm.Vm::(run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20downtime=20= thread=20started=0AThread-1484339::DEBUG::2013-01-08=20= 10:41:08,252::libvirtvm::371::vm.Vm::(run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting=20migration=20= monitor=20thread=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:09,521::libvirtvm::350::vm.Vm::(cancel)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::canceling=20migration=20= downtime=20thread=0AThread-1484337::DEBUG::2013-01-08=20= 10:41:09,521::libvirtvm::409::vm.Vm::(stop)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::stopping=20migration=20= monitor=20thread=0AThread-1484338::DEBUG::2013-01-08=20= 10:41:09,522::libvirtvm::347::vm.Vm::(run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration=20downtime=20= thread=20exiting=0AThread-1484337::ERROR::2013-01-08=20= 10:41:09,522::vm::179::vm.Vm::(_recover)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::internal=20error=20= Process=20exited=20while=20reading=20console=20log=20output:=20=0A= Thread-1484340::DEBUG::2013-01-08=20= 10:41:09,544::task::568::TaskManager.Task::(_updateState)=20= Task=3D`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving=20from=20state=20= init=20->=20state=20preparing=0AThread-1484340::INFO::2013-01-08=20= 10:41:09,544::logUtils::37::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats(options=3DNone)=0AThread-1484340::INFO::2013-01-08=20= 10:41:09,544::logUtils::39::dispatcher::(wrapper)=20Run=20and=20protect:=20= repoStats,=20Return=20response:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00229001045227',=20'lastCheck':=20'2.2',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00204110145569',=20'lastCheck':=20'1.1',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00174999237061',=20'lastCheck':=20'1.1',=20'code':=200,=20'valid':=20= True}}=0AThread-1484340::DEBUG::2013-01-08=20= 10:41:09,544::task::1151::TaskManager.Task::(prepare)=20= Task=3D`bfebf940-d2a3-4b6c-948b-cac951a686bf`::finished:=20= {'2a1939bd-9fa3-4896-b8a9-46234172aae7':=20{'delay':=20= '0.00229001045227',=20'lastCheck':=20'2.2',=20'code':=200,=20'valid':=20= True},=20'ab686999-f320-4a61-ae07-e99c2f858996':=20{'delay':=20= '0.00204110145569',=20'lastCheck':=20'1.1',=20'code':=200,=20'valid':=20= True},=20'9cff8858-9188-42eb-b089-22f89719394d':=20{'delay':=20= '0.00174999237061',=20'lastCheck':=20'1.1',=20'code':=200,=20'valid':=20= True}}=0AThread-1484340::DEBUG::2013-01-08=20= 10:41:09,544::task::568::TaskManager.Task::(_updateState)=20= Task=3D`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving=20from=20state=20= preparing=20->=20state=20finished=0AThread-1484340::DEBUG::2013-01-08=20= 10:41:09,545::resourceManager::809::ResourceManager.Owner::(releaseAll)=20= Owner.releaseAll=20requests=20{}=20resources=20{}=0A= Thread-1484340::DEBUG::2013-01-08=20= 10:41:09,545::resourceManager::844::ResourceManager.Owner::(cancelAll)=20= Owner.cancelAll=20requests=20{}=0AThread-1484340::DEBUG::2013-01-08=20= 10:41:09,545::task::957::TaskManager.Task::(_decref)=20= Task=3D`bfebf940-d2a3-4b6c-948b-cac951a686bf`::ref=200=20aborting=20= False=0AThread-1484341::DEBUG::2013-01-08=20= 10:41:09,558::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk=20vda=20latency=20= not=20available=0AThread-1484341::DEBUG::2013-01-08=20= 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`7b8f725b-0a67-46d4-a3cf-db43daad0c42`::Disk=20vda=20latency=20= not=20available=0AThread-1484341::DEBUG::2013-01-08=20= 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Disk=20vda=20latency=20= not=20available=0AThread-1484341::DEBUG::2013-01-08=20= 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`e8683e88-f3f2-4fe9-80f7-f4888d8e7a13`::Disk=20vda=20latency=20= not=20available=0AThread-1484337::ERROR::2013-01-08=20= 10:41:09,754::vm::258::vm.Vm::(run)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Failed=20to=20migrate=0A= Traceback=20(most=20recent=20call=20last):=0A=20=20File=20= "/usr/share/vdsm/vm.py",=20line=20245,=20in=20run=0A=20=20=20=20= self._startUnderlyingMigration()=0A=20=20File=20= "/usr/share/vdsm/libvirtvm.py",=20line=20474,=20in=20= _startUnderlyingMigration=0A=20=20=20=20None,=20maxBandwidth)=0A=20=20= File=20"/usr/share/vdsm/libvirtvm.py",=20line=20510,=20in=20f=0A=20=20=20= =20ret=20=3D=20attr(*args,=20**kwargs)=0A=20=20File=20= "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py",=20line=20= 83,=20in=20wrapper=0A=20=20=20=20ret=20=3D=20f(*args,=20**kwargs)=0A=20=20= File=20"/usr/lib64/python2.6/site-packages/libvirt.py",=20line=201103,=20= in=20migrateToURI2=0A=20=20=20=20if=20ret=20=3D=3D=20-1:=20raise=20= libvirtError=20('virDomainMigrateToURI2()=20failed',=20dom=3Dself)=0A= libvirtError:=20internal=20error=20Process=20exited=20while=20reading=20= console=20log=20output:=20=0AThread-1484343::DEBUG::2013-01-08=20= 10:41:11,654::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.207]::call=20vmGetStats=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-1484343::DEBUG::2013-01-08=20= 10:41:11,654::libvirtvm::278::vm.Vm::(_getDiskLatency)=20= vmId=3D`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk=20vda=20latency=20= not=20available=0AThread-1484343::DEBUG::2013-01-08=20= 10:41:11,655::BindingXMLRPC::890::vds::(wrapper)=20return=20vmGetStats=20= with=20{'status':=20{'message':=20'Done',=20'code':=200},=20'statsList':=20= [{'status':=20'Up',=20'username':=20'Unknown',=20'memUsage':=20'0',=20= 'acpiEnable':=20'true',=20'pid':=20'5780',=20'displayIp':=20= '10.192.42.196',=20'displayPort':=20u'5904',=20'session':=20'Unknown',=20= 'displaySecurePort':=20u'5905',=20'timeOffset':=20-2L,=20'hash':=20= '-7242028114076316120',=20'balloonInfo':=20{'balloon_max':=201048576,=20= 'balloon_cur':=201048576},=20'pauseCode':=20'NOERR',=20'clientIp':=20'',=20= 'kvmEnable':=20'true',=20'network':=20{u'vnet2':=20{'macAddr':=20= '00:1a:4a:c0:2a:05',=20'rxDropped':=20'0',=20'rxErrors':=20'0',=20= 'txDropped':=20'0',=20'txRate':=20'0.0',=20'rxRate':=20'0.0',=20= 'txErrors':=20'0',=20'state':=20'unknown',=20'speed':=20'1000',=20= 'name':=20u'vnet2'}},=20'vmId':=20= 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf',=20'displayType':=20'qxl',=20= 'cpuUser':=20'0.49',=20'disks':=20{u'vda':=20{'readRate':=20'0.00',=20= 'truesize':=20'2936401920',=20'apparentsize':=20'21474836480',=20= 'writeRate':=20'1273.87',=20'imageID':=20= '12a6472f-9ab9-436a-8508-b6721cb2b227'},=20u'hdc':=20{'readLatency':=20= '0',=20'apparentsize':=20'0',=20'writeLatency':=20'0',=20'flushLatency':=20= '0',=20'readRate':=20'0.00',=20'truesize':=20'0',=20'writeRate':=20= '0.00'}},=20'monitorResponse':=20'0',=20'statsAge':=20'0.36',=20= 'elapsedTime':=20'1707880',=20'vmType':=20'kvm',=20'cpuSys':=20'0.40',=20= 'appsList':=20[],=20'guestIPs':=20''}]}=0A= Thread-1484344::DEBUG::2013-01-08=20= 10:41:11,679::BindingXMLRPC::883::vds::(wrapper)=20client=20= [10.192.42.207]::call=20vmGetMigrationStatus=20with=20= ('cfb17b98-1476-4fbf-9fab-7c7f48b60adf',)=20{}=0A= Thread-1484344::DEBUG::2013-01-08=20= 10:41:11,679::BindingXMLRPC::890::vds::(wrapper)=20return=20= vmGetMigrationStatus=20with=20{'status':=20{'message':=20'Fatal=20error=20= during=20migration',=20'code':=2012}}=0AVM=20Channels=20= Listener::DEBUG::2013-01-08=20= 10:41:12,057::vmChannels::60::vds::(_handle_timeouts)=20Timeout=20on=20= fileno=2018.=0A= --Apple-Mail=_C82D1F4B-8BD2-4AB4-8D7E-7DAE9D5676F1 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=iso-8859-1 log from both sides. see attached --Apple-Mail=_C82D1F4B-8BD2-4AB4-8D7E-7DAE9D5676F1--
odd, migration seem to be successful on destination server, but source reports a problem: Thread-1484336::DEBUG::2013-01-08 10:41:07,659::BindingXMLRPC::883::vds::(wrapper) client [10.192.42.207]::call vmMigrate with ({'src': '10.192.42.196', 'dst': '10.192.42.165:54321', 'vmId': 'cfb17b98-1476-4fbf-9f Thread-1484336::DEBUG::2013-01-08 10:41:07,659::API::432::vds::(migrate) {'src': '10.192.42.196', 'dst': '10.192.42.165:54321', 'vmId': 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf', 'method': 'online'} Thread-1484337::DEBUG::2013-01-08 10:41:07,660::vm::125::vm.Vm::(_setupVdsConnection) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Destination server is: 10.192.42.165:54321 Thread-1484336::DEBUG::2013-01-08 10:41:07,660::BindingXMLRPC::890::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}} Thread-1484337::DEBUG::2013-01-08 10:41:07,660::vm::127::vm.Vm::(_setupVdsConnection) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Initiating connection with destination Thread-1484337::DEBUG::2013-01-08 10:41:07,752::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk vda latency not available Thread-1484337::DEBUG::2013-01-08 10:41:07,835::vm::173::vm.Vm::(_prepareGuest) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration Process begins Thread-1484337::DEBUG::2013-01-08 10:41:07,927::vm::237::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration semaphore acquired Thread-1484337::DEBUG::2013-01-08 10:41:08,251::libvirtvm::449::vm.Vm::(_startUnderlyingMigration) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting migration to qemu+tls://10.192.42.165/system Thread-1484338::DEBUG::2013-01-08 10:41:08,251::libvirtvm::335::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration downtime thread started Thread-1484339::DEBUG::2013-01-08 10:41:08,252::libvirtvm::371::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting migration monitor thread Thread-1484337::DEBUG::2013-01-08 10:41:09,521::libvirtvm::350::vm.Vm::(cancel) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::canceling migration downtime thread Thread-1484337::DEBUG::2013-01-08 10:41:09,521::libvirtvm::409::vm.Vm::(stop) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::stopping migration monitor thread Thread-1484338::DEBUG::2013-01-08 10:41:09,522::libvirtvm::347::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration downtime thread exiting Thread-1484337::ERROR::2013-01-08 10:41:09,522::vm::179::vm.Vm::(_recover) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::internal error Process exited while reading console log output: Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::568::TaskManager.Task::(_updateState) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving from state init -> state preparing Thread-1484340::INFO::2013-01-08 10:41:09,544::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-1484340::INFO::2013-01-08 10:41:09,544::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2a1939bd-9fa3-4896-b8a9-46234172aae7': {'delay': '0.00229001045227', 'lastCheck': ' Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::1151::TaskManager.Task::(prepare) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::finished: {'2a1939bd-9fa3-4896-b8a9-46234172aae7': {'delay': '0.00229001045227', Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::568::TaskManager.Task::(_updateState) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving from state preparing -> state finished Thread-1484340::DEBUG::2013-01-08 10:41:09,545::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1484340::DEBUG::2013-01-08 10:41:09,545::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1484340::DEBUG::2013-01-08 10:41:09,545::task::957::TaskManager.Task::(_decref) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::ref 0 aborting False Thread-1484341::DEBUG::2013-01-08 10:41:09,558::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`7b8f725b-0a67-46d4-a3cf-db43daad0c42`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`e8683e88-f3f2-4fe9-80f7-f4888d8e7a13`::Disk vda latency not available Thread-1484337::ERROR::2013-01-08 10:41:09,754::vm::258::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Failed to migrate Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 245, in run self._startUnderlyingMigration() File "/usr/share/vdsm/libvirtvm.py", line 474, in _startUnderlyingMigration None, maxBandwidth) File "/usr/share/vdsm/libvirtvm.py", line 510, in f ret = attr(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 83, in wrapper ret = f(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1103, in migrateToURI2 if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self) libvirtError: internal error Process exited while reading console log output: any chance you attach libvirtd.log and qemu log (/var/log/libvirt/qemu/{}.log? Danken - any insights? ----- Original Message -----
From: "Tom Brown" <tom@ng23.net> To: "Roy Golan" <rgolan@redhat.com> Cc: "Haim Ateya" <hateya@redhat.com>, users@ovirt.org Sent: Tuesday, January 8, 2013 11:50:26 AM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
can you attach the same snip from the src VDSM 10.192.42.196 as well?
The log is pretty chatty therefore i did another migration attempt and snipd'd the new log from both sides.
see attached
libvirtError: internal error Process exited while reading console log outpu could this be related to selinux? can you try disabling it and see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool. Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to. thanks
On Wed, Jan 09, 2013 at 10:06:12AM +0000, Tom Brown wrote:
libvirtError: internal error Process exited while reading console log outpu could this be related to selinux? can you try disabling it and see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool.
Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to.
I have (only a vague) memory of discussing this already... Shouldn't oVirt-Engine be aware of selinux enforcement? If a cluster has disabled hosts, an enforcing host should not be operational (or at least warn the admin about that).
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Tom Brown" <tom@ng23.net> Cc: "Simon Grinberg" <sgrinber@redhat.com>, users@ovirt.org Sent: Wednesday, January 9, 2013 2:11:14 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 10:06:12AM +0000, Tom Brown wrote:
libvirtError: internal error Process exited while reading console log outpu could this be related to selinux? can you try disabling it and see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool.
Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to.
I have (only a vague) memory of discussing this already... Shouldn't oVirt-Engine be aware of selinux enforcement? If a cluster has disabled hosts, an enforcing host should not be operational (or at least warn the admin about that).
I recall something like that, but I don't recall we ever converged and can't find the thread
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
On Wed, Jan 09, 2013 at 09:05:37AM -0500, Simon Grinberg wrote:
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Tom Brown" <tom@ng23.net> Cc: "Simon Grinberg" <sgrinber@redhat.com>, users@ovirt.org Sent: Wednesday, January 9, 2013 2:11:14 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 10:06:12AM +0000, Tom Brown wrote:
libvirtError: internal error Process exited while reading console log outpu could this be related to selinux? can you try disabling it and see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool.
Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to.
I have (only a vague) memory of discussing this already... Shouldn't oVirt-Engine be aware of selinux enforcement? If a cluster has disabled hosts, an enforcing host should not be operational (or at least warn the admin about that).
I recall something like that, but I don't recall we ever converged and can't find the thread
What is your opinion on the subject? I think that at the least, the scheduler must be aware of selinux enforcement when it chooses migration destination.
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Simon Grinberg" <simon@redhat.com> Cc: users@ovirt.org, "Tom Brown" <tom@ng23.net> Sent: Wednesday, January 9, 2013 6:20:02 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 09:05:37AM -0500, Simon Grinberg wrote:
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Tom Brown" <tom@ng23.net> Cc: "Simon Grinberg" <sgrinber@redhat.com>, users@ovirt.org Sent: Wednesday, January 9, 2013 2:11:14 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 10:06:12AM +0000, Tom Brown wrote:
libvirtError: internal error Process exited while reading console log outpu could this be related to selinux? can you try disabling it and see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool.
Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to.
I have (only a vague) memory of discussing this already... Shouldn't oVirt-Engine be aware of selinux enforcement? If a cluster has disabled hosts, an enforcing host should not be operational (or at least warn the admin about that).
I recall something like that, but I don't recall we ever converged and can't find the thread
What is your opinion on the subject?
I think that at the least, the scheduler must be aware of selinux enforcement when it chooses migration destination.
Either all or non in the same cluster - that is the default. On a mixed environment, the non enforced hosts should be move to non-operational, but VM should not be migrated off due to this, we don't want them moved to protected hosts without the admin awareness. As exception to the above, have a config parameter that allows in a mixed environment to migrate VMs from an insecure onto a secure host never the other way around. This is to support transition from non-enabled system to enabled. I think this is the closest I can get to the agreement (or at least concerns) raised in that old thread I can't find.
On Wed, Jan 09, 2013 at 11:34:56AM -0500, Simon Grinberg wrote:
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Simon Grinberg" <simon@redhat.com> Cc: users@ovirt.org, "Tom Brown" <tom@ng23.net> Sent: Wednesday, January 9, 2013 6:20:02 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 09:05:37AM -0500, Simon Grinberg wrote:
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Tom Brown" <tom@ng23.net> Cc: "Simon Grinberg" <sgrinber@redhat.com>, users@ovirt.org Sent: Wednesday, January 9, 2013 2:11:14 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 10:06:12AM +0000, Tom Brown wrote:
> libvirtError: internal error Process exited while reading > console log outpu could this be related to selinux? can you try disabling it and see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool.
Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to.
I have (only a vague) memory of discussing this already... Shouldn't oVirt-Engine be aware of selinux enforcement? If a cluster has disabled hosts, an enforcing host should not be operational (or at least warn the admin about that).
I recall something like that, but I don't recall we ever converged and can't find the thread
What is your opinion on the subject?
I think that at the least, the scheduler must be aware of selinux enforcement when it chooses migration destination.
Either all or non in the same cluster - that is the default.
On a mixed environment, the non enforced hosts should be move to non-operational, but VM should not be migrated off due to this, we don't want them moved to protected hosts without the admin awareness.
As exception to the above, have a config parameter that allows in a mixed environment to migrate VMs from an insecure onto a secure host never the other way around. This is to support transition from non-enabled system to enabled.
Please see Tom's report above:
It was indeed the case! my src node was set to disabled and my destination node was enforcing ...
We apparently cannot migrate an insecure guest into an enforcing system.
I think this is the closest I can get to the agreement (or at least concerns) raised in that old thread I can't find.
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Simon Grinberg" <simon@redhat.com> Cc: users@ovirt.org, "Tom Brown" <tom@ng23.net> Sent: Thursday, January 10, 2013 2:09:28 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 11:34:56AM -0500, Simon Grinberg wrote:
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Simon Grinberg" <simon@redhat.com> Cc: users@ovirt.org, "Tom Brown" <tom@ng23.net> Sent: Wednesday, January 9, 2013 6:20:02 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 09:05:37AM -0500, Simon Grinberg wrote:
----- Original Message -----
From: "Dan Kenigsberg" <danken@redhat.com> To: "Tom Brown" <tom@ng23.net> Cc: "Simon Grinberg" <sgrinber@redhat.com>, users@ovirt.org Sent: Wednesday, January 9, 2013 2:11:14 PM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
On Wed, Jan 09, 2013 at 10:06:12AM +0000, Tom Brown wrote:
>> libvirtError: internal error Process exited while >> reading >> console log outpu > could this be related to selinux? can you try disabling > it > and > see if migration succeeds?
It was indeed the case! my src node was set to disabled and my destination node was enforcing, this was due to the destination being the first HV built and therefore provisioned slightly differently, my kickstart server is a VM in the pool.
Its interesting that a VM can be provisioned onto a node that is set to enforcing and yet not migrated to.
I have (only a vague) memory of discussing this already... Shouldn't oVirt-Engine be aware of selinux enforcement? If a cluster has disabled hosts, an enforcing host should not be operational (or at least warn the admin about that).
I recall something like that, but I don't recall we ever converged and can't find the thread
What is your opinion on the subject?
I think that at the least, the scheduler must be aware of selinux enforcement when it chooses migration destination.
Either all or non in the same cluster - that is the default.
On a mixed environment, the non enforced hosts should be move to non-operational, but VM should not be migrated off due to this, we don't want them moved to protected hosts without the admin awareness.
As exception to the above, have a config parameter that allows in a mixed environment to migrate VMs from an insecure onto a secure host never the other way around. This is to support transition from non-enabled system to enabled.
Please see Tom's report above:
It was indeed the case! my src node was set to disabled and my destination node was enforcing ...
We apparently cannot migrate an insecure guest into an enforcing system.
Well you've asked for my opinion not current implementation :) I'm not sure anything was implemented on the selinux requirements, need to check this, the error I see in this thread is run time failure due to improper setting, which is to be expected on migration from non labelled zone into a labelled zone.
I think this is the closest I can get to the agreement (or at least concerns) raised in that old thread I can't find.
Source or destination? On 9 Jan 2013, at 07:35, Haim Ateya <hateya@redhat.com> wrote:
odd,
migration seem to be successful on destination server, but source reports a problem:
Thread-1484336::DEBUG::2013-01-08 10:41:07,659::BindingXMLRPC::883::vds::(wrapper) client [10.192.42.207]::call vmMigrate with ({'src': '10.192.42.196', 'dst': '10.192.42.165:54321', 'vmId': 'cfb17b98-1476-4fbf-9f Thread-1484336::DEBUG::2013-01-08 10:41:07,659::API::432::vds::(migrate) {'src': '10.192.42.196', 'dst': '10.192.42.165:54321', 'vmId': 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf', 'method': 'online'} Thread-1484337::DEBUG::2013-01-08 10:41:07,660::vm::125::vm.Vm::(_setupVdsConnection) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Destination server is: 10.192.42.165:54321 Thread-1484336::DEBUG::2013-01-08 10:41:07,660::BindingXMLRPC::890::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}} Thread-1484337::DEBUG::2013-01-08 10:41:07,660::vm::127::vm.Vm::(_setupVdsConnection) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Initiating connection with destination Thread-1484337::DEBUG::2013-01-08 10:41:07,752::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk vda latency not available Thread-1484337::DEBUG::2013-01-08 10:41:07,835::vm::173::vm.Vm::(_prepareGuest) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration Process begins Thread-1484337::DEBUG::2013-01-08 10:41:07,927::vm::237::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration semaphore acquired Thread-1484337::DEBUG::2013-01-08 10:41:08,251::libvirtvm::449::vm.Vm::(_startUnderlyingMigration) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting migration to qemu+tls://10.192.42.165/system Thread-1484338::DEBUG::2013-01-08 10:41:08,251::libvirtvm::335::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration downtime thread started Thread-1484339::DEBUG::2013-01-08 10:41:08,252::libvirtvm::371::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting migration monitor thread Thread-1484337::DEBUG::2013-01-08 10:41:09,521::libvirtvm::350::vm.Vm::(cancel) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::canceling migration downtime thread Thread-1484337::DEBUG::2013-01-08 10:41:09,521::libvirtvm::409::vm.Vm::(stop) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::stopping migration monitor thread Thread-1484338::DEBUG::2013-01-08 10:41:09,522::libvirtvm::347::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration downtime thread exiting Thread-1484337::ERROR::2013-01-08 10:41:09,522::vm::179::vm.Vm::(_recover) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::internal error Process exited while reading console log output: Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::568::TaskManager.Task::(_updateState) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving from state init -> state preparing Thread-1484340::INFO::2013-01-08 10:41:09,544::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-1484340::INFO::2013-01-08 10:41:09,544::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2a1939bd-9fa3-4896-b8a9-46234172aae7': {'delay': '0.00229001045227', 'lastCheck': ' Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::1151::TaskManager.Task::(prepare) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::finished: {'2a1939bd-9fa3-4896-b8a9-46234172aae7': {'delay': '0.00229001045227', Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::568::TaskManager.Task::(_updateState) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving from state preparing -> state finished Thread-1484340::DEBUG::2013-01-08 10:41:09,545::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1484340::DEBUG::2013-01-08 10:41:09,545::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1484340::DEBUG::2013-01-08 10:41:09,545::task::957::TaskManager.Task::(_decref) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::ref 0 aborting False Thread-1484341::DEBUG::2013-01-08 10:41:09,558::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`7b8f725b-0a67-46d4-a3cf-db43daad0c42`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`e8683e88-f3f2-4fe9-80f7-f4888d8e7a13`::Disk vda latency not available Thread-1484337::ERROR::2013-01-08 10:41:09,754::vm::258::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Failed to migrate Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 245, in run self._startUnderlyingMigration() File "/usr/share/vdsm/libvirtvm.py", line 474, in _startUnderlyingMigration None, maxBandwidth) File "/usr/share/vdsm/libvirtvm.py", line 510, in f ret = attr(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 83, in wrapper ret = f(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1103, in migrateToURI2 if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self) libvirtError: internal error Process exited while reading console log output:
any chance you attach libvirtd.log and qemu log (/var/log/libvirt/qemu/{}.log?
Danken - any insights?
----- Original Message -----
From: "Tom Brown" <tom@ng23.net> To: "Roy Golan" <rgolan@redhat.com> Cc: "Haim Ateya" <hateya@redhat.com>, users@ovirt.org Sent: Tuesday, January 8, 2013 11:50:26 AM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
can you attach the same snip from the src VDSM 10.192.42.196 as well?
The log is pretty chatty therefore i did another migration attempt and snipd'd the new log from both sides.
see attached
both. ----- Original Message -----
From: "Tom Brown" <tom@ng23.net> To: "Haim Ateya" <hateya@redhat.com> Cc: "Dan Kenigsberg" <danken@redhat.com>, users@ovirt.org, "Roy Golan" <rgolan@redhat.com> Sent: Wednesday, January 9, 2013 10:03:11 AM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
Source or destination?
On 9 Jan 2013, at 07:35, Haim Ateya <hateya@redhat.com> wrote:
odd,
migration seem to be successful on destination server, but source reports a problem:
Thread-1484336::DEBUG::2013-01-08 10:41:07,659::BindingXMLRPC::883::vds::(wrapper) client [10.192.42.207]::call vmMigrate with ({'src': '10.192.42.196', 'dst': '10.192.42.165:54321', 'vmId': 'cfb17b98-1476-4fbf-9f Thread-1484336::DEBUG::2013-01-08 10:41:07,659::API::432::vds::(migrate) {'src': '10.192.42.196', 'dst': '10.192.42.165:54321', 'vmId': 'cfb17b98-1476-4fbf-9fab-7c7f48b60adf', 'method': 'online'} Thread-1484337::DEBUG::2013-01-08 10:41:07,660::vm::125::vm.Vm::(_setupVdsConnection) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Destination server is: 10.192.42.165:54321 Thread-1484336::DEBUG::2013-01-08 10:41:07,660::BindingXMLRPC::890::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}} Thread-1484337::DEBUG::2013-01-08 10:41:07,660::vm::127::vm.Vm::(_setupVdsConnection) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Initiating connection with destination Thread-1484337::DEBUG::2013-01-08 10:41:07,752::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk vda latency not available Thread-1484337::DEBUG::2013-01-08 10:41:07,835::vm::173::vm.Vm::(_prepareGuest) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration Process begins Thread-1484337::DEBUG::2013-01-08 10:41:07,927::vm::237::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration semaphore acquired Thread-1484337::DEBUG::2013-01-08 10:41:08,251::libvirtvm::449::vm.Vm::(_startUnderlyingMigration) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting migration to qemu+tls://10.192.42.165/system Thread-1484338::DEBUG::2013-01-08 10:41:08,251::libvirtvm::335::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration downtime thread started Thread-1484339::DEBUG::2013-01-08 10:41:08,252::libvirtvm::371::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::starting migration monitor thread Thread-1484337::DEBUG::2013-01-08 10:41:09,521::libvirtvm::350::vm.Vm::(cancel) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::canceling migration downtime thread Thread-1484337::DEBUG::2013-01-08 10:41:09,521::libvirtvm::409::vm.Vm::(stop) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::stopping migration monitor thread Thread-1484338::DEBUG::2013-01-08 10:41:09,522::libvirtvm::347::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::migration downtime thread exiting Thread-1484337::ERROR::2013-01-08 10:41:09,522::vm::179::vm.Vm::(_recover) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::internal error Process exited while reading console log output: Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::568::TaskManager.Task::(_updateState) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving from state init -> state preparing Thread-1484340::INFO::2013-01-08 10:41:09,544::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-1484340::INFO::2013-01-08 10:41:09,544::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2a1939bd-9fa3-4896-b8a9-46234172aae7': {'delay': '0.00229001045227', 'lastCheck': ' Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::1151::TaskManager.Task::(prepare) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::finished: {'2a1939bd-9fa3-4896-b8a9-46234172aae7': {'delay': '0.00229001045227', Thread-1484340::DEBUG::2013-01-08 10:41:09,544::task::568::TaskManager.Task::(_updateState) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::moving from state preparing -> state finished Thread-1484340::DEBUG::2013-01-08 10:41:09,545::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-1484340::DEBUG::2013-01-08 10:41:09,545::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-1484340::DEBUG::2013-01-08 10:41:09,545::task::957::TaskManager.Task::(_decref) Task=`bfebf940-d2a3-4b6c-948b-cac951a686bf`::ref 0 aborting False Thread-1484341::DEBUG::2013-01-08 10:41:09,558::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`7b8f725b-0a67-46d4-a3cf-db43daad0c42`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`9dc63ce4-0f76-4963-adfe-6f8eb1a44806`::Disk vda latency not available Thread-1484341::DEBUG::2013-01-08 10:41:09,559::libvirtvm::278::vm.Vm::(_getDiskLatency) vmId=`e8683e88-f3f2-4fe9-80f7-f4888d8e7a13`::Disk vda latency not available Thread-1484337::ERROR::2013-01-08 10:41:09,754::vm::258::vm.Vm::(run) vmId=`cfb17b98-1476-4fbf-9fab-7c7f48b60adf`::Failed to migrate Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 245, in run self._startUnderlyingMigration() File "/usr/share/vdsm/libvirtvm.py", line 474, in _startUnderlyingMigration None, maxBandwidth) File "/usr/share/vdsm/libvirtvm.py", line 510, in f ret = attr(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 83, in wrapper ret = f(*args, **kwargs) File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1103, in migrateToURI2 if ret == -1: raise libvirtError ('virDomainMigrateToURI2() failed', dom=self) libvirtError: internal error Process exited while reading console log output:
any chance you attach libvirtd.log and qemu log (/var/log/libvirt/qemu/{}.log?
Danken - any insights?
----- Original Message -----
From: "Tom Brown" <tom@ng23.net> To: "Roy Golan" <rgolan@redhat.com> Cc: "Haim Ateya" <hateya@redhat.com>, users@ovirt.org Sent: Tuesday, January 8, 2013 11:50:26 AM Subject: Re: [Users] oVirt 3.1 - VM Migration Issue
can you attach the same snip from the src VDSM 10.192.42.196 as well?
The log is pretty chatty therefore i did another migration attempt and snipd'd the new log from both sides.
see attached
participants (5)
-
Dan Kenigsberg -
Haim Ateya -
Roy Golan -
Simon Grinberg -
Tom Brown