- Users - oVirt List Archives

[Users] Problems with migration on a VM and not detected by gui
by Gianluca Cecchi 05 Feb '14

05 Feb '14

Hello, passing from 3.3.3rc to 3.3.3 final on fedora 19 based infra. Two hosts and one engine. Gluster DC. I have 3 VMs: CentOS 5.10, 6.5, Fedora 20 Main steps: 1) update engine with usual procedure 2) all VMs are on one node; I put into maintenance the other one and update it and reboot 3) activate the new node and migrate all VMs to it. >From webadmin gui point of view it seems all ok. Only "strange" thing is that the CentOS 6.5 VM has no ip shown, when usually it has becuse of ovrt-guest-agent installed on it So I try to connect to its console (configured as VNC). But I get error (the other two are ok and they are spice) Also, I cannot ping or ssh into the VM so there is indeed some problem. I didn't connect since 30th January so I don't knw if any probem arised before today. >From the original host /var/log/libvirt/qemu/c6s.log I see: 2014-01-30 11:21:37.561+0000: shutting down 2014-01-30 11:22:14.595+0000: starting up LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin QEMU_AUDIO_DRV=none /usr/bin/qemu-kvm -name c6s -S -machine pc-1.0,accel=kvm,usb=off -cpu Opteron_G2 -m 1024 -smp 1,sockets=1,cores=1,threads=1 -uuid 4147e0d3-19a7-447b-9d88-2ff19365bec0 -smbios type=1,manufacturer=oVirt,product=oVirt Node,version=19-5,serial=34353439-3036-435A-4A38-303330393338,uuid=4147e0d3-19a7-447b-9d88-2ff19365bec0 -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/c6s.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=2014-01-23T11:42:26,driftfix=slew -no-shutdown -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x4 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -drive if=none,id=drive-ide0-1-0,readonly=on,format=raw,serial= -device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -drive file=/rhev/data-center/mnt/glusterSD/f18ovn01.ceda.polimi.it:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/images/a5e4f67b-50b5-4740-9990-39deb8812445/53408cb0-bcd4-40de-bc69-89d59b7b5bc2,if=none,id=drive-virtio-disk0,format=raw,serial=a5e4f67b-50b5-4740-9990-39deb8812445,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,bootindex=1 -drive file=/rhev/data-center/mnt/glusterSD/f18ovn01.ceda.polimi.it:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/images/c1477133-6b06-480d-a233-1dae08daf8b3/c2a82c64-9dee-42bb-acf2-65b8081f2edf,if=none,id=drive-scsi0-0-0-0,format=raw,serial=c1477133-6b06-480d-a233-1dae08daf8b3,cache=none,werror=stop,rerror=stop,aio=threads -device scsi-hd,bus=scsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,id=scsi0-0-0-0 -netdev tap,fd=27,id=hostnet0,vhost=on,vhostfd=28 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=00:1a:4a:8f:04:f8,bus=pci.0,addr=0x3 -chardev socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/4147e0d3-19a7-447b-9d88-2ff19365bec0.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/4147e0d3-19a7-447b-9d88-2ff19365bec0.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 -device virtconsole,chardev=charconsole0,id=console0 -device usb-tablet,id=input0 -vnc 0:0,password -k en-us -vga cirrus -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x7 char device redirected to /dev/pts/0 (label charconsole0) 2014-02-04 12:48:01.855+0000: shutting down qemu: terminating on signal 15 from pid 1021 >From the updated host where I apparently migrated it I see: 2014-02-04 12:47:54.674+0000: starting up LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin QEMU_AUDIO_DRV=none /usr/bin/qemu-kvm -name c6s -S -machine pc-1.0,accel=kvm,usb=off -cpu Opteron_G2 -m 1024 -smp 1,sockets=1,cores=1,threads=1 -uuid 4147e0d3-19a7-447b-9d88-2ff19365bec0 -smbios type=1,manufacturer=oVirt,product=oVirt Node,version=19-5,serial=34353439-3036-435A-4A38-303330393338,uuid=4147e0d3-19a7-447b-9d88-2ff19365bec0 -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/var/lib/libvirt/qemu/c6s.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=2014-01-28T13:08:06,driftfix=slew -no-shutdown -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x4 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x6 -drive if=none,id=drive-ide0-1-0,readonly=on,format=raw,serial= -device ide-cd,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -drive file=/rhev/data-center/mnt/glusterSD/f18ovn01.ceda.polimi.it:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/images/a5e4f67b-50b5-4740-9990-39deb8812445/53408cb0-bcd4-40de-bc69-89d59b7b5bc2,if=none,id=drive-virtio-disk0,format=raw,serial=a5e4f67b-50b5-4740-9990-39deb8812445,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,bootindex=1 -drive file=/rhev/data-center/mnt/glusterSD/f18ovn01.ceda.polimi.it:gvdata/d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291/images/c1477133-6b06-480d-a233-1dae08daf8b3/c2a82c64-9dee-42bb-acf2-65b8081f2edf,if=none,id=drive-scsi0-0-0-0,format=raw,serial=c1477133-6b06-480d-a233-1dae08daf8b3,cache=none,werror=stop,rerror=stop,aio=threads -device scsi-hd,bus=scsi0.0,channel=0,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,id=scsi0-0-0-0 -netdev tap,fd=30,id=hostnet0,vhost=on,vhostfd=31 -device virtio-net-pci,netdev=hostnet0,id=net0,mac=00:1a:4a:8f:04:f8,bus=pci.0,addr=0x3 -chardev socket,id=charchannel0,path=/var/lib/libvirt/qemu/channels/4147e0d3-19a7-447b-9d88-2ff19365bec0.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/4147e0d3-19a7-447b-9d88-2ff19365bec0.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 -device virtconsole,chardev=charconsole0,id=console0 -device usb-tablet,id=input0 -vnc 0:0,password -k en-us -vga cirrus -incoming tcp:[::]:51152 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x7 char device redirected to /dev/pts/1 (label charconsole0) engine log https://drive.google.com/file/d/0BwoPbcrMv8mvZWpqOHNqc0dnenc/edit?usp=shari… source vdsm log: https://drive.google.com/file/d/0BwoPbcrMv8mvYlluMDh1Y19jdEU/edit?usp=shari… dest vdsm log https://drive.google.com/file/d/0BwoPbcrMv8mvT1JxcmdKWlloOFU/edit?usp=shari… First error I see in source host log: Thread-728830::ERROR::2014-02-04 13:42:59,735::BindingXMLRPC::984::vds::(wrapper) unexpected error Traceback (most recent call last): File "/usr/share/vdsm/BindingXMLRPC.py", line 970, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/gluster/api.py", line 53, in wrapper rv = func(*args, **kwargs) File "/usr/share/vdsm/gluster/api.py", line 206, in volumeStatus statusOption) File "/usr/share/vdsm/supervdsm.py", line 50, in __call__ return callMethod() File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda> **kwargs) File "<string>", line 2, in glusterVolumeStatus File "/usr/lib64/python2.7/multiprocessing/managers.py", line 773, in _callmethod raise convert_to_error(kind, result) KeyError: 'path' Thread-728831::ERROR::2014-02-04 13:42:59,805::BindingXMLRPC::984::vds::(wrapper) unexpected error Traceback (most recent call last): File "/usr/share/vdsm/BindingXMLRPC.py", line 970, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/gluster/api.py", line 53, in wrapper rv = func(*args, **kwargs) File "/usr/share/vdsm/gluster/api.py", line 206, in volumeStatus statusOption) File "/usr/share/vdsm/supervdsm.py", line 50, in __call__ return callMethod() File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda> **kwargs) File "<string>", line 2, in glusterVolumeStatus File "/usr/lib64/python2.7/multiprocessing/managers.py", line 773, in _callmethod raise convert_to_error(kind, result) KeyError: 'path' Thread-323::INFO::2014-02-04 13:43:05,765::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291', spUUID='eb679feb-4da2-4fd0-a185-abbe459ffa70', imgUUID='a3d332c0-c302-4f28-9ed3-e2e83566343f', volUUID='701eca86-df87-4b16-ac6d-e9f51e7ac171', options=None) Apart the problem itself, another one is in my opinion the engine that doesn't know about it at all.... For this VM, in its event tab I can see only: 2014-Feb-04, 13:57 user admin@internal initiated console session for VM c6s 1b78630c oVirt 2014-Feb-04, 13:51 user admin@internal initiated console session for VM c6s 1d77f16a oVirt 2014-Feb-04, 13:48 Migration completed (VM: c6s, Source: f18ovn03, Destination: f18ovn01, Duration: 8 sec). 17c547cc oVirt 2014-Feb-04, 13:47 Migration started (VM: c6s, Source: f18ovn03, Destination: f18ovn01, User: admin@internal). 17c547cc oVirt 2014-Jan-30, 12:30 user admin@internal initiated console session for VM c6s 5536edb8 oVirt 2014-Jan-30, 12:23 VM c6s started on Host f18ovn03 45209312 oVirt 2014-Jan-30, 12:22 user admin@internal initiated console session for VM c6s 19c766c8 oVirt 2014-Jan-30, 12:22 user admin@internal initiated console session for VM c6s 79815897 oVirt 2014-Jan-30, 12:22 VM c6s was started by admin@internal (Host: f18ovn03). 45209312 oVirt 2014-Jan-30, 12:22 VM c6s configuration was updated by admin@internal. 76cbc53 oVirt 2014-Jan-30, 12:21 VM c6s is down. Exit message: User shut down oVirt 2014-Jan-30, 12:20 VM shutdown initiated by admin@internal on VM c6s (Host: f18ovn03). 213c3a55 oVirt Gianluca

4 6

[Users] VM install failures on a stateless node
by David Li 04 Feb '14

04 Feb '14

Hi, I have been trying to install my first VM on a stateless node. so far I have failed twice with the node ending up in the "Non-responsive" mode. I had to reboot to recover and it took a while to reconfigure everything since this is stateless. I can still get into the node via the console. It's not dead. But the ovirtmgmt interface seems to be dead. The other iSCSI interface is running ok. Can anyone recommend ways how to debug this problem? Thanks. David

2 5

[Users] Ovirt 3.3.2 Cannot attach POSIX (gluster) storage domain
by Steve Dainard 04 Feb '14

04 Feb '14

I can successfully create a POSIX storage domain backed by gluster, but at the end of creation I get an error message "failed to acquire host id". Note that I have successfully created/activated NFS DC/SD on the same ovirt/hosts. I have some logs when I tried to attach to the DC after failure: *engine.log* 2014-02-04 09:54:04,324 INFO [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (ajp--127.0.0.1-8702-3) [1dd40406] Lock Acquired to object EngineLock [ex clusiveLocks= key: 8c4e8898-c91a-4d49-98e8-b6467791a9cc value: POOL , sharedLocks= ] 2014-02-04 09:54:04,473 INFO [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (pool-6-thread-42) [1dd40406] Running command: AddStoragePoolWithStorages Command internal: false. Entities affected : ID: 8c4e8898-c91a-4d49-98e8-b6467791a9cc Type: StoragePool 2014-02-04 09:54:04,673 INFO [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (pool-6-thread-42) [3f86c31b] Running command: ConnectStorageToVdsCommand intern al: true. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: System 2014-02-04 09:54:04,682 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-6-thread-42) [3f86c31b] START, ConnectStorageServerVDSCommand( HostName = ovirt001, HostId = 48f13d47-8346-4ff6-81ca-4f4324069db3, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = POSIXFS, connectionList = [{ id: 87f9 ff74-93c4-4fe5-9a56-ed5338290af9, connection: 10.0.10.3:/rep2, iqn: null, vfsType: glusterfs, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), lo g id: 332ff091 2014-02-04 09:54:05,089 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-6-thread-42) [3f86c31b] FINISH, ConnectStorageServerVDSCommand , return: {87f9ff74-93c4-4fe5-9a56-ed5338290af9=0}, log id: 332ff091 2014-02-04 09:54:05,093 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (pool-6-thread-42) [3f86c31b] START, CreateStoragePoolVDSCommand(HostNa me = ovirt001, HostId = 48f13d47-8346-4ff6-81ca-4f4324069db3, storagePoolId=8c4e8898-c91a-4d49-98e8-b6467791a9cc, storageType=POSIXFS, storagePoolName=IT, masterDomainId=471 487ed-2946-4dfc-8ec3-96546006be12, domainsIdList=[471487ed-2946-4dfc-8ec3-96546006be12], masterVersion=3), log id: 1be84579 2014-02-04 09:54:08,833 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorag ePoolVDSCommand] (pool-6-thread-42) [3f86c31b] Failed in CreateStoragePoolVDS method 2014-02-04 09:54:08,834 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (pool-6-thread-42) [3f86c31b] Error code AcquireHostIdFailure and error message VDSGenericException: VDSErrorException: Failed to CreateStoragePoolVDS, error = Cannot acquire host id: ('471487ed-2946-4dfc-8ec3-96546006be12', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument')) 2014-02-04 09:54:08,835 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (pool-6-thread-42) [3f86c31b] Command org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand return value StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=661, mMessage=Cannot acquire host id: ('471487ed-2946-4dfc-8ec3-96546006be12', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument'))]] 2014-02-04 09:54:08,836 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (pool-6-thread-42) [3f86c31b] HostName = ovirt001 2014-02-04 09:54:08,840 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (pool-6-thread-42) [3f86c31b] Command CreateStoragePoolVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateStoragePoolVDS, error = Cannot acquire host id: ('471487ed-2946-4dfc-8ec3-96546006be12', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument')) 2014-02-04 09:54:08,840 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (pool-6-thread-42) [3f86c31b] FINISH, CreateStoragePoolVDSCommand, log id: 1be84579 2014-02-04 09:54:08,841 ERROR [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (pool-6-thread-42) [3f86c31b] Command org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to CreateStoragePoolVDS, error = Cannot acquire host id: ('471487ed-2946-4dfc-8ec3-96546006be12', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument')) (Failed with error AcquireHostIdFailure and code 661) 2014-02-04 09:54:08,867 INFO [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (pool-6-thread-42) [3f86c31b] Command [id=373987cb-b54d-4174-b4a9-195be631f0d7]: Compensating CHANGED_ENTITY of org.ovirt.engine.core.common.businessentities.StoragePool; snapshot: id=8c4e8898-c91a-4d49-98e8-b6467791a9cc. 2014-02-04 09:54:08,871 INFO [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (pool-6-thread-42) [3f86c31b] Command [id=373987cb-b54d-4174-b4a9-195be631f0d7]: Compensating NEW_ENTITY_ID of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: storagePoolId = 8c4e8898-c91a-4d49-98e8-b6467791a9cc, storageId = 471487ed-2946-4dfc-8ec3-96546006be12. 2014-02-04 09:54:08,879 INFO [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (pool-6-thread-42) [3f86c31b] Command [id=373987cb-b54d-4174-b4a9-195be631f0d7]: Compensating CHANGED_ENTITY of org.ovirt.engine.core.common.businessentities.StorageDomainStatic; snapshot: id=471487ed-2946-4dfc-8ec3-96546006be12. 2014-02-04 09:54:08,951 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-42) [3f86c31b] Correlation ID: 1dd40406, Job ID: 07003dff-9e0e-42ae-8f88-6b055b45f797, Call Stack: null, Custom Event ID: -1, Message: Failed to attach Storage Domains to Data Center IT. (User: admin@internal) 2014-02-04 09:54:08,975 INFO [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (pool-6-thread-42) [3f86c31b] Lock freed to object EngineLock [exclusiveLocks= key: 8c4e8898-c91a-4d49-98e8-b6467791a9cc value: POOL , sharedLocks= ] *vdsm.log* Thread-30::DEBUG::2014-02-04 09:54:04,692::BindingXMLRPC::167::vds::(wrapper) client [10.0.10.2] flowID [3f86c31b] Thread-30::DEBUG::2014-02-04 09:54:04,692::task::579::TaskManager.Task::(_updateState) Task=`218dcde9-bbc7-4d5a-ad53-0bab556c6261`::moving from state init -> state preparing Thread-30::INFO::2014-02-04 09:54:04,693::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=6, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': '10.0.10.3:/rep2', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', 'password': '******', 'id': '87f9ff74-93c4-4fe5-9a56-ed5338290af9'}], options=None) Thread-30::DEBUG::2014-02-04 09:54:04,698::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/mount -t glusterfs 10.0.10.3:/rep2 /rhev/data-center/mnt/10.0.10.3:_rep2' (cwd None) Thread-30::DEBUG::2014-02-04 09:54:05,067::hsm::2315::Storage.HSM::(__prefetchDomains) posix local path: /rhev/data-center/mnt/10.0.10.3:_rep2 Thread-30::DEBUG::2014-02-04 09:54:05,078::hsm::2333::Storage.HSM::(__prefetchDomains) Found SD uuids: ('471487ed-2946-4dfc-8ec3-96546006be12',) Thread-30::DEBUG::2014-02-04 09:54:05,078::hsm::2389::Storage.HSM::(connectStorageServer) knownSDs: {471487ed-2946-4dfc-8ec3-96546006be12: storage.nfsSD.findDomain} Thread-30::INFO::2014-02-04 09:54:05,078::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '87f9ff74-93c4-4fe5-9a56-ed5338290af9'}]} Thread-30::DEBUG::2014-02-04 09:54:05,079::task::1168::TaskManager.Task::(prepare) Task=`218dcde9-bbc7-4d5a-ad53-0bab556c6261`::finished: {'statuslist': [{'status': 0, 'id': '87f9ff74-93c4-4fe5-9a56-ed5338290af9'}]} Thread-30::DEBUG::2014-02-04 09:54:05,079::task::579::TaskManager.Task::(_updateState) Task=`218dcde9-bbc7-4d5a-ad53-0bab556c6261`::moving from state preparing -> state finished Thread-30::DEBUG::2014-02-04 09:54:05,079::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-30::DEBUG::2014-02-04 09:54:05,079::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-30::DEBUG::2014-02-04 09:54:05,079::task::974::TaskManager.Task::(_decref) Task=`218dcde9-bbc7-4d5a-ad53-0bab556c6261`::ref 0 aborting False Thread-31::DEBUG::2014-02-04 09:54:05,098::BindingXMLRPC::167::vds::(wrapper) client [10.0.10.2] flowID [3f86c31b] Thread-31::DEBUG::2014-02-04 09:54:05,099::task::579::TaskManager.Task::(_updateState) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::moving from state init -> state preparing Thread-31::INFO::2014-02-04 09:54:05,099::logUtils::44::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='8c4e8898-c91a-4d49-98e8-b6467791a9cc', poolName='IT', masterDom='471487ed-2946-4dfc-8ec3-96546006be12', domList=['471487ed-2946-4dfc-8ec3-96546006be12'], masterVersion=3, lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60, ioOpTimeoutSec=10, leaseRetries=3, options=None) Thread-31::DEBUG::2014-02-04 09:54:05,099::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-31::DEBUG::2014-02-04 09:54:05,100::misc::811::SamplingMethod::(__call__) Got in to sampling method Thread-31::DEBUG::2014-02-04 09:54:05,100::misc::809::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-31::DEBUG::2014-02-04 09:54:05,100::misc::811::SamplingMethod::(__call__) Got in to sampling method Thread-31::DEBUG::2014-02-04 09:54:05,100::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-31::DEBUG::2014-02-04 09:54:05,114::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21 Thread-31::DEBUG::2014-02-04 09:54:05,115::misc::819::SamplingMethod::(__call__) Returning last result Thread-31::DEBUG::2014-02-04 09:54:07,144::multipath::112::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None) Thread-31::DEBUG::2014-02-04 09:54:07,331::multipath::112::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 Thread-31::DEBUG::2014-02-04 09:54:07,332::lvm::510::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-31::DEBUG::2014-02-04 09:54:07,333::lvm::512::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-31::DEBUG::2014-02-04 09:54:07,333::lvm::521::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-31::DEBUG::2014-02-04 09:54:07,333::lvm::523::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-31::DEBUG::2014-02-04 09:54:07,333::lvm::541::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-31::DEBUG::2014-02-04 09:54:07,334::lvm::543::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-31::DEBUG::2014-02-04 09:54:07,334::misc::819::SamplingMethod::(__call__) Returning last result Thread-31::DEBUG::2014-02-04 09:54:07,499::fileSD::137::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.0.10.3: _rep2/471487ed-2946-4dfc-8ec3-96546006be12 Thread-31::DEBUG::2014-02-04 09:54:07,605::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-31::DEBUG::2014-02-04 09:54:07,647::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=gluster-store-rep2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=10.0.10.3:/rep2', 'ROLE=Regular', 'SDUUID=471487ed-2946-4dfc-8ec3-96546006be12', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=469191aac3fb8ef504b6a4d301b6d8be6fffece1'] Thread-31::DEBUG::2014-02-04 09:54:07,683::fileSD::558::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-31::DEBUG::2014-02-04 09:54:07,684::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '471487ed-2946-4dfc-8ec3-96546006be12_imageNS' Thread-31::DEBUG::2014-02-04 09:54:07,684::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '471487ed-2946-4dfc-8ec3-96546006be12_volumeNS' Thread-31::INFO::2014-02-04 09:54:07,684::fileSD::299::Storage.StorageDomain::(validate) sdUUID=471487ed-2946-4dfc-8ec3-96546006be12 Thread-31::DEBUG::2014-02-04 09:54:07,692::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=gluster-store-rep2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=10.0.10.3:/rep2', 'ROLE=Regular', 'SDUUID=471487ed-2946-4dfc-8ec3-96546006be12', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=469191aac3fb8ef504b6a4d301b6d8be6fffece1'] Thread-31::DEBUG::2014-02-04 09:54:07,693::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc`ReqID=`e0a3d477-b953-49d9-ab78-67695a6bc6d5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '971' at 'createStoragePool' Thread-31::DEBUG::2014-02-04 09:54:07,693::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc' for lock type 'exclusive' Thread-31::DEBUG::2014-02-04 09:54:07,693::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc' is free. Now locking as 'exclusive' (1 active user) Thread-31::DEBUG::2014-02-04 09:54:07,693::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc`ReqID=`e0a3d477-b953-49d9-ab78-67695a6bc6d5`::Granted request Thread-31::DEBUG::2014-02-04 09:54:07,694::task::811::TaskManager.Task::(resourceAcquired) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::_resourcesAcquired: Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc (exclusive) Thread-31::DEBUG::2014-02-04 09:54:07,694::task::974::TaskManager.Task::(_decref) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::ref 1 aborting False Thread-31::DEBUG::2014-02-04 09:54:07,694::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.471487ed-2946-4dfc-8ec3-96546006be12`ReqID=`bc20dd7e-d351-47c5-8ed3-78b1b11d703a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '973' at 'createStoragePool' Thread-31::DEBUG::2014-02-04 09:54:07,694::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.471487ed-2946-4dfc-8ec3-96546006be12' for lock type 'exclusive' Thread-31::DEBUG::2014-02-04 09:54:07,695::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.471487ed-2946-4dfc-8ec3-96546006be12' is free. Now locking as 'exclusive' (1 active user) Thread-31::DEBUG::2014-02-04 09:54:07,695::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.471487ed-2946-4dfc-8ec3-96546006be12`ReqID=`bc20dd7e-d351-47c5-8ed3-78b1b11d703a`::Granted request Thread-31::DEBUG::2014-02-04 09:54:07,695::task::811::TaskManager.Task::(resourceAcquired) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::_resourcesAcquired: Storage.471487ed-2946-4dfc-8ec3-96546006be12 (exclusive) Thread-31::DEBUG::2014-02-04 09:54:07,695::task::974::TaskManager.Task::(_decref) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::ref 1 aborting False Thread-31::INFO::2014-02-04 09:54:07,696::sp::593::Storage.StoragePool::(create) spUUID=8c4e8898-c91a-4d49-98e8-b6467791a9cc poolName=IT master_sd=471487ed-2946-4dfc-8ec3-96546006be12 domList=['471487ed-2946-4dfc-8ec3-96546006be12'] masterVersion=3 {'LEASETIMESEC': 60, 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5} Thread-31::INFO::2014-02-04 09:54:07,696::fileSD::299::Storage.StorageDomain::(validate) sdUUID=471487ed-2946-4dfc-8ec3-96546006be12 Thread-31::DEBUG::2014-02-04 09:54:07,703::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=gluster-store-rep2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=10.0.10.3:/rep2', 'ROLE=Regular', 'SDUUID=471487ed-2946-4dfc-8ec3-96546006be12', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=469191aac3fb8ef504b6a4d301b6d8be6fffece1'] Thread-31::DEBUG::2014-02-04 09:54:07,710::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=gluster-store-rep2', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=10.0.10.3:/rep2', 'ROLE=Regular', 'SDUUID=471487ed-2946-4dfc-8ec3-96546006be12', 'TYPE=POSIXFS', 'VERSION=3', '_SHA_CKSUM=469191aac3fb8ef504b6a4d301b6d8be6fffece1'] Thread-31::DEBUG::2014-02-04 09:54:07,711::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction Thread-31::DEBUG::2014-02-04 09:54:07,711::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction Thread-31::INFO::2014-02-04 09:54:07,711::clusterlock::174::SANLock::(acquireHostId) Acquiring host id for domain 471487ed-2946-4dfc-8ec3-96546006be12 (id: 250) Thread-31::ERROR::2014-02-04 09:54:08,722::task::850::TaskManager.Task::(_setError) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::Unexpected error Traceback (most recent call last): File "/usr/share/vdsm/storage/task.py", line 857, in _run return fn(*args, **kargs) File "/usr/share/vdsm/logUtils.py", line 45, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 977, in createStoragePool masterVersion, leaseParams) File "/usr/share/vdsm/storage/sp.py", line 618, in create self._acquireTemporaryClusterLock(msdUUID, leaseParams) File "/usr/share/vdsm/storage/sp.py", line 560, in _acquireTemporaryClusterLock msd.acquireHostId(self.id) File "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId self._clusterLock.acquireHostId(hostId, async) File "/usr/share/vdsm/storage/clusterlock.py", line 189, in acquireHostId raise se.AcquireHostIdFailure(self._sdUUID, e) AcquireHostIdFailure: Cannot acquire host id: ('471487ed-2946-4dfc-8ec3-96546006be12', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument')) Thread-31::DEBUG::2014-02-04 09:54:08,826::task::869::TaskManager.Task::(_run) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::Task._run: 66924dbf-5a1c-473e-a158-d038aae38dc3 (None, '8c4e8898-c91a-4d49-98e8-b6467791a9cc', 'IT', '471487ed-2946-4dfc-8ec3-96546006be12', ['471487ed-2946-4dfc-8ec3-96546006be12'], 3, None, 5, 60, 10, 3) {} failed - stopping task Thread-31::DEBUG::2014-02-04 09:54:08,826::task::1194::TaskManager.Task::(stop) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::stopping in state preparing (force False) Thread-31::DEBUG::2014-02-04 09:54:08,826::task::974::TaskManager.Task::(_decref) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::ref 1 aborting True Thread-31::INFO::2014-02-04 09:54:08,826::task::1151::TaskManager.Task::(prepare) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::aborting: Task is aborted: 'Cannot acquire host id' - code 661 Thread-31::DEBUG::2014-02-04 09:54:08,826::task::1156::TaskManager.Task::(prepare) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::Prepare: aborted: Cannot acquire host id Thread-31::DEBUG::2014-02-04 09:54:08,827::task::974::TaskManager.Task::(_decref) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::ref 0 aborting True Thread-31::DEBUG::2014-02-04 09:54:08,827::task::909::TaskManager.Task::(_doAbort) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::Task._doAbort: force False Thread-31::DEBUG::2014-02-04 09:54:08,827::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-31::DEBUG::2014-02-04 09:54:08,827::task::579::TaskManager.Task::(_updateState) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::moving from state preparing -> state aborting Thread-31::DEBUG::2014-02-04 09:54:08,827::task::534::TaskManager.Task::(__state_aborting) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::_aborting: recover policy none Thread-31::DEBUG::2014-02-04 09:54:08,827::task::579::TaskManager.Task::(_updateState) Task=`66924dbf-5a1c-473e-a158-d038aae38dc3`::moving from state aborting -> state failed Thread-31::DEBUG::2014-02-04 09:54:08,827::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.471487ed-2946-4dfc-8ec3-96546006be12': < ResourceRef 'Storage.471487ed-2946-4dfc-8ec3-96546006be12', isValid: 'True' obj: 'None'>, 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc': < ResourceRef 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc', isValid: 'True' obj: 'None'>} Thread-31::DEBUG::2014-02-04 09:54:08,828::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-31::DEBUG::2014-02-04 09:54:08,828::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.471487ed-2946-4dfc-8ec3-96546006be12' Thread-31::DEBUG::2014-02-04 09:54:08,828::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.471487ed-2946-4dfc-8ec3-96546006be12' (0 active users) Thread-31::DEBUG::2014-02-04 09:54:08,828::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.471487ed-2946-4dfc-8ec3-96546006be12' is free, finding out if anyone is waiting for it. Thread-31::DEBUG::2014-02-04 09:54:08,828::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.471487ed-2946-4dfc-8ec3-96546006be12', Clearing records. Thread-31::DEBUG::2014-02-04 09:54:08,828::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc' Thread-31::DEBUG::2014-02-04 09:54:08,829::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc' (0 active users) Thread-31::DEBUG::2014-02-04 09:54:08,829::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc' is free, finding out if anyone is waiting for it. Thread-31::DEBUG::2014-02-04 09:54:08,829::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.8c4e8898-c91a-4d49-98e8-b6467791a9cc', Clearing records. Thread-31::ERROR::2014-02-04 09:54:08,829::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot acquire host id: ('471487ed-2946-4dfc-8ec3-96546006be12', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument'))", 'code': 661}} *Storage domain metadata file:* CLASS=Data DESCRIPTION=gluster-store-rep2 IOOPTIMEOUTSEC=10 LEASERETRIES=3 LEASETIMESEC=60 LOCKPOLICY= LOCKRENEWALINTERVALSEC=5 POOL_UUID= REMOTE_PATH=10.0.10.3:/rep2 ROLE=Regular SDUUID=471487ed-2946-4dfc-8ec3-96546006be12 TYPE=POSIXFS VERSION=3 _SHA_CKSUM=469191aac3fb8ef504b6a4d301b6d8be6fffece1 *Steve Dainard * IT Infrastructure Manager Miovision <http://miovision.com/> | *Rethink Traffic* 519-513-2407 ex.250 877-646-8476 (toll-free) *Blog <http://miovision.com/blog> | **LinkedIn <https://www.linkedin.com/company/miovision-technologies> | Twitter <https://twitter.com/miovision> | Facebook <https://www.facebook.com/miovision>* ------------------------------ Miovision Technologies Inc. | 148 Manitou Drive, Suite 101, Kitchener, ON, Canada | N2C 1L3 This e-mail may contain information that is privileged or confidential. If you are not the intended recipient, please delete the e-mail and any attachments and notify us immediately.

3 4

Re: [Users] I can't remove VM
by Dafna Ron 04 Feb '14

04 Feb '14

Any time. If you manage to reproduce please let us know. Dafna On 02/04/2014 05:00 PM, Eduardo Ramos wrote: > Hi Dafna! Thanks for responding. > > In order to collect full logs, I migrated my 61 machines from 16 to 2 > hosts. When I tried to remove, it worked without any problem. I did > not understand why. I'm investigating. > > Thanks again for your attention. > > On 02/03/2014 11:43 AM, Dafna Ron wrote: >> please attach full vdsm and engine logs. >> >> Thanks, >> >> Dafna >> >> >> On 02/03/2014 12:11 PM, Eduardo Ramos wrote: >>> Hi all! >>> >>> I'm having trouble on removing virtual machines. My environment run >>> on a ISCSI domain storage. When I try remove, the SPM logs: >>> >>> # Start vdsm SPM log # >>> Thread-6019517::INFO::2014-02-03 >>> 09:58:09,293::logUtils::41::dispatcher::(wrapper) Run and protect: >>> deleteImage(sdUUID='c332da29-ba9f-4c94-8fa9-346bb8e04e2a', >>> spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> imgUUID='57ba1906-2035-4503-acbc-5f6f077f75cc', postZero='false', >>> force='false') >>> Thread-6019517::INFO::2014-02-03 >>> 09:58:09,293::blockSD::816::Storage.StorageDomain::(validate) >>> sdUUID=c332da29-ba9f-4c94-8fa9-346bb8e04e2a >>> Thread-6019517::ERROR::2014-02-03 >>> 09:58:10,061::task::833::TaskManager.Task::(_setError) >>> Task=`8cbf9978-ed51-488a-af52-a3db030e44ff`::Unexpected error >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/task.py", line 840, in _run >>> return fn(*args, **kargs) >>> File "/usr/share/vdsm/logUtils.py", line 42, in wrapper >>> res = f(*args, **kwargs) >>> File "/usr/share/vdsm/storage/hsm.py", line 1429, in deleteImage >>> allVols = dom.getAllVolumes() >>> File "/usr/share/vdsm/storage/blockSD.py", line 972, in getAllVolumes >>> return getAllVolumes(self.sdUUID) >>> File "/usr/share/vdsm/storage/blockSD.py", line 172, in getAllVolumes >>> vImg not in res[vPar]['imgs']): >>> KeyError: '63650a24-7e83-4c0a-851d-0ce9869a294d' >>> Thread-6019517::INFO::2014-02-03 >>> 09:58:10,063::task::1134::TaskManager.Task::(prepare) >>> Task=`8cbf9978-ed51-488a-af52-a3db030e44ff`::aborting: Task is >>> aborted: u"'63650a24-7e83-4c0a-851d-0ce9869a294d'" - code 100 >>> Thread-6019517::ERROR::2014-02-03 >>> 09:58:10,066::dispatcher::70::Storage.Dispatcher.Protect::(run) >>> '63650a24-7e83-4c0a-851d-0ce9869a294d' >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run >>> result = ctask.prepare(self.func, *args, **kwargs) >>> File "/usr/share/vdsm/storage/task.py", line 1142, in prepare >>> raise self.error >>> KeyError: '63650a24-7e83-4c0a-851d-0ce9869a294d' >>> Thread-6019518::INFO::2014-02-03 >>> 09:58:10,087::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getSpmStatus(spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> options=None) >>> Thread-6019518::INFO::2014-02-03 >>> 09:58:10,088::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getSpmStatus, Return response: {'spm_st': {'spmId': 14, 'spmStatus': >>> 'SPM', 'spmLver': 64}} >>> Thread-6019519::INFO::2014-02-03 >>> 09:58:10,100::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getAllTasksStatuses(spUUID=None, options=None) >>> Thread-6019519::INFO::2014-02-03 >>> 09:58:10,101::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getAllTasksStatuses, Return response: {'allTasksStatus': {}} >>> Thread-6019520::INFO::2014-02-03 >>> 09:58:10,109::logUtils::41::dispatcher::(wrapper) Run and protect: >>> spmStop(spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', options=None) >>> Thread-6019520::INFO::2014-02-03 >>> 09:58:10,681::clusterlock::121::SafeLease::(release) Releasing >>> cluster lock for domain c332da29-ba9f-4c94-8fa9-346bb8e04e2a >>> Thread-6019521::INFO::2014-02-03 >>> 09:58:11,054::logUtils::41::dispatcher::(wrapper) Run and protect: >>> repoStats(options=None) >>> Thread-6019521::INFO::2014-02-03 >>> 09:58:11,054::logUtils::44::dispatcher::(wrapper) Run and protect: >>> repoStats, Return response: >>> {u'51eb6183-157d-4015-ae0f-1c7ffb1731c0': {'delay': >>> '0.00799298286438', 'lastCheck': '5.3', 'code': 0, 'valid': True}, >>> u'c332da29-ba9f-4c94-8fa9-346bb8e04e2a': {'delay': >>> '0.0197920799255', 'lastCheck': '4.9', 'code': 0, 'valid': True}, >>> u'0e0be898-6e04-4469-bb32-91f3cf8146d1': {'delay': >>> '0.00803208351135', 'lastCheck': '5.3', 'code': 0, 'valid': True}} >>> Thread-6019520::INFO::2014-02-03 >>> 09:58:11,732::logUtils::44::dispatcher::(wrapper) Run and protect: >>> spmStop, Return response: None >>> Thread-6019523::INFO::2014-02-03 >>> 09:58:11,835::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getAllTasksStatuses(spUUID=None, options=None) >>> Thread-6019523::INFO::2014-02-03 >>> 09:58:11,835::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getAllTasksStatuses, Return response: {'allTasksStatus': {}} >>> Thread-6019524::INFO::2014-02-03 >>> 09:58:11,844::logUtils::41::dispatcher::(wrapper) Run and protect: >>> spmStop(spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', options=None) >>> Thread-6019524::ERROR::2014-02-03 >>> 09:58:11,846::task::833::TaskManager.Task::(_setError) >>> Task=`00df5ff7-bbf4-4a0e-b60b-1b06dcaa7683`::Unexpected error >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/task.py", line 840, in _run >>> return fn(*args, **kargs) >>> File "/usr/share/vdsm/logUtils.py", line 42, in wrapper >>> res = f(*args, **kwargs) >>> File "/usr/share/vdsm/storage/hsm.py", line 601, in spmStop >>> pool.stopSpm() >>> File "/usr/share/vdsm/storage/securable.py", line 66, in wrapper >>> raise SecureError() >>> SecureError >>> Thread-6019524::INFO::2014-02-03 >>> 09:58:11,855::task::1134::TaskManager.Task::(prepare) >>> Task=`00df5ff7-bbf4-4a0e-b60b-1b06dcaa7683`::aborting: Task is >>> aborted: u'' - code 100 >>> Thread-6019524::ERROR::2014-02-03 >>> 09:58:11,857::dispatcher::70::Storage.Dispatcher.Protect::(run) >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run >>> result = ctask.prepare(self.func, *args, **kwargs) >>> File "/usr/share/vdsm/storage/task.py", line 1142, in prepare >>> raise self.error >>> SecureError >>> Dummy-6018624::INFO::2014-02-03 >>> 09:58:14,220::storage_mailbox::674::Storage.MailBox.SpmMailMonitor::(run) >>> SPM_MailMonitor - Incoming mail monitoring thread stopped >>> Thread-34627::INFO::2014-02-03 >>> 09:58:17,696::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getVolumeSize(sdUUID='c332da29-ba9f-4c94-8fa9-346bb8e04e2a', >>> spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> imgUUID='974d9602-8fbe-485b-a12d-59b6c34826b7', >>> volUUID='c1bcfe5c-20ab-4f50-a88b-e2e0e1184bf8', options=None) >>> Thread-34757::INFO::2014-02-03 >>> 09:58:17,696::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getVolumeSize(sdUUID='c332da29-ba9f-4c94-8fa9-346bb8e04e2a', >>> spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> imgUUID='49f65bfd-8592-42b9-9a31-91268402903f', >>> volUUID='511e6584-4f19-426d-9379-b223d0c2d9c6', options=None) >>> Thread-34627::INFO::2014-02-03 >>> 09:58:17,697::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getVolumeSize, Return response: {'truesize': '10737418240', >>> 'apparentsize': '10737418240'} >>> Thread-34757::INFO::2014-02-03 >>> 09:58:17,698::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getVolumeSize, Return response: {'truesize': '32212254720', >>> 'apparentsize': '32212254720'} >>> Thread-6019529::INFO::2014-02-03 >>> 09:58:21,672::logUtils::41::dispatcher::(wrapper) Run and protect: >>> repoStats(options=None) >>> Thread-6019529::INFO::2014-02-03 >>> 09:58:21,673::logUtils::44::dispatcher::(wrapper) Run and protect: >>> repoStats, Return response: >>> {u'51eb6183-157d-4015-ae0f-1c7ffb1731c0': {'delay': >>> '0.00730204582214', 'lastCheck': '5.9', 'code': 0, 'valid': True}, >>> u'c332da29-ba9f-4c94-8fa9-346bb8e04e2a': {'delay': >>> '0.0207469463348', 'lastCheck': '5.3', 'code': 0, 'valid': True}, >>> u'0e0be898-6e04-4469-bb32-91f3cf8146d1': {'delay': >>> '0.00734615325928', 'lastCheck': '5.9', 'code': 0, 'valid': True}} >>> Thread-243::INFO::2014-02-03 >>> 09:58:27,800::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getVolumeSize(sdUUID='c332da29-ba9f-4c94-8fa9-346bb8e04e2a', >>> spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> imgUUID='50f2c3e9-aa94-4ad1-9c3f-91b452292374', >>> volUUID='d7cddb76-a5b7-49ed-9efe-44d92ec18d93', options=None) >>> Thread-34590::INFO::2014-02-03 >>> 09:58:27,801::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getVolumeSize(sdUUID='c332da29-ba9f-4c94-8fa9-346bb8e04e2a', >>> spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> imgUUID='c36bb1da-babd-47bd-a406-58f0cb529c00', >>> volUUID='6ea83f9e-c614-4e11-ab57-314ed4efeeaa', options=None) >>> Thread-243::INFO::2014-02-03 >>> 09:58:27,802::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getVolumeSize, Return response: {'truesize': '10737418240', >>> 'apparentsize': '10737418240'} >>> Thread-34590::INFO::2014-02-03 >>> 09:58:27,803::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getVolumeSize, Return response: {'truesize': '107374182400', >>> 'apparentsize': '107374182400'} >>> Thread-6019535::INFO::2014-02-03 >>> 09:58:32,337::logUtils::41::dispatcher::(wrapper) Run and protect: >>> repoStats(options=None) >>> Thread-6019535::INFO::2014-02-03 >>> 09:58:32,337::logUtils::44::dispatcher::(wrapper) Run and protect: >>> repoStats, Return response: >>> {u'51eb6183-157d-4015-ae0f-1c7ffb1731c0': {'delay': >>> '0.0119340419769', 'lastCheck': '6.6', 'code': 0, 'valid': True}, >>> u'c332da29-ba9f-4c94-8fa9-346bb8e04e2a': {'delay': >>> '0.0190720558167', 'lastCheck': '6.0', 'code': 0, 'valid': True}, >>> u'0e0be898-6e04-4469-bb32-91f3cf8146d1': {'delay': >>> '0.00720596313477', 'lastCheck': '6.6', 'code': 0, 'valid': True}} >>> Thread-2017487::INFO::2014-02-03 >>> 09:58:37,692::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getVolumeSize(sdUUID='c332da29-ba9f-4c94-8fa9-346bb8e04e2a', >>> spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', >>> imgUUID='827f2d81-dc8c-414e-90d2-75e76b3250a0', >>> volUUID='f86ec330-0815-4361-8ce7-abf3318a8939', options=None) >>> Thread-2017487::INFO::2014-02-03 >>> 09:58:37,693::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getVolumeSize, Return response: {'truesize': '10737418240', >>> 'apparentsize': '10737418240'} >>> Thread-6019540::INFO::2014-02-03 >>> 09:58:39,118::logUtils::41::dispatcher::(wrapper) Run and protect: >>> getAllTasksStatuses(spUUID=None, options=None) >>> Thread-6019540::INFO::2014-02-03 >>> 09:58:39,118::logUtils::44::dispatcher::(wrapper) Run and protect: >>> getAllTasksStatuses, Return response: {'allTasksStatus': {}} >>> Thread-6019541::INFO::2014-02-03 >>> 09:58:39,126::logUtils::41::dispatcher::(wrapper) Run and protect: >>> spmStop(spUUID='9dbc7bb1-c460-4202-8f10-862d2ed3ed9a', options=None) >>> Thread-6019541::ERROR::2014-02-03 >>> 09:58:39,127::task::833::TaskManager.Task::(_setError) >>> Task=`1f478485-401b-4b9b-b58b-1e7973cf64a2`::Unexpected error >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/task.py", line 840, in _run >>> return fn(*args, **kargs) >>> File "/usr/share/vdsm/logUtils.py", line 42, in wrapper >>> res = f(*args, **kwargs) >>> File "/usr/share/vdsm/storage/hsm.py", line 601, in spmStop >>> pool.stopSpm() >>> File "/usr/share/vdsm/storage/securable.py", line 66, in wrapper >>> raise SecureError() >>> SecureError >>> Thread-6019541::INFO::2014-02-03 >>> 09:58:39,128::task::1134::TaskManager.Task::(prepare) >>> Task=`1f478485-401b-4b9b-b58b-1e7973cf64a2`::aborting: Task is >>> aborted: u'' - code 100 >>> Thread-6019541::ERROR::2014-02-03 >>> 09:58:39,130::dispatcher::70::Storage.Dispatcher.Protect::(run) >>> Traceback (most recent call last): >>> File "/usr/share/vdsm/storage/dispatcher.py", line 62, in run >>> result = ctask.prepare(self.func, *args, **kwargs) >>> File "/usr/share/vdsm/storage/task.py", line 1142, in prepare >>> raise self.error >>> SecureError >>> # End vdsm SPM log # >>> >>> And after, the cluster elects another SPM. >>> >>> The webgui shows on 'events' tab: >>> >>> # Start webgui events # >>> Data Center is being initialized, please wait for initialization to >>> complete. >>> Failed to remove VM _12.147_postgresql_default.sir.inpe.br_apagar >>> (User: eduardo.ramos). >>> # End webgui events # >>> >>> Engine logs nothing but normal change of SPM. >>> >>> I would like to know how I can identify what is stuck, and if I can >>> delete by hand, deleting entry from DB and lvremove. >>> >>> Thanks! >>> >>> >>> _______________________________________________ >>> Users mailing list >>> Users(a)ovirt.org >>> http://lists.ovirt.org/mailman/listinfo/users >> >> > > -- Dafna Ron

1 0

[Users] oVirt 3.3.3 RC EL6 Live Snapshot
by Karli Sjöberg 04 Feb '14

04 Feb '14

Hi! I´ve gone through upgrading from 3.3.2 to 3.3.3 RC on CentOS 6.5 in our test environment, went off without a hitch, so "good job" guys! However something I´d very much like to see fixed is live snapshots for CentOS, especially since it seems to be fixed already for Fedora. Issue already been discussed: http://lists.ovirt.org/pipermail/users/2013-December/019090.html Is this something that can be targeted for 3.3.3 GA? -- Med Vänliga Hälsningar ------------------------------------------------------------------------------- Karli Sjöberg Swedish University of Agricultural Sciences Box 7079 (Visiting Address Kronåsvägen 8) S-750 07 Uppsala, Sweden Phone: +46-(0)18-67 15 66 karli.sjoberg(a)slu.se

8 25

[Users] Install on CentOS6.5 fails
by ml ml 04 Feb '14

04 Feb '14

Hello List, i am trying to install oVirt on CentOS6.5 The Howto from: http://www.ovirt.org/Download fails with: [root@ovirt ovirt-engine]# yum localinstall http://ovirt.org/releases/ovirt-release-el.noarch.rpm Loaded plugins: fastestmirror, versionlock Setting up Local Package Process ovirt-release-el.noarch.rpm | 8.1 kB 00:00 Examining /var/tmp/yum-root-200V5v/ovirt-release-el.noarch.rpm: ovirt-release-el6-10.0.1-3.noarch Marking /var/tmp/yum-root-200V5v/ovirt-release-el.noarch.rpm to be installed Loading mirror speeds from cached hostfile * base: ftp.plusline.de * extras: mirror.skylink-datacenter.de * updates: ftp-stud.fht-esslingen.de Resolving Dependencies --> Running transaction check ---> Package ovirt-release-el6.noarch 0:10.0.1-3 will be installed --> Processing Dependency: epel-release for package: ovirt-release-el6-10.0.1-3.noarch --> Finished Dependency Resolution Error: Package: ovirt-release-el6-10.0.1-3.noarch (/ovirt-release-el.noarch) Requires: epel-release You could try using --skip-broken to work around the problem You could try running: rpm -Va --nofiles --nodigest So i used: http://wiki.centos.org/HowTos/oVirt The Install runs without any errors. However, i am getting a blank page now when i try to access my webadmin page. My Server.log: 1. 2014-02-04 12:19:49,332 ERROR [org.jboss.as.controller.management-operation] (ServerService Thread Pool -- 20) JBAS014612: Operation ("add") failed - address: ([("subsystem" => "jaxrs")]): org.jboss.modules.ModuleLoadError: Error loading module from /usr/share/ovirt-engine/modules/org/apache/httpcomponents/main/module.xml at org.jboss.modules.ModuleLoadException.toError(ModuleLoadException.java:78) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.Module.getPathsUnchecked(Module.java:1166) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.Module.loadModuleClass(Module.java:512) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:182) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:468) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:456) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ConcurrentClassLoader.performLoadClassChecked(ConcurrentClassLoader.java:423) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:120) [jboss-modules.jar:1.1.1.GA] at org.jboss.resteasy.plugins.server.servlet.ResteasyBootstrapClasses.<clinit>(ResteasyBootstrapClasses.java:11) at org.jboss.as.jaxrs.deployment.JaxrsScanningProcessor.<clinit>(JaxrsScanningProcessor.java:121) at org.jboss.as.jaxrs.JaxrsSubsystemAdd$1.execute(JaxrsSubsystemAdd.java:61) at org.jboss.as.server.AbstractDeploymentChainStep.execute(AbstractDeploymentChainStep.java:45) at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:385) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.controller.AbstractOperationContext.doCompleteStep(AbstractOperationContext.java:272) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.controller.AbstractOperationContext.completeStep(AbstractOperationContext.java:200) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.controller.ParallelBootOperationStepHandler$ParallelBootTask.run(ParallelBootOperationStepHandler.java:311) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146) [rt.jar:1.6.0_30] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.6.0_30] at java.lang.Thread.run(Thread.java:701) [rt.jar:1.6.0_30] at org.jboss.threads.JBossThread.run(JBossThread.java:122) [jboss-threads-2.0.0.GA.jar:2.0.0.GA] Caused by: javax.xml.stream.XMLStreamException: ParseError at [row,col]:[31,47] Message: Failed to add resource root 'httpclient.jar' at path 'httpclient.jar' at org.jboss.modules.ModuleXmlParser.parseResourceRoot(ModuleXmlParser.java:898) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleXmlParser.parseResources(ModuleXmlParser.java:854) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleXmlParser.parseModuleContents(ModuleXmlParser.java:676) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleXmlParser.parseDocument(ModuleXmlParser.java:548) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleXmlParser.parseModuleXml(ModuleXmlParser.java:287) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleXmlParser.parseModuleXml(ModuleXmlParser.java:242) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.LocalModuleLoader.parseModuleInfoFile(LocalModuleLoader.java:138) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.LocalModuleLoader.findModule(LocalModuleLoader.java:122) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleLoader.loadModuleLocal(ModuleLoader.java:275) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.ModuleLoader.preloadModule(ModuleLoader.java:222) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.LocalModuleLoader.preloadModule(LocalModuleLoader.java:94) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.Module.addPaths(Module.java:841) [jboss-modules.jar: 1.1.1.GA] at org.jboss.modules.Module.link(Module.java:1181) [jboss-modules.jar:1.1.1.GA] at org.jboss.modules.Module.getPaths(Module.java:1153) [jboss-modules.jar: 1.1.1.GA] at org.jboss.modules.Module.getPathsUnchecked(Module.java:1164) [jboss-modules.jar:1.1.1.GA] ... 19 more my processes: [root@ovirt ovirt-engine]# ps aux USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND root 1 0.0 0.0 19232 1488 ? Ss 12:01 0:01 /sbin/init root 2 0.0 0.0 0 0 ? S 12:01 0:00 [kthreadd] root 3 0.0 0.0 0 0 ? S 12:01 0:00 [migration/0] root 4 0.0 0.0 0 0 ? S 12:01 0:00 [ksoftirqd/0] root 5 0.0 0.0 0 0 ? S 12:01 0:00 [migration/0] root 6 0.0 0.0 0 0 ? S 12:01 0:00 [watchdog/0] root 7 0.0 0.0 0 0 ? S 12:01 0:00 [events/0] root 8 0.0 0.0 0 0 ? S 12:01 0:00 [cgroup] root 9 0.0 0.0 0 0 ? S 12:01 0:00 [khelper] root 10 0.0 0.0 0 0 ? S 12:01 0:00 [netns] root 11 0.0 0.0 0 0 ? S 12:01 0:00 [async/mgr] root 12 0.0 0.0 0 0 ? S 12:01 0:00 [pm] root 13 0.0 0.0 0 0 ? S 12:01 0:00 [sync_supers] root 14 0.0 0.0 0 0 ? S 12:01 0:00 [bdi-default] root 15 0.0 0.0 0 0 ? S 12:01 0:00 [kintegrityd/0] root 16 0.0 0.0 0 0 ? S 12:01 0:00 [kblockd/0] root 17 0.0 0.0 0 0 ? S 12:01 0:00 [kacpid] root 18 0.0 0.0 0 0 ? S 12:01 0:00 [kacpi_notify] root 19 0.0 0.0 0 0 ? S 12:01 0:00 [kacpi_hotplug] root 20 0.0 0.0 0 0 ? S 12:01 0:00 [ata_aux] root 21 0.0 0.0 0 0 ? S 12:01 0:00 [ata_sff/0] root 22 0.0 0.0 0 0 ? S 12:01 0:00 [ksuspend_usbd] root 23 0.0 0.0 0 0 ? S 12:01 0:00 [khubd] root 24 0.0 0.0 0 0 ? S 12:01 0:00 [kseriod] root 25 0.0 0.0 0 0 ? S 12:01 0:00 [md/0] root 26 0.0 0.0 0 0 ? S 12:01 0:00 [md_misc/0] root 27 0.0 0.0 0 0 ? S 12:01 0:00 [linkwatch] root 28 0.0 0.0 0 0 ? S 12:01 0:00 [khungtaskd] root 29 0.0 0.0 0 0 ? S 12:01 0:00 [kswapd0] root 30 0.0 0.0 0 0 ? SN 12:01 0:00 [ksmd] root 31 0.0 0.0 0 0 ? SN 12:01 0:00 [khugepaged] root 32 0.0 0.0 0 0 ? S 12:01 0:00 [aio/0] root 33 0.0 0.0 0 0 ? S 12:01 0:00 [crypto/0] root 38 0.0 0.0 0 0 ? S 12:01 0:00 [kthrotld/0] root 39 0.0 0.0 0 0 ? S 12:01 0:00 [pciehpd] root 41 0.0 0.0 0 0 ? S 12:02 0:00 [kpsmoused] root 42 0.0 0.0 0 0 ? S 12:02 0:00 [usbhid_resumer] root 72 0.0 0.0 0 0 ? S 12:02 0:00 [kstriped] root 133 0.0 0.0 0 0 ? S 12:02 0:00 [scsi_eh_0] root 134 0.0 0.0 0 0 ? S 12:02 0:00 [scsi_eh_1] root 195 0.0 0.0 0 0 ? S 12:02 0:00 [scsi_eh_2] root 196 0.0 0.0 0 0 ? S 12:02 0:00 [vmw_pvscsi_wq_2] root 272 0.0 0.0 0 0 ? S 12:02 0:00 [kdmflush] root 274 0.0 0.0 0 0 ? S 12:02 0:00 [kdmflush] root 291 0.0 0.0 0 0 ? S 12:02 0:00 [jbd2/dm-0-8] root 292 0.0 0.0 0 0 ? S 12:02 0:00 [ext4-dio-unwrit] root 369 0.0 0.0 11076 1164 ? S<s 12:02 0:00 /sbin/udevd -d root 533 0.0 0.0 0 0 ? S 12:02 0:00 [vmmemctl] root 656 0.0 0.0 0 0 ? S 12:02 0:00 [jbd2/sda1-8] root 657 0.0 0.0 0 0 ? S 12:02 0:00 [ext4-dio-unwrit] root 695 0.0 0.0 0 0 ? S 12:02 0:00 [kauditd] root 765 0.0 0.0 0 0 ? S 12:02 0:00 [flush-253:0] root 903 0.0 0.0 27640 792 ? S<sl 12:02 0:00 auditd root 919 0.0 0.0 249088 1580 ? Sl 12:02 0:00 /sbin/rsyslogd -i /var/run/syslogd.pid -c 5 root 956 0.0 0.0 0 0 ? S 12:02 0:00 [rpciod/0] rpcuser 962 0.0 0.0 23348 1328 ? Ss 12:02 0:00 rpc.statd -p 662 -o 2020 root 1081 0.0 0.0 66608 1228 ? Ss 12:02 0:00 /usr/sbin/sshd root 1203 0.0 0.0 81280 3400 ? Ss 12:02 0:00 /usr/libexec/postfix/master postfix 1211 0.0 0.0 81360 3372 ? S 12:02 0:00 pickup -l -t fifo -u postfix 1212 0.0 0.0 81532 3416 ? S 12:02 0:00 qmgr -l -t fifo -u root 1228 0.0 0.0 117300 1380 ? Ss 12:02 0:00 crond root 1232 0.0 0.0 100360 4060 ? Ss 12:02 0:00 sshd: root@pts/0 root 1245 0.0 0.0 4064 572 tty1 Ss+ 12:02 0:00 /sbin/mingetty /dev/tty1 root 1247 0.0 0.0 4064 568 tty2 Ss+ 12:02 0:00 /sbin/mingetty /dev/tty2 root 1249 0.0 0.0 4064 568 tty3 Ss+ 12:02 0:00 /sbin/mingetty /dev/tty3 root 1252 0.0 0.0 4064 572 tty4 Ss+ 12:02 0:00 /sbin/mingetty /dev/tty4 root 1254 0.0 0.0 12280 2580 ? S< 12:02 0:00 /sbin/udevd -d root 1255 0.0 0.0 12280 2576 ? S< 12:02 0:00 /sbin/udevd -d root 1256 0.0 0.0 4064 568 tty5 Ss+ 12:02 0:00 /sbin/mingetty /dev/tty5 root 1258 0.0 0.0 4064 568 tty6 Ss+ 12:02 0:00 /sbin/mingetty /dev/tty6 root 1263 0.0 0.0 108304 1852 pts/0 Ss+ 12:02 0:00 -bash root 1327 0.0 0.0 100360 4104 ? Ss 12:05 0:00 sshd: root@pts/1 root 1333 0.0 0.0 108304 1916 pts/1 Ss 12:05 0:00 -bash root 1574 0.0 0.0 100360 4088 ? Ss 12:08 0:00 sshd: root@pts/2 root 1578 0.0 0.0 108304 1896 pts/2 Ss+ 12:09 0:00 -bash rpc 6827 0.0 0.0 18976 872 ? Ss 12:11 0:00 rpcbind root 6923 0.0 0.0 21656 964 ? Ss 12:11 0:00 rpc.mountd -p 892 root 6928 0.0 0.0 0 0 ? S 12:11 0:00 [lockd] root 6929 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd4] root 6930 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd4_callbacks] root 6931 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6932 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6933 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6934 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6935 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6936 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6937 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6938 0.0 0.0 0 0 ? S 12:11 0:00 [nfsd] root 6961 0.0 0.0 25164 576 ? Ss 12:11 0:00 rpc.idmapd postgres 11279 0.0 0.1 217620 7044 ? S 12:19 0:00 /usr/bin/postmaster -p 5432 -D /var/lib/pgsql/data postgres 11281 0.0 0.0 179264 1480 ? Ss 12:19 0:00 postgres: logger process postgres 11283 0.0 0.0 217736 2860 ? Ss 12:19 0:00 postgres: writer process postgres 11284 0.0 0.0 217620 1676 ? Ss 12:19 0:00 postgres: wal writer process postgres 11285 0.0 0.0 217884 2060 ? Ss 12:19 0:00 postgres: autovacuum launcher process postgres 11286 0.0 0.0 179548 1792 ? Ss 12:19 0:00 postgres: stats collector process ovirt 12406 0.9 6.0 2164440 300836 ? Ssl 12:19 0:08 engine-service -server -XX:+TieredCompilation -Xms1g -Xmx1g -XX:PermSize=256m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Dsun.rmi.dgc.client.gcInterval=3600000 -D postgres 12464 0.0 0.0 218848 3872 ? Ss 12:19 0:00 postgres: engine engine 127.0.0.1(42069) idle root 12494 0.0 0.1 201080 5532 ? Ss 12:20 0:00 /usr/sbin/httpd apache 12496 0.0 0.0 201220 3868 ? S 12:20 0:00 /usr/sbin/httpd apache 12497 0.0 0.0 201228 4044 ? S 12:20 0:00 /usr/sbin/httpd apache 12498 0.0 0.0 201228 4044 ? S 12:20 0:00 /usr/sbin/httpd apache 12499 0.0 0.0 201228 4004 ? S 12:20 0:00 /usr/sbin/httpd apache 12500 0.0 0.0 201228 4408 ? S 12:20 0:00 /usr/sbin/httpd apache 12501 0.0 0.0 201228 4536 ? S 12:20 0:00 /usr/sbin/httpd apache 12502 0.0 0.0 201228 4516 ? S 12:20 0:00 /usr/sbin/httpd apache 12503 0.0 0.0 201080 3124 ? S 12:20 0:00 /usr/sbin/httpd root 12557 0.0 0.0 110232 1168 pts/1 R+ 12:34 0:00 ps aux my packages: [root@ovirt ovirt-engine]# rpm -qa | grep ovirt ovirt-engine-sdk-3.2.0.3-1.el6.centos.alt.noarch ovirt-image-uploader-3.1.0-26.el6.centos.alt.noarch ovirt-engine-userportal-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-restapi-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-config-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-tools-common-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-webadmin-portal-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-backend-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-log-collector-3.1.0-26.el6.centos.alt.noarch ovirt-iso-uploader-3.1.0-26.el6.centos.alt.noarch ovirt-engine-cli-3.2.0.6-1.el6.centos.alt.noarch ovirt-engine-jbossas711-1-3.el6.alt.x86_64 ovirt-engine-dbscripts-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-setup-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-notification-service-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-genericapi-3.1.0-3.26.3.el6.centos.alt.noarch ovirt-engine-3.1.0-3.26.3.el6.centos.alt.noarch What i am doing wrong? Thank you! Cheers, Mario

5 4

[Users] ovirt-report Forbidden access error
by Alessandro Bianchi 04 Feb '14

04 Feb '14

Hi all I installed ovirt-engine-reports-3.3.2-1.fc19.noarch using yum Now I have reports listed when right clicking on Vms but on any report i see this error: Forbidden You don't have permission to access /ovirt-engine-reports/flow.html on this server. This seems to be related to apache redirection but how to fix it? I have three files in conf.d ovirt-engine-root-redirect.conf z-ovirt-engine-proxy.conf z-ovirt-engine-reports-proxy.conf but can't figure how to fix them I applied no changes to these files Any hint? Thank you

3 19

[Users] CPU and Memory sharing
by Jaison peter 04 Feb '14

04 Feb '14

Hi all , I would like to know whether CPU or memory sharing among physical nodes are possible in ovirt . Suppose I have 3 physical nodes in my cluster with 24GB RAM and 8 cores each . Then one of my client needs a VM with 32GB RAM and 12 cores , that means vm need resources more than a physical server . So is that possible in ovirt cluster .? If it is not directly possible is they are any cloning & Load balancing methods like in amzon auto scaling ?

2 1

[Users] [QE] oVirt 3.4.0 beta status
by Sandro Bonazzola 04 Feb '14

04 Feb '14

Hi, oVirt 3.4.0 beta has been released and is actually on QA. We're going to tart composing oVirt 3.4.0 beta2 this Thursday 2014-02-06 09:00 UTC from 3.4 branches. This build will be used for a second Test Day scheduled for 2014-02-11. The bug tracker [1] shows the following bugs blocking the release: Whiteboard Bug ID Status Summary gluster 1038988 POST Gluster brick sync does not work when host has multiple interfaces gluster 1059606 POST Errors in rebalance and remove-brick status and sync integration 1054080 POST gracefully warn about unsupported upgrade from legacy releases integration 1058018 POST upgrade from 3.3 overwrites exports with acl None There are still 393 bugs [2] targeted to 3.4.0. Excluding node and documentation bugs we still have 238 bugs [3] targeted to 3.4.0. Please review them as soon as possible. Maintainers: - Please remember to rebuild your packages before 2014-02-06 09:00 UTC if you want them to be included in 3.4.0 beta. - Please add the bugs to the tracker if you think that 3.4.0 should not be released without them fixed. - Please provide ETA on blockers bugs - Please update the target to 3.4.1 or any next release for bugs that won't be in 3.4.0: it will ease gathering the blocking bugs for next releases. - Please fill release notes, the page has been created here [4] - Please update http://www.ovirt.org/OVirt_3.4_TestDay before 2014-02-11 For those who want to help testing the bugs, I suggest to add yourself as QA contact for the bug. Please also be prepared for upcoming oVirt 3.4.0 Test Day on 2014-02-11! Thanks to all people already testing 3.4.0 beta! [1] https://bugzilla.redhat.com/1024889 [2] http://red.ht/1eIRZXM [3] http://red.ht/1auBU3r [4] http://www.ovirt.org/OVirt_3.4.0_release_notes -- Sandro Bonazzola Better technology. Faster innovation. Powered by community collaboration. See how it works at redhat.com

2 2

[Users] Migration failed (previous migrations succeded)
by Markus Stockhausen 04 Feb '14

04 Feb '14

This is a multi-part message in MIME format. ------=_NextPartTM-000-16e476a9-dc0a-459b-91a5-33c52e66e68f Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Hello,=0A= =0A= we did some migration tests this day and all of a sudden the migration=0A= failed. That particular VM was moved around several times that day without= =0A= any problems. During the migration the VM was running a download.=0A= =0A= The logs are attached. If you need more, do not hesitate to ask.=0A= =0A= Thanks in advance.=0A= =0A= Markus=0A= =0A= **************************=0A= web log:=0A= =0A= 2014-Jan-30, 16:17 Migration failed due to Error: Migration not in progress= (VM: Win7x64_Master, Source: colovn02, Destination: colovn04).=0A= 2014-Jan-30, 16:11 Migration started (VM: Win7x64_Master, Source: colovn02,= Destination: colovn04, User: hil1).=0A= 2014-Jan-30, 16:10 Migration completed (VM: Win7x64_Master, Source: colovn0= 4, Destination: colovn02, Duration: 52 sec).=0A= 2014-Jan-30, 16:05 Migration started (VM: Win7x64_Master, Source: colovn04,= Destination: colovn02, User: hil1).=0A= 2014-Jan-30, 16:04 Migration completed (VM: Win7x64_Master, Source: colovn0= 3, Destination: colovn04, Duration: 24 sec).=0A= 2014-Jan-30, 16:01 Migration started (VM: Win7x64_Master, Source: colovn03,= Destination: colovn04, User: hil1).=0A= =0A= **************************=0A= Engine=0A= =0A= 2014-01-30 16:17:31,871 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-97) RefreshVmList vm id ce64f528-9= 981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in= the refresh until migration is done=0A= 2014-01-30 16:17:34,955 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-96) RefreshVmList vm id ce64f528-9= 981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in= the refresh until migration is done=0A= 2014-01-30 16:17:38,067 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-2) RefreshVmList vm id ce64f528-99= 81-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in = the refresh until migration is done=0A= 2014-01-30 16:17:41,147 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-100) RefreshVmList vm id ce64f528-= 9981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it i= n the refresh until migration is done=0A= 2014-01-30 16:17:44,268 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-88) RefreshVmList vm id ce64f528-9= 981-4ec6-a172-9d70a00a34cd status =3D Paused on vds colovn04 ignoring it in= the refresh until migration is done=0A= 2014-01-30 16:17:46,440 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-13) VM Win7x64_Master ce64f528-998= 1-4ec6-a172-9d70a00a34cd moved from MigratingFrom --> Up=0A= 2014-01-30 16:17:46,444 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-13) Adding VM ce64f528-9981-4ec6-a= 172-9d70a00a34cd to re-run list=0A= 2014-01-30 16:17:46,456 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRun= TimeInfo] (DefaultQuartzScheduler_Worker-13) Rerun vm ce64f528-9981-4ec6-a1= 72-9d70a00a34cd. Called from vds colovn02=0A= 2014-01-30 16:17:46,475 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) START, MigrateStatusVDSCommand(Ho= stName =3D colovn02, HostId =3D 1303e86e-cd91-406b-8a27-e75ef0a9defb, vmId= =3Dce64f528-9981-4ec6-a172-9d70a00a34cd), log id: 91bccfb=0A= 2014-01-30 16:17:46,485 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Failed in MigrateStatusVDS method= =0A= 2014-01-30 16:17:46,488 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Error code MIGRATION_CANCEL_ERROR= and error message VDSGenericException: VDSErrorException: Failed to Migrat= eStatusVDS, error =3D Migration canceled=0A= 2014-01-30 16:17:46,492 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Command org.ovirt.engine.core.vds= broker.vdsbroker.MigrateStatusVDSCommand return value=0A= StatusOnlyReturnForXmlRpc [mStatus=3DStatusForXmlRpc [mCode=3D47, mMessage= =3DMigration canceled]]=0A= 2014-01-30 16:17:46,495 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) HostName =3D colovn02=0A= 2014-01-30 16:17:46,508 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) Command MigrateStatusVDS executio= n failed. Exception: VDSErrorException: VDSGenericException: VDSErrorExcept= ion: Failed to MigrateStatusVDS, error =3D Migration canceled=0A= 2014-01-30 16:17:46,511 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.Mi= grateStatusVDSCommand] (pool-6-thread-48) FINISH, MigrateStatusVDSCommand, = log id: 91bccfb=0A= 2014-01-30 16:17:46,522 INFO [org.ovirt.engine.core.dal.dbbroker.auditlogh= andling.AuditLogDirector] (pool-6-thread-48) Correlation ID: 71aa9786, Job = ID: 4f805590-135a-49a6-871a-91389ae99d9a, Call Stack: null, Custom Event ID= : -1, Message: Migration failed due to Error: Migration not in progress (VM= : Win7x64_Master, Source: colovn02, Destination: colovn04).=0A= 2014-01-30 16:18:27,016 INFO [org.ovirt.engine.core.bll.MigrateVmToServerC= ommand] (ajp--127.0.0.1-8702-2) [5fed7321] Failed to Acquire Lock to object= EngineLock [exclusiveLocks=3D key: ce64f528-9981-4ec6-a172-9d70a00a34cd va= lue: VM=0A= , sharedLocks=3D ]=0A= 2014-01-30 16:18:27,020 WARN [org.ovirt.engine.core.bll.MigrateVmToServerC= ommand] (ajp--127.0.0.1-8702-2) [5fed7321] CanDoAction of action MigrateVmT= oServer failed. Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAIL= ED_VM_IS_BEING_MIGRATED,$VmName Win7x64_Master=0A= 2014-01-30 16:18:56,318 INFO [org.ovirt.engine.core.bll.MigrateVmToServerC= ommand] (ajp--127.0.0.1-8702-12) [4b6f62e9] Failed to Acquire Lock to objec= t EngineLock [exclusiveLocks=3D key: ce64f528-9981-4ec6-a172-9d70a00a34cd v= alue: VM=0A= =0A= **************************=0A= vdsm_source:=0A= =0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::1168::TaskManager.Task= ::(prepare) Task=3D`d313ee92-9094-49ad-8850-fbb6df383a22`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000176962', 'lastCheck': '1= .8', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.000154703', 'lastCheck': '8.0', 'code': 0, 'valid':= True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.= 000147093', 'lastCheck': '7.5', 'code': 0, 'valid': True, 'version': 0}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000179083', 'lastCheck':= '7.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.000224103', 'lastCheck': '6.3', 'code': 0, 'vali= d': True, 'version': 3}}=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::579::TaskManager.Task:= :(_updateState) Task=3D`d313ee92-9094-49ad-8850-fbb6df383a22`::moving from = state preparing -> state finished=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-290096::DEBUG::2014-01-30 16:17:04,874::task::974::TaskManager.Task:= :(_decref) Task=3D`d313ee92-9094-49ad-8850-fbb6df383a22`::ref 0 aborting Fa= lse=0A= Thread-289929::WARNING::2014-01-30 16:17:05,585::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (24MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:05,585::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 360 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:06,907::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:06,913::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000192548 s, 2.9 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:07,394::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:07,400::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000213713 s, 1.7 MB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:07,771::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:07,778::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000190935 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:08,586::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:08,593::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000184154 s, 3.0 MB/s\n'; <rc> =3D 0=0A= Thread-25::DEBUG::2014-01-30 16:17:13,044::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:13,050::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.00017907 s, 3.6 MB/s\n'; <rc> =3D 0=0A= Thread-289929::WARNING::2014-01-30 16:17:15,586::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (16MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:15,587::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 370 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:16,923::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:16,929::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000248981 s, 2.2 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:17,412::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:17,418::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000252188 s, 1.4 MB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:17,789::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:17,796::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000203099 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:18,604::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:18,611::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000177334 s, 3.1 MB/s\n'; <rc> =3D 0=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,057::task::579::TaskManager.Task:= :(_updateState) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::moving from = state init -> state preparing=0A= Thread-290102::INFO::2014-01-30 16:17:20,057::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-290102::INFO::2014-01-30 16:17:20,058::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.00017907', 'lastCheck': '7.0', 'code': 0, 'v= alid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'delay= ': '0.000248981', 'lastCheck': '3.1', 'code': 0, 'valid': True, 'version': = 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000252188', 'lastC= heck': '2.6', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-= b36f-f39f16d3974f': {'delay': '0.000203099', 'lastCheck': '2.3', 'code': 0,= 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'de= lay': '0.000177334', 'lastCheck': '1.4', 'code': 0, 'valid': True, 'version= ': 3}}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::task::1168::TaskManager.Task= ::(prepare) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.00017907', 'lastCheck': '7.= 0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a= 9e58545': {'delay': '0.000248981', 'lastCheck': '3.1', 'code': 0, 'valid': = True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.0= 00252188', 'lastCheck': '2.6', 'code': 0, 'valid': True, 'version': 0}, '63= 041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000203099', 'lastCheck': = '2.3', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-73= 2789dd18d4': {'delay': '0.000177334', 'lastCheck': '1.4', 'code': 0, 'valid= ': True, 'version': 3}}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::task::579::TaskManager.Task:= :(_updateState) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::moving from = state preparing -> state finished=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,058::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-290102::DEBUG::2014-01-30 16:17:20,059::task::974::TaskManager.Task:= :(_decref) Task=3D`0d381417-48c8-4035-99e5-01f34f55f98c`::ref 0 aborting Fa= lse=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,908::task::579::TaskManager.Task:= :(_updateState) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::moving from = state init -> state preparing=0A= Thread-289906::INFO::2014-01-30 16:17:22,909::logUtils::44::dispatcher::(wr= apper) Run and protect: getVolumeSize(sdUUID=3D'965ca3b6-4f9c-4e81-b6e8-5ed= 4a9e58545', spUUID=3D'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=3D'1b2= 3ac73-0748-49cd-94b6-11555e35be81', volUUID=3D'5156a43b-c9dc-40fa-a9b7-a35b= 7f22f0eb', options=3DNone)=0A= Thread-289906::INFO::2014-01-30 16:17:22,911::logUtils::47::dispatcher::(wr= apper) Run and protect: getVolumeSize, Return response: {'truesize': '17700= 114432', 'apparentsize': '21474836480'}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,911::task::1168::TaskManager.Task= ::(prepare) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::finished: {'true= size': '17700114432', 'apparentsize': '21474836480'}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,911::task::579::TaskManager.Task:= :(_updateState) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::moving from = state preparing -> state finished=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,911::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,912::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-289906::DEBUG::2014-01-30 16:17:22,912::task::974::TaskManager.Task:= :(_decref) Task=3D`308ddd49-b5c0-43a5-93fc-ccfd6220eb28`::ref 0 aborting Fa= lse=0A= Thread-25::DEBUG::2014-01-30 16:17:23,063::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:23,069::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000189592 s, 3.4 MB/s\n'; <rc> =3D 0=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:23,109::vmChannels::91::vds::= (_handle_timeouts) Timeout on fileno 105.=0A= Thread-289929::WARNING::2014-01-30 16:17:25,588::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (15MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:25,588::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 380 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:26,940::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:26,947::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.00019559 s, 2.8 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:27,430::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:27,439::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.00317489 s, 112 kB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:27,808::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:27,815::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000189549 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:28,621::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:28,632::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.00469703 s, 119 kB/s\n'; <rc> =3D 0=0A= Thread-25::DEBUG::2014-01-30 16:17:33,081::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:33,087::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000191272 s, 3.4 MB/s\n'; <rc> =3D 0=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,257::task::579::TaskManager.Task:= :(_updateState) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::moving from = state init -> state preparing=0A= Thread-290108::INFO::2014-01-30 16:17:35,257::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-290108::INFO::2014-01-30 16:17:35,257::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000191272', 'lastCheck': '2.2', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.00019559', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': = 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00317489', 'lastCh= eck': '7.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-b= 36f-f39f16d3974f': {'delay': '0.000189549', 'lastCheck': '7.4', 'code': 0, = 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'del= ay': '0.00469703', 'lastCheck': '6.6', 'code': 0, 'valid': True, 'version':= 3}}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::1168::TaskManager.Task= ::(prepare) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000191272', 'lastCheck': '2= .2', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.00019559', 'lastCheck': '8.3', 'code': 0, 'valid': = True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.0= 0317489', 'lastCheck': '7.8', 'code': 0, 'valid': True, 'version': 0}, '630= 41fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000189549', 'lastCheck': '= 7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732= 789dd18d4': {'delay': '0.00469703', 'lastCheck': '6.6', 'code': 0, 'valid':= True, 'version': 3}}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::579::TaskManager.Task:= :(_updateState) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::moving from = state preparing -> state finished=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-290108::DEBUG::2014-01-30 16:17:35,258::task::974::TaskManager.Task:= :(_decref) Task=3D`c598fcf4-774b-4420-af70-090d43cd58b5`::ref 0 aborting Fa= lse=0A= Thread-289929::WARNING::2014-01-30 16:17:35,590::vm::800::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration stalling: dataRemainin= g (33MiB) > smallest_dataRemaining (9MiB). Refer to RHBZ#919201.=0A= Thread-289929::INFO::2014-01-30 16:17:35,590::vm::812::vm.Vm::(run) vmId=3D= `ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration Progress: 390 seconds ela= psed, 99% of data processed, 99% of mem processed=0A= Thread-26::DEBUG::2014-01-30 16:17:36,959::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:36,966::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000212972 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-27::DEBUG::2014-01-30 16:17:37,450::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:37,457::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000199826 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-33::DEBUG::2014-01-30 16:17:37,826::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:37,833::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000200537 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:38,644::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:38,650::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000206259 s, 2.7 MB/s\n'; <rc> =3D 0=0A= Thread-25::DEBUG::2014-01-30 16:17:43,099::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-25::DEBUG::2014-01-30 16:17:43,105::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000187228 s, 3.4 MB/s\n'; <rc> =3D 0=0A= Thread-289929::WARNING::2014-01-30 16:17:45,592::vm::789::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Migration is stuck: Hasn't progr= essed in 300.055635929 seconds. Aborting.=0A= Thread-289929::DEBUG::2014-01-30 16:17:45,594::vm::815::vm.Vm::(stop) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::stopping migration monitor threa= d=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:45,918::vm::4840::vm.Vm::(_onLibv= irtLifecycleEvent) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::event Res= umed detail 1 opaque None=0A= Thread-289927::DEBUG::2014-01-30 16:17:45,920::libvirtconnection::108::libv= irtconnection::(wrapper) Unknown libvirterror: ecode: 78 edom: 10 level: 2 = message: Operation abgebrochen: Migrations-Job: abgebrochen durch Client=0A= Thread-289927::DEBUG::2014-01-30 16:17:45,920::vm::745::vm.Vm::(cancel) vmI= d=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::canceling migration downtime th= read=0A= Thread-289927::DEBUG::2014-01-30 16:17:45,920::vm::815::vm.Vm::(stop) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::stopping migration monitor threa= d=0A= Thread-289927::ERROR::2014-01-30 16:17:45,920::vm::238::vm.Vm::(_recover) v= mId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Operation abgebrochen: Migrat= ions-Job: abgebrochen durch Client=0A= Thread-289927::ERROR::2014-01-30 16:17:45,949::vm::337::vm.Vm::(run) vmId= =3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Failed to migrate=0A= Traceback (most recent call last):=0A= File "/usr/share/vdsm/vm.py", line 323, in run=0A= self._startUnderlyingMigration()=0A= File "/usr/share/vdsm/vm.py", line 400, in _startUnderlyingMigration=0A= None, maxBandwidth)=0A= File "/usr/share/vdsm/vm.py", line 838, in f=0A= ret =3D attr(*args, **kwargs)=0A= File "/usr/lib64/python2.7/site-packages/vdsm/libvirtconnection.py", line= 76, in wrapper=0A= ret =3D f(*args, **kwargs)=0A= File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1274, in migra= teToURI2=0A= if ret =3D=3D -1: raise libvirtError ('virDomainMigrateToURI2() failed'= , dom=3Dself)=0A= libvirtError: Operation abgebrochen: Migrations-Job: abgebrochen durch Clie= nt=0A= Thread-26::DEBUG::2014-01-30 16:17:46,976::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-26::DEBUG::2014-01-30 16:17:46,982::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000163843 s, 3.4 MB/s\n'; <rc> =3D 0=0A= Thread-290114::DEBUG::2014-01-30 16:17:47,444::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-290114::DEBUG::2014-01-30 16:17:47,445::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiE= nable': 'true', 'guestFQDN': '', 'pid': '14467', 'displayIp': '192.168.11.4= 2', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900'= , 'timeOffset': '0', 'hash': '3172497814970917300', 'balloonInfo': {'balloo= n_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152', '= balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {= u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '605', 'rxErrors': = '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '1.4', 'txErrors': '0', '= state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f528-9= 981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '35.99', 'dis= ks': {u'hdc': {'readLatency': '0', 'apparentsize': '0', 'writeLatency': '0'= , 'flushLatency': '0', 'readRate': '0.00', 'truesize': '0', 'writeRate': '0= .00'}, u'sda': {'readLatency': '0', 'apparentsize': '21474836480', 'writeLa= tency': '2110228', 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81', 'flus= hLatency': '0', 'readRate': '0.00', 'truesize': '17700114432', 'writeRate':= '1640924.26'}}, 'monitorResponse': '0', 'statsAge': '0.49', 'elapsedTime':= '1235', 'vmType': 'kvm', 'cpuSys': '35.99', 'appsList': [], 'guestIPs': ''= }]}=0A= Thread-27::DEBUG::2014-01-30 16:17:47,468::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-27::DEBUG::2014-01-30 16:17:47,474::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000176178 s, 2.0 MB/s\n'; <rc> =3D 0=0A= Thread-290115::DEBUG::2014-01-30 16:17:47,493::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetMigrationStatus with ('ce64f528-998= 1-4ec6-a172-9d70a00a34cd',) {}=0A= Thread-290115::DEBUG::2014-01-30 16:17:47,493::BindingXMLRPC::981::vds::(wr= apper) return vmGetMigrationStatus with {'status': {'message': 'Migration c= anceled', 'code': 47}, 'progress': 99}=0A= Thread-33::DEBUG::2014-01-30 16:17:47,845::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-33::DEBUG::2014-01-30 16:17:47,851::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000191543 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-38::DEBUG::2014-01-30 16:17:48,662::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-38::DEBUG::2014-01-30 16:17:48,668::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000225105 s, 2.5 MB/s\n'; <rc> =3D 0=0A= Thread-290116::DEBUG::2014-01-30 16:17:50,490::task::579::TaskManager.Task:= :(_updateState) Task=3D`cd241aee-e845-4143-bfe3-01383c65e90e`::moving from = state init -> state preparing=0A= Thread-290116::INFO::2014-01-30 16:17:50,490::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= =0A= **************************=0A= vdsm_target:=0A= =0A= Thread-285228::DEBUG::2014-01-30 16:17:07,460::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285228::DEBUG::2014-01-30 16:17:07,460::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285228::DEBUG::2014-01-30 16:17:07,461::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '867', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.44', 'elap= sedTime': '1212', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-40::DEBUG::2014-01-30 16:17:07,811::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:07,818::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000160605 s, 4.0 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:08,363::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:08,369::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000144136 s, 2.5 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:17:10,080::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:10,086::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000213518 s, 1.7 MB/s\n'; <rc> =3D 0=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,569::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,570::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285230::DEBUG::2014-01-30 16:17:10,571::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '887', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '1.55', 'elap= sedTime': '1215', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-41::DEBUG::2014-01-30 16:17:11,570::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:11,577::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000211434 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,656::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,656::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,657::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285232::DEBUG::2014-01-30 16:17:13,658::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '887', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.38', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.63', 'elap= sedTime': '1218', 'vmType': 'kvm', 'cpuSys': '2.07', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-52::DEBUG::2014-01-30 16:17:14,494::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:14,501::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000228157 s, 2.4 MB/s\n'; <rc> =3D 0=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,719::task::579::TaskManager.Task:= :(_updateState) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::moving from = state init -> state preparing=0A= Thread-285233::INFO::2014-01-30 16:17:16,720::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285233::INFO::2014-01-30 16:17:16,720::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000160605', 'lastCheck': '8.9', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000211434', 'lastCheck': '5.1', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000144136', 'last= Check': '8.3', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44= -b36f-f39f16d3974f': {'delay': '0.000213518', 'lastCheck': '6.6', 'code': 0= , 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'d= elay': '0.000228157', 'lastCheck': '2.2', 'code': 0, 'valid': True, 'versio= n': 3}}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,720::task::1168::TaskManager.Task= ::(prepare) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000160605', 'lastCheck': '8= .9', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.000211434', 'lastCheck': '5.1', 'code': 0, 'valid':= True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.= 000144136', 'lastCheck': '8.3', 'code': 0, 'valid': True, 'version': 0}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000213518', 'lastCheck':= '6.6', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.000228157', 'lastCheck': '2.2', 'code': 0, 'vali= d': True, 'version': 3}}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,720::task::579::TaskManager.Task:= :(_updateState) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::moving from = state preparing -> state finished=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,720::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,721::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285233::DEBUG::2014-01-30 16:17:16,721::task::974::TaskManager.Task:= :(_decref) Task=3D`3b433b6a-d9ed-4edc-adcc-b9994ba7877a`::ref 0 aborting Fa= lse=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285234::DEBUG::2014-01-30 16:17:16,733::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-40::DEBUG::2014-01-30 16:17:17,821::domainMonitor::182::Storage.Doma= inMonitorThread::(_monitorDomain) Refreshing domain 2c51d320-88ce-4f23-8215= -e15f55f66906=0A= Thread-40::DEBUG::2014-01-30 16:17:17,834::fileSD::154::Storage.StorageDoma= in::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_v= ar_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906=0A= Thread-40::DEBUG::2014-01-30 16:17:17,835::persistentDict::192::Storage.Per= sistentDict::(__init__) Created a persistent dict with FileMetadataRW backe= nd=0A= Thread-40::DEBUG::2014-01-30 16:17:17,842::persistentDict::234::Storage.Per= sistentDict::(refresh) read lines (FileMetadataRW)=3D['CLASS=3DData', 'DESC= RIPTION=3Dcolnas03_IB', 'IOOPTIMEOUTSEC=3D10', 'LEASERETRIES=3D3', 'LEASETI= MESEC=3D60', 'LOCKPOLICY=3D', 'LOCKRENEWALINTERVALSEC=3D5', 'MASTER_VERSION= =3D3', 'POOL_DESCRIPTION=3DCollogia', 'POOL_DOMAINS=3D272ec473-6041-42ee-bd= 1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320= -88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Ac= tive,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=3D2', 'POOL= _SPM_LVER=3D33', 'POOL_UUID=3D94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOT= E_PATH=3D10.10.30.253:/var/nas3/OVirtIB', 'ROLE=3DMaster', 'SDUUID=3D2c51d3= 20-88ce-4f23-8215-e15f55f66906', 'TYPE=3DNFS', 'VERSION=3D3', '_SHA_CKSUM= =3D75ca15b219476f472d87a8c375650d35eabb8d16']=0A= Thread-40::DEBUG::2014-01-30 16:17:17,843::fileSD::572::Storage.StorageDoma= in::(imageGarbageCollector) Removing remnants of deleted images []=0A= Thread-40::INFO::2014-01-30 16:17:17,844::sd::374::Storage.StorageDomain::(= _registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15= f55f66906_imageNS already registered=0A= Thread-40::INFO::2014-01-30 16:17:17,844::sd::382::Storage.StorageDomain::(= _registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15= f55f66906_volumeNS already registered=0A= Thread-40::DEBUG::2014-01-30 16:17:17,854::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:17,860::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000216469 s, 3.0 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:18,381::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:18,387::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000243463 s, 1.5 MB/s\n'; <rc> =3D 0=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,814::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,815::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285241::DEBUG::2014-01-30 16:17:19,816::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '909', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.78', 'elap= sedTime': '1224', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:20,026::vmChannels::91::vds::= (_handle_timeouts) Timeout on fileno 98.=0A= Thread-47::DEBUG::2014-01-30 16:17:20,096::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:20,103::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.00022031 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:17:21,589::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:21,596::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.0002126 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,928::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,929::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285243::DEBUG::2014-01-30 16:17:22,930::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '909', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '1.88', 'elap= sedTime': '1227', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-52::DEBUG::2014-01-30 16:17:24,512::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:24,519::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000195213 s, 2.9 MB/s\n'; <rc> =3D 0=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,006::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,006::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,006::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,007::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,007::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285245::DEBUG::2014-01-30 16:17:26,008::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '929', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.95', 'elap= sedTime': '1230', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= Thread-40::DEBUG::2014-01-30 16:17:27,875::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:27,881::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000195778 s, 3.3 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:28,399::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:28,406::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.00021875 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.2]::call vmGetStats with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc stats not avail= able=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::645::vm.Vm::(_getDiskSta= ts) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda stats not avail= able=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,119::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk hdc latency not a= vailable=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,120::vm::684::vm.Vm::(_getDiskLat= ency) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Disk sda latency not a= vailable=0A= Thread-285247::DEBUG::2014-01-30 16:17:29,121::BindingXMLRPC::981::vds::(wr= apper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 's= tatsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'a= cpiEnable': 'true', 'guestFQDN': '', 'pid': '7671', 'displayIp': '192.168.1= 1.44', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'59= 00', 'timeOffset': '0', 'hash': '7219603903902024642', 'balloonInfo': {'bal= loon_max': '2097152', 'balloon_target': '2097152', 'balloon_cur': '2097152'= , 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network'= : {u'vnet0': {'macAddr': '00:1a:4a:ee:d3:4a', 'rxDropped': '946', 'rxErrors= ': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0'= , 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'ce64f52= 8-9981-4ec6-a172-9d70a00a34cd', 'displayType': 'qxl', 'cpuUser': '0.44', 'd= isks': {u'hdc': {'truesize': '0', 'apparentsize': '0'}, u'sda': {'truesize'= : '17700114432', 'apparentsize': '21474836480', 'imageID': '1b23ac73-0748-4= 9cd-94b6-11555e35be81'}}, 'monitorResponse': '0', 'statsAge': '0.07', 'elap= sedTime': '1233', 'vmType': 'kvm', 'cpuSys': '1.93', 'appsList': [], 'guest= IPs': ''}]}=0A= VM Channels Listener::ERROR::2014-01-30 16:17:29,729::vmChannels::53::vds::= (_handle_event) Received 00000019 on fileno 98=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:29,729::vmChannels::128::vds:= :(_handle_unconnected) Trying to connect fileno 98.=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:29,730::guestIF::147::vm.Vm::= (_connect) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Attempting connec= tion to /var/lib/libvirt/qemu/channels/ce64f528-9981-4ec6-a172-9d70a00a34cd= .com.redhat.rhevm.vdsm=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:29,730::guestIF::158::vm.Vm::= (_connect) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Failed to connect= to /var/lib/libvirt/qemu/channels/ce64f528-9981-4ec6-a172-9d70a00a34cd.com= .redhat.rhevm.vdsm with 111=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,770::vm::4840::vm.Vm::(_onLibv= irtLifecycleEvent) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::event Sto= pped detail 5 opaque None=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,770::vm::2166::vm.Vm::(_onQemuD= eath) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::underlying process dis= connected=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,770::vm::4320::vm.Vm::(releaseV= m) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Release VM resources=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,775::libvirtconnection::108::l= ibvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level:= 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID = 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,776::sampling::292::vm.Vm::(st= op) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stop statistics collecti= on=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,776::vmChannels::205::vds::(un= register) Delete fileno 98 from listener.=0A= Thread-285161::DEBUG::2014-01-30 16:17:29,776::sampling::323::vm.Vm::(run) = vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stats thread finished=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,777::libvirtconnection::108::l= ibvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level:= 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID = 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)=0A= libvirtEventLoop::WARNING::2014-01-30 16:17:29,777::clientIF::362::vds::(te= ardownVolumePath) Drive is not a vdsm image: VOLWM_CHUNK_MB:1024 VOLWM_CHUN= K_REPLICATE_MULT:2 VOLWM_FREE_PCT:50 _blockDev:False _checkIoTuneCategories= :<bound method Drive._checkIoTuneCategories of <vm.Drive object at 0x7f3560= 03bb90>> _customize:<bound method Drive._customize of <vm.Drive object at 0= x7f356003bb90>> _deviceXML:<disk device=3D"cdrom" type=3D"file">=0A= <driver name=3D"qemu" type=3D"raw"/>=0A= <source startupPolicy=3D"optional"/>=0A= <target bus=3D"ide" dev=3D"hdc"/>=0A= <readonly/>=0A= <serial/>=0A= <alias name=3D"ide0-1-0"/>=0A= <address bus=3D"1" controller=3D"0" target=3D"0" type=3D"drive" unit= =3D"0"/>=0A= </disk> _makeName:<bound method Drive._makeName of <vm.Drive object at = 0x7f356003bb90>> _setExtSharedState:<bound method Drive._setExtSharedState = of <vm.Drive object at 0x7f356003bb90>> _validateIoTuneParams:<bound method= Drive._validateIoTuneParams of <vm.Drive object at 0x7f356003bb90>> addres= s:{u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u= 'unit': u'0'} alias:ide0-1-0 apparentsize:0 blockDev:False cache:none conf:= {'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus':= '', 'pid': '7671', 'memGuaranteedSize': 2048, 'transparentHugePages': 'tru= e', 'displaySecurePort': u'5900', 'timeOffset': '0', 'cpuType': 'Nehalem', = 'smp': '2', 'custom': {'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3= 073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd= 3e9device_50fb5c9c-d9b3-4422-b216-3ff71ac6d774device_bb8234b4-44d4-4086-906= c-744b572ddbd9': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d70a00a34cd, de= viceId=3Dbb8234b4-44d4-4086-906c-744b572ddbd9, device=3Dspicevmc, type=3DCH= ANNEL, bootOrder=3D0, specParams=3D{}, address=3D{port=3D3, bus=3D0, contro= ller=3D0, type=3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, readOnly= =3Dfalse, deviceAlias=3Dchannel2, customProperties=3D{}, snapshotId=3Dnull}= ', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3073f208-c700-4b39-99= f1-56c33e884c78': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d70a00a34cd, d= eviceId=3D3073f208-c700-4b39-99f1-56c33e884c78, device=3Dvirtio-serial, typ= e=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, doma= in=3D0x0000, type=3Dpci, slot=3D0x06, function=3D0x0}, managed=3Dfalse, plu= gged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dvirtio-serial0, customProperti= es=3D{}, snapshotId=3Dnull}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2d= evice_3073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-62= 10ecabd3e9device_50fb5c9c-d9b3-4422-b216-3ff71ac6d774': 'VmDevice {vmId=3Dc= e64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=3D50fb5c9c-d9b3-4422-b216-3ff= 71ac6d774, device=3Dunix, type=3DCHANNEL, bootOrder=3D0, specParams=3D{}, a= ddress=3D{port=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial}, managed= =3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dchannel1, customP= roperties=3D{}, snapshotId=3Dnull}', 'sap_agent': 'false', 'device_aff6efaa= -b33b-4385-a311-0c770cf56cf2': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d= 70a00a34cd, deviceId=3Daff6efaa-b33b-4385-a311-0c770cf56cf2, device=3Dide, = type=3DCONTROLLER, bootOrder=3D0, specParams=3D{}, address=3D{bus=3D0x00, d= omain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1}, managed=3Dfalse, = plugged=3Dtrue, readOnly=3Dfalse, deviceAlias=3Dide0, customProperties=3D{}= , snapshotId=3Dnull}', 'device_aff6efaa-b33b-4385-a311-0c770cf56cf2device_3= 073f208-c700-4b39-99f1-56c33e884c78device_0c7f4f0b-98d4-4a1a-934e-6210ecabd= 3e9': 'VmDevice {vmId=3Dce64f528-9981-4ec6-a172-9d70a00a34cd, deviceId=3D0c= 7f4f0b-98d4-4a1a-934e-6210ecabd3e9, device=3Dunix, type=3DCHANNEL, bootOrde= r=3D0, specParams=3D{}, address=3D{port=3D1, bus=3D0, controller=3D0, type= =3Dvirtio-serial}, managed=3Dfalse, plugged=3Dtrue, readOnly=3Dfalse, devic= eAlias=3Dchannel0, customProperties=3D{}, snapshotId=3Dnull}'}, 'vmType': '= kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 2048, 'vmName': 'Win7x64= _Master', 'nice': '0', 'clientIp': '', 'vmId': 'ce64f528-9981-4ec6-a172-9d7= 0a00a34cd', 'displayIp': '192.168.11.44', 'keyboardLayout': 'de', 'displayP= ort': '-1', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinpu= ts,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'r= tl8139,pv', 'smpCoresPerSocket': '2', 'kvmEnable': 'true', 'displayNetwork'= : 'ovirtmgmt', 'devices': [{'device': 'unix', 'alias': 'channel0', 'type': = 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-seria= l', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel= ', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'por= t': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', '= address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': = '3'}}, {'specParams': {}, 'alias': u'scsi0', 'deviceId': '294da3e7-42c8-487= 2-918c-cafa13cec438', 'address': {u'slot': u'0x04', u'bus': u'0x00', u'doma= in': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'device': 'scsi', 'm= odel': 'virtio-scsi', 'type': 'controller'}, {'device': 'usb', 'alias': u'u= sb0', 'type': 'controller', 'address': {u'slot': u'0x01', u'bus': u'0x00', = u'domain': u'0x0000', u'type': u'pci', u'function': u'0x2'}}, {'device': 'i= de', 'alias': u'ide0', 'type': 'controller', 'address': {u'slot': u'0x01', = u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x1'= }}, {'device': 'virtio-serial', 'alias': u'virtio-serial0', 'type': 'contro= ller', 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000',= u'type': u'pci', u'function': u'0x0'}}, {'specParams': {'vram': '32768', '= heads': '1'}, 'alias': 'video0', 'deviceId': '14faa0f4-9b5f-4997-bcdb-889d4= 9672122', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 't= ype': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicMo= del': 'pv', 'macAddr': '00:1a:4a:ee:d3:4a', 'linkActive': True, 'network': = 'ovirtmgmt', 'specParams': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': u= 'net0', 'deviceId': '0109b881-8911-40ef-9e19-ad0d8daf5917', 'address': {u's= lot': u'0x03', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'fu= nction': u'0x0'}, 'device': 'bridge', 'type': 'interface', 'name': u'vnet0'= }, {'index': '2', 'iface': 'ide', 'name': u'hdc', 'alias': u'ide0-1-0', 'sp= ecParams': {'path': ''}, 'readonly': 'True', 'deviceId': '6aad5e48-613b-48d= b-838a-fc923fb0cdd7', 'address': {u'bus': u'1', u'controller': u'0', u'type= ': u'drive', u'target': u'0', u'unit': u'0'}, 'device': 'cdrom', 'shared': = 'false', 'path': '', 'type': 'disk'}, {'address': {u'bus': u'0', u'controll= er': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'reqsize': '= 0', 'index': 0, 'iface': 'scsi', 'apparentsize': '21474836480', 'specParams= ': {}, 'imageID': '1b23ac73-0748-49cd-94b6-11555e35be81', 'readonly': 'Fals= e', 'shared': 'false', 'truesize': '17698430976', 'type': 'disk', 'domainID= ': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volumeInfo': {'domainID': '965c= a3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'pa= th': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e= 81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be81/5156a43b-c= 9dc-40fa-a9b7-a35b7f22f0eb', 'volumeID': '5156a43b-c9dc-40fa-a9b7-a35b7f22f= 0eb', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/96= 5ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35b= e81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb.lease', 'imageID': '1b23ac73-0748-= 49cd-94b6-11555e35be81'}, 'format': 'raw', 'deviceId': '1b23ac73-0748-49cd-= 94b6-11555e35be81', 'poolID': '94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'devi= ce': 'disk', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/= 965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e3= 5be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'propagateErrors': 'off', 'opt= ional': 'false', 'name': u'sda', 'bootOrder': u'1', 'volumeID': '5156a43b-c= 9dc-40fa-a9b7-a35b7f22f0eb', 'alias': u'scsi0-0-0-0', 'volumeChain': [{'dom= ainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOf= fset': 0, 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965= ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-94b6-11555e35be= 81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb', 'volumeID': '5156a43b-c9dc-40fa-a= 9b7-a35b7f22f0eb', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_na= s1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/1b23ac73-0748-49cd-9= 4b6-11555e35be81/5156a43b-c9dc-40fa-a9b7-a35b7f22f0eb.lease', 'imageID': '1= b23ac73-0748-49cd-94b6-11555e35be81'}]}, {'specParams': {}, 'alias': 'sound= 0', 'deviceId': '38b39d1b-7573-4112-b04f-669402652413', 'address': {'slot':= '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0= '}, 'device': 'ich6', 'type': 'sound'}, {'target': 2097152, 'specParams': {= 'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '7c9ed232-f54e-4382-a2= 2e-f74c2b6412f4', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0= 000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'b= alloon'}], 'status': 'Paused', 'display': 'qxl'} createXmlElem:<bound metho= d Drive.createXmlElem of <vm.Drive object at 0x7f356003bb90>> device:cdrom = deviceId:6aad5e48-613b-48db-838a-fc923fb0cdd7 drv:raw extSharedState:none g= etLeasesXML:<bound method Drive.getLeasesXML of <vm.Drive object at 0x7f356= 003bb90>> getNextVolumeSize:<bound method Drive.getNextVolumeSize of <vm.Dr= ive object at 0x7f356003bb90>> getXML:<bound method Drive.getXML of <vm.Dri= ve object at 0x7f356003bb90>> hasVolumeLeases:False iface:ide index:2 isDis= kReplicationInProgress:<bound method Drive.isDiskReplicationInProgress of <= vm.Drive object at 0x7f356003bb90>> isVdsmImage:<bound method Drive.isVdsmI= mage of <vm.Drive object at 0x7f356003bb90>> log:<logUtils.SimpleLogAdapter= object at 0x7f356002ef90> name:hdc networkDev:False path: readonly:True re= qsize:0 serial: shared:false specParams:{'path': ''} truesize:0 type:cdrom = volExtensionChunk:1024 watermarkLimit:536870912=0A= Traceback (most recent call last):=0A= File "/usr/share/vdsm/clientIF.py", line 356, in teardownVolumePath=0A= res =3D self.irs.teardownImage(drive['domainID'],=0A= File "/usr/share/vdsm/vm.py", line 1389, in __getitem__=0A= raise KeyError(key)=0A= KeyError: 'domainID'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,779::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::moving fr= om state init -> state preparing=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,779::logUtils::44::dispatcher::= (wrapper) Run and protect: teardownImage(sdUUID=3D'965ca3b6-4f9c-4e81-b6e8-= 5ed4a9e58545', spUUID=3D'94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID=3D'= 1b23ac73-0748-49cd-94b6-11555e35be81', volUUID=3DNone)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::197::Res= ourceManager.Request::(__init__) ResName=3D`Storage.965ca3b6-4f9c-4e81-b6e8= -5ed4a9e58545`ReqID=3D`ce6ba549-acf2-49fa-8b36-2194b81606a5`::Request was m= ade in '/usr/share/vdsm/storage/hsm.py' line '3283' at 'teardownImage'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::541::Res= ourceManager::(registerResource) Trying to register resource 'Storage.965ca= 3b6-4f9c-4e81-b6e8-5ed4a9e58545' for lock type 'shared'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::600::Res= ourceManager::(registerResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-= 5ed4a9e58545' is free. Now locking as 'shared' (1 active user)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::resourceManager::237::Res= ourceManager.Request::(grant) ResName=3D`Storage.965ca3b6-4f9c-4e81-b6e8-5e= d4a9e58545`ReqID=3D`ce6ba549-acf2-49fa-8b36-2194b81606a5`::Granted request= =0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,780::task::811::TaskManager.Ta= sk::(resourceAcquired) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::_reso= urcesAcquired: Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 (shared)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::974::TaskManager.Ta= sk::(_decref) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::ref 1 aborting= False=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,781::logUtils::47::dispatcher::= (wrapper) Run and protect: teardownImage, Return response: None=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::1168::TaskManager.T= ask::(prepare) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::finished: Non= e=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::moving fr= om state preparing -> state finished=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::resourceManager::939::Res= ourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'S= torage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': < ResourceRef 'Storage.965ca3= b6-4f9c-4e81-b6e8-5ed4a9e58545', isValid: 'True' obj: 'None'>}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,781::resourceManager::976::Res= ourceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::615::Res= ourceManager::(releaseResource) Trying to release resource 'Storage.965ca3b= 6-4f9c-4e81-b6e8-5ed4a9e58545'=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::634::Res= ourceManager::(releaseResource) Released resource 'Storage.965ca3b6-4f9c-4e= 81-b6e8-5ed4a9e58545' (0 active users)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::640::Res= ourceManager::(releaseResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5= ed4a9e58545' is free, finding out if anyone is waiting for it.=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::resourceManager::648::Res= ourceManager::(releaseResource) No one is waiting for resource 'Storage.965= ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', Clearing records.=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,782::task::974::TaskManager.Ta= sk::(_decref) Task=3D`b2f2b540-29c7-436f-b28a-e3fa961e9ddd`::ref 0 aborting= False=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,783::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::moving fr= om state init -> state preparing=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,783::logUtils::44::dispatcher::= (wrapper) Run and protect: inappropriateDevices(thiefId=3D'ce64f528-9981-4e= c6-a172-9d70a00a34cd')=0A= libvirtEventLoop::INFO::2014-01-30 16:17:29,783::logUtils::47::dispatcher::= (wrapper) Run and protect: inappropriateDevices, Return response: None=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::1168::TaskManager.T= ask::(prepare) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::finished: Non= e=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::579::TaskManager.Ta= sk::(_updateState) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::moving fr= om state preparing -> state finished=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::resourceManager::939::Res= ourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}= =0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::resourceManager::976::Res= ourceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,784::task::974::TaskManager.Ta= sk::(_decref) Task=3D`889a75b9-0702-40d3-99da-f7994e33c40c`::ref 0 aborting= False=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,787::BindingXMLRPC::974::vds::(wr= apper) client [192.168.11.42]::call vmDestroy with ('ce64f528-9981-4ec6-a17= 2-9d70a00a34cd',) {}=0A= Thread-285248::INFO::2014-01-30 16:17:29,787::API::318::vds::(destroy) vmCo= ntainerLock acquired by vm ce64f528-9981-4ec6-a172-9d70a00a34cd=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,787::vm::4374::vm.Vm::(destroy) v= mId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::destroy Called=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,788::vm::4368::vm.Vm::(deleteVm) = vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Total desktops after destroy= of ce64f528-9981-4ec6-a172-9d70a00a34cd is 0=0A= Thread-285248::DEBUG::2014-01-30 16:17:29,788::BindingXMLRPC::981::vds::(wr= apper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'c= ode': 0}}=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::libvirtconnection::108::l= ibvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level:= 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID = 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::vm::2577::vm.Vm::(setDown= Status) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Changed state to Dow= n: Lost connection with qemu process=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,792::sampling::292::vm.Vm::(st= op) vmId=3D`ce64f528-9981-4ec6-a172-9d70a00a34cd`::Stop statistics collecti= on=0A= libvirtEventLoop::DEBUG::2014-01-30 16:17:29,793::libvirtconnection::108::l= ibvirtconnection::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level:= 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID = 'ce64f528-9981-4ec6-a172-9d70a00a34cd' (Win7x64_Master)=0A= Thread-47::DEBUG::2014-01-30 16:17:30,113::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:30,120::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000169437 s, 2.1 MB/s\n'; <rc> =3D 0=0A= VM Channels Listener::DEBUG::2014-01-30 16:17:30,731::vmChannels::112::vds:= :(_do_del_channels) fileno 98 was removed from listener.=0A= Thread-41::DEBUG::2014-01-30 16:17:31,606::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:31,612::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000246606 s, 2.3 MB/s\n'; <rc> =3D 0=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,200::task::579::TaskManager.Task:= :(_updateState) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::moving from = state init -> state preparing=0A= Thread-285249::INFO::2014-01-30 16:17:32,200::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285249::INFO::2014-01-30 16:17:32,201::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000195778', 'lastCheck': '4.3', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000246606', 'lastCheck': '0.6', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.00021875', 'lastC= heck': '3.8', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44-= b36f-f39f16d3974f': {'delay': '0.000169437', 'lastCheck': '2.1', 'code': 0,= 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'de= lay': '0.000195213', 'lastCheck': '7.7', 'code': 0, 'valid': True, 'version= ': 3}}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::1168::TaskManager.Task= ::(prepare) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000195778', 'lastCheck': '4= .3', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.000246606', 'lastCheck': '0.6', 'code': 0, 'valid':= True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.= 00021875', 'lastCheck': '3.8', 'code': 0, 'valid': True, 'version': 0}, '63= 041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000169437', 'lastCheck': = '2.1', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-73= 2789dd18d4': {'delay': '0.000195213', 'lastCheck': '7.7', 'code': 0, 'valid= ': True, 'version': 3}}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::579::TaskManager.Task:= :(_updateState) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::moving from = state preparing -> state finished=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285249::DEBUG::2014-01-30 16:17:32,201::task::974::TaskManager.Task:= :(_decref) Task=3D`e44ca35a-0638-43b2-99b7-85790a96f8a2`::ref 0 aborting Fa= lse=0A= Thread-52::DEBUG::2014-01-30 16:17:34,531::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:34,538::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000202672 s, 2.7 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:17:37,893::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:37,899::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000200736 s, 3.2 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:38,418::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:38,423::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000239232 s, 1.5 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:17:40,132::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:40,137::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000199954 s, 1.8 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:17:41,622::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:41,628::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000177973 s, 3.1 MB/s\n'; <rc> =3D 0=0A= Thread-52::DEBUG::2014-01-30 16:17:44,549::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:44,555::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000217367 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,564::task::579::TaskManager.Task:= :(_updateState) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::moving from = state init -> state preparing=0A= Thread-285255::INFO::2014-01-30 16:17:47,564::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285255::INFO::2014-01-30 16:17:47,564::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000200736', 'lastCheck': '9.7', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000177973', 'lastCheck': '5.9', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000239232', 'last= Check': '9.1', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44= -b36f-f39f16d3974f': {'delay': '0.000199954', 'lastCheck': '7.4', 'code': 0= , 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'d= elay': '0.000217367', 'lastCheck': '3.0', 'code': 0, 'valid': True, 'versio= n': 3}}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,564::task::1168::TaskManager.Task= ::(prepare) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000200736', 'lastCheck': '9= .7', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.000177973', 'lastCheck': '5.9', 'code': 0, 'valid':= True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.= 000239232', 'lastCheck': '9.1', 'code': 0, 'valid': True, 'version': 0}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000199954', 'lastCheck':= '7.4', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.000217367', 'lastCheck': '3.0', 'code': 0, 'vali= d': True, 'version': 3}}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::task::579::TaskManager.Task:= :(_updateState) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::moving from = state preparing -> state finished=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285255::DEBUG::2014-01-30 16:17:47,565::task::974::TaskManager.Task:= :(_decref) Task=3D`feb38342-e432-4cdf-afc4-39582ee67c68`::ref 0 aborting Fa= lse=0A= Thread-40::DEBUG::2014-01-30 16:17:47,913::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:47,919::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000156636 s, 4.1 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:48,435::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:48,440::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000219512 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:17:50,153::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:17:50,158::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000129306 s, 2.8 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:17:51,639::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:17:51,645::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000299809 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-52::DEBUG::2014-01-30 16:17:54,565::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:17:54,571::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.00023204 s, 2.4 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:17:57,934::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:17:57,940::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000197083 s, 3.3 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:17:58,453::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:17:58,458::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000150387 s, 2.4 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:18:00,168::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:18:00,174::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000222782 s, 1.6 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:18:01,655::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:18:01,661::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000197351 s, 2.8 MB/s\n'; <rc> =3D 0=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,942::task::579::TaskManager.Task:= :(_updateState) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::moving from = state init -> state preparing=0A= Thread-285261::INFO::2014-01-30 16:18:02,943::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285261::INFO::2014-01-30 16:18:02,943::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000197083', 'lastCheck': '5.0', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000197351', 'lastCheck': '1.3', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000150387', 'last= Check': '4.5', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b44= -b36f-f39f16d3974f': {'delay': '0.000222782', 'lastCheck': '2.8', 'code': 0= , 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'d= elay': '0.00023204', 'lastCheck': '8.4', 'code': 0, 'valid': True, 'version= ': 3}}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,943::task::1168::TaskManager.Task= ::(prepare) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::finished: {'2c51= d320-88ce-4f23-8215-e15f55f66906': {'delay': '0.000197083', 'lastCheck': '5= .0', 'code': 0, 'valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4= a9e58545': {'delay': '0.000197351', 'lastCheck': '1.3', 'code': 0, 'valid':= True, 'version': 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.= 000150387', 'lastCheck': '4.5', 'code': 0, 'valid': True, 'version': 0}, '6= 3041fa9-e093-4b44-b36f-f39f16d3974f': {'delay': '0.000222782', 'lastCheck':= '2.8', 'code': 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-7= 32789dd18d4': {'delay': '0.00023204', 'lastCheck': '8.4', 'code': 0, 'valid= ': True, 'version': 3}}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::task::579::TaskManager.Task:= :(_updateState) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::moving from = state preparing -> state finished=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::resourceManager::939::Resour= ceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::resourceManager::976::Resour= ceManager.Owner::(cancelAll) Owner.cancelAll requests {}=0A= Thread-285261::DEBUG::2014-01-30 16:18:02,944::task::974::TaskManager.Task:= :(_decref) Task=3D`5683bb8f-2158-4c8f-a263-46b6e7a086da`::ref 0 aborting Fa= lse=0A= Thread-52::DEBUG::2014-01-30 16:18:04,581::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:18:04,588::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000218219 s, 2.6 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:18:07,953::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:18:07,959::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.00019818 s, 3.3 MB/s\n'; <rc> =3D 0=0A= Thread-42::DEBUG::2014-01-30 16:18:08,470::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-42::DEBUG::2014-01-30 16:18:08,475::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n357 b= ytes (357 B) copied, 0.000178019 s, 2.0 MB/s\n'; <rc> =3D 0=0A= Thread-47::DEBUG::2014-01-30 16:18:10,186::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/me= tadata bs=3D4096 count=3D1' (cwd None)=0A= Thread-47::DEBUG::2014-01-30 16:18:10,192::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n363 b= ytes (363 B) copied, 0.000189951 s, 1.9 MB/s\n'; <rc> =3D 0=0A= Thread-41::DEBUG::2014-01-30 16:18:11,671::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-41::DEBUG::2014-01-30 16:18:11,677::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000247616 s, 2.2 MB/s\n'; <rc> =3D 0=0A= Thread-52::DEBUG::2014-01-30 16:18:14,598::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-52::DEBUG::2014-01-30 16:18:14,604::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n557 b= ytes (557 B) copied, 0.000208255 s, 2.7 MB/s\n'; <rc> =3D 0=0A= Thread-40::DEBUG::2014-01-30 16:18:17,974::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) '/usr/bin/dd iflag=3Ddirect if=3D/rhev/data-center/mnt/10.= 10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/met= adata bs=3D4096 count=3D1' (cwd None)=0A= Thread-40::DEBUG::2014-01-30 16:18:17,979::fileSD::239::Storage.Misc.excCmd= ::(getReadDelay) SUCCESS: <err> =3D '0+1 records in\n0+1 records out\n645 b= ytes (645 B) copied, 0.000217282 s, 3.0 MB/s\n'; <rc> =3D 0=0A= Thread-285267::DEBUG::2014-01-30 16:18:18,464::task::579::TaskManager.Task:= :(_updateState) Task=3D`1e0fc684-6d0b-4694-996c-728b66ae9fc2`::moving from = state init -> state preparing=0A= Thread-285267::INFO::2014-01-30 16:18:18,465::logUtils::44::dispatcher::(wr= apper) Run and protect: repoStats(options=3DNone)=0A= Thread-285267::INFO::2014-01-30 16:18:18,465::logUtils::47::dispatcher::(wr= apper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-82= 15-e15f55f66906': {'delay': '0.000217282', 'lastCheck': '0.5', 'code': 0, '= valid': True, 'version': 3}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'dela= y': '0.000247616', 'lastCheck': '6.8', 'code': 0, 'valid': True, 'version':= 3}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'delay': '0.000178019', 'last= Check': '10.0', 'code': 0, 'valid': True, 'version': 0}, '63041fa9-e093-4b4= 4-b36f-f39f16d3974f': {'delay': '0.000189951', 'lastCheck': '8.3', 'code': = 0, 'valid': True, 'version': 0}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'= delay': '0.000208255', 'lastCheck': '3.9', 'code': 0, 'valid': True, 'versi= on': 3}}=0A= ------=_NextPartTM-000-16e476a9-dc0a-459b-91a5-33c52e66e68f Content-Type: text/plain; name="InterScan_Disclaimer.txt" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="InterScan_Disclaimer.txt" **************************************************************************** Diese E-Mail enthält vertrauliche und/oder rechtlich geschützte Informationen. Wenn Sie nicht der richtige Adressat sind oder diese E-Mail irrtümlich erhalten haben, informieren Sie bitte sofort den Absender und vernichten Sie diese Mail. Das unerlaubte Kopieren sowie die unbefugte Weitergabe dieser Mail ist nicht gestattet. Über das Internet versandte E-Mails können unter fremden Namen erstellt oder manipuliert werden. Deshalb ist diese als E-Mail verschickte Nachricht keine rechtsverbindliche Willenserklärung. Collogia Unternehmensberatung AG Ubierring 11 D-50678 Köln Vorstand: Kadir Akin Dr. Michael Höhnerbach Vorsitzender des Aufsichtsrates: Hans Kristian Langva Registergericht: Amtsgericht Köln Registernummer: HRB 52 497 This e-mail may contain confidential and/or privileged information. If you are not the intended recipient (or have received this e-mail in error) please notify the sender immediately and destroy this e-mail. Any unauthorized copying, disclosure or distribution of the material in this e-mail is strictly forbidden. e-mails sent over the internet may have been written under a wrong name or been manipulated. That is why this message sent as an e-mail is not a legally binding declaration of intention. Collogia Unternehmensberatung AG Ubierring 11 D-50678 Köln executive board: Kadir Akin Dr. Michael Höhnerbach President of the supervisory board: Hans Kristian Langva Registry office: district court Cologne Register number: HRB 52 497 **************************************************************************** ------=_NextPartTM-000-16e476a9-dc0a-459b-91a5-33c52e66e68f--

5 11