Attachment 606751 Details for Bug 851397 – vdsm.log under /var/log/vdsm dir

vdsm.log under /var/log/vdsm dir

vdsm.log (text/plain), 42.11 KB, created by EricLee on 2012-08-24 04:41:14 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: EricLee

Created: 2012-08-24 04:41:14 UTC

Size: 42.11 KB

patch

obsolete

>Thread-2277::DEBUG::2012-08-24 12:30:35,453::task::588::TaskManager.Task::(_updateState) Task=`89cd942c-736b-44f6-9f6b-b26ea237ede0`::moving from state init -> state preparing
>Thread-2277::INFO::2012-08-24 12:30:35,453::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2277::INFO::2012-08-24 12:30:35,454::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000935077667236', 'lastCheck': 1345782635.2403541, 'code': 0, 'valid': True}}
>Thread-2277::DEBUG::2012-08-24 12:30:35,454::task::1172::TaskManager.Task::(prepare) Task=`89cd942c-736b-44f6-9f6b-b26ea237ede0`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000935077667236', 'lastCheck': 1345782635.2403541, 'code': 0, 'valid': True}}
>Thread-2277::DEBUG::2012-08-24 12:30:35,454::task::588::TaskManager.Task::(_updateState) Task=`89cd942c-736b-44f6-9f6b-b26ea237ede0`::moving from state preparing -> state finished
>Thread-2277::DEBUG::2012-08-24 12:30:35,454::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2277::DEBUG::2012-08-24 12:30:35,455::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2277::DEBUG::2012-08-24 12:30:35,455::task::978::TaskManager.Task::(_decref) Task=`89cd942c-736b-44f6-9f6b-b26ea237ede0`::ref 0 aborting False
>Thread-2281::DEBUG::2012-08-24 12:30:41,308::BindingXMLRPC::864::vds::(wrapper) client [10.66.5.12]::call vmCreate with ({'custom': {'device_b254ee62-d8f5-4aa2-929a-cf60cf737086': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=b254ee62-d8f5-4aa2-929a-cf60cf737086,Device=ide,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621a': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=5651a43c-ae09-4e12-ba8e-e0ca7b46621a,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7device_60ac1e61-a60b-403d-921a-5474bfa19826device_117a48b2-f007-48a7-a420-c04db2e43a45device_3cf0cd12-2a2e-4b0c-af2e-ab2e97738cf0': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=3cf0cd12-2a2e-4b0c-af2e-ab2e97738cf0,Device=usb,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=74c9363a-5eda-41d8-b166-9ba54dce8bf7,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=1, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7device_60ac1e61-a60b-403d-921a-5474bfa19826device_117a48b2-f007-48a7-a420-c04db2e43a45': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=117a48b2-f007-48a7-a420-c04db2e43a45,Device=spicevmc,Type=channel,BootOrder=0,SpecParams={},Address={port=3, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel2', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7device_60ac1e61-a60b-403d-921a-5474bfa19826': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=60ac1e61-a60b-403d-921a-5474bfa19826,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=2, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.3.0', 'displayNetwork': 'rhevm', 'vmId': '33dd3127-7f9c-48c5-9d26-5a86e36c3266', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '53ecb2bd-3db9-47ba-b1ba-538e842f4eeb', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '0be84509-fe98-499e-93ad-2e21f467675e', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '224281dd-7258-417c-a46e-dc025185e03e', 'volumeID': '5b777633-c8c8-427a-b022-59a9c36fca73', 'imageID': '02907a43-6d99-4271-8b28-64e14a4e354d', 'specParams': {}, 'readonly': 'false', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'deviceId': '02907a43-6d99-4271-8b28-64e14a4e354d', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:7a:04', 'network': 'rhevm', 'specParams': {}, 'deviceId': '7283e1e3-88da-44f5-a6e7-937330c365b4', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '3cf0cd12-2a2e-4b0c-af2e-ab2e97738cf0', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '77cbf8d6-69a7-4e5a-90d2-dd7c8909f134'}], 'smp': '1', 'vmType': 'kvm', 'timeOffset': '-43200', 'memSize': 512, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs', 'smpCoresPerSocket': '1', 'vmName': 'whuang', 'display': 'qxl', 'transparentHugePages': 'true', 'nice': '0'},) {} flowID [78e14e3a]
>Thread-2281::INFO::2012-08-24 12:30:41,319::API::216::vds::(create) vmContainerLock acquired by vm 33dd3127-7f9c-48c5-9d26-5a86e36c3266
>Thread-2282::DEBUG::2012-08-24 12:30:41,323::vm::567::vm.Vm::(_startUnderlyingVm) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::Start
>Thread-2281::DEBUG::2012-08-24 12:30:41,323::API::229::vds::(create) Total desktops after creation of 33dd3127-7f9c-48c5-9d26-5a86e36c3266 is 1
>Thread-2282::DEBUG::2012-08-24 12:30:41,324::vm::571::vm.Vm::(_startUnderlyingVm) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::_ongoingCreations acquired
>Thread-2281::DEBUG::2012-08-24 12:30:41,324::BindingXMLRPC::870::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.3.0', 'vmId': '33dd3127-7f9c-48c5-9d26-5a86e36c3266', 'pid': '0', 'timeOffset': '-43200', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'device_b254ee62-d8f5-4aa2-929a-cf60cf737086': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=b254ee62-d8f5-4aa2-929a-cf60cf737086,Device=ide,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=ide0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621a': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=5651a43c-ae09-4e12-ba8e-e0ca7b46621a,Device=virtio-serial,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x04, function=0x0},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=virtio-serial0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7device_60ac1e61-a60b-403d-921a-5474bfa19826device_117a48b2-f007-48a7-a420-c04db2e43a45device_3cf0cd12-2a2e-4b0c-af2e-ab2e97738cf0': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=3cf0cd12-2a2e-4b0c-af2e-ab2e97738cf0,Device=usb,Type=controller,BootOrder=0,SpecParams={},Address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x2},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=usb0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=74c9363a-5eda-41d8-b166-9ba54dce8bf7,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=1, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel0', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7device_60ac1e61-a60b-403d-921a-5474bfa19826device_117a48b2-f007-48a7-a420-c04db2e43a45': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=117a48b2-f007-48a7-a420-c04db2e43a45,Device=spicevmc,Type=channel,BootOrder=0,SpecParams={},Address={port=3, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel2', 'device_b254ee62-d8f5-4aa2-929a-cf60cf737086device_5651a43c-ae09-4e12-ba8e-e0ca7b46621adevice_74c9363a-5eda-41d8-b166-9ba54dce8bf7device_60ac1e61-a60b-403d-921a-5474bfa19826': 'VmId=33dd3127-7f9c-48c5-9d26-5a86e36c3266,DeviceId=60ac1e61-a60b-403d-921a-5474bfa19826,Device=unix,Type=channel,BootOrder=0,SpecParams={},Address={port=2, bus=0, controller=0, type=virtio-serial},IsManaged=false,IsPlugged=true,IsReadOnly=false,alias=channel1'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages': 'true', 'displayNetwork': 'rhevm', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '53ecb2bd-3db9-47ba-b1ba-538e842f4eeb', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '0be84509-fe98-499e-93ad-2e21f467675e', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'raw', 'optional': 'false', 'poolID': '224281dd-7258-417c-a46e-dc025185e03e', 'volumeID': '5b777633-c8c8-427a-b022-59a9c36fca73', 'imageID': '02907a43-6d99-4271-8b28-64e14a4e354d', 'specParams': {}, 'readonly': 'false', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'deviceId': '02907a43-6d99-4271-8b28-64e14a4e354d', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:7a:04', 'network': 'rhevm', 'specParams': {}, 'deviceId': '7283e1e3-88da-44f5-a6e7-937330c365b4', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': '3cf0cd12-2a2e-4b0c-af2e-ab2e97738cf0', 'address': {'bus': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '77cbf8d6-69a7-4e5a-90d2-dd7c8909f134'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 512, 'displayIp': '10.66.4.191', 'spiceSecureChannels': 'smain,sinputs', 'smpCoresPerSocket': '1', 'vmName': 'whuang', 'display': 'qxl', 'nice': '0'}}
>Thread-2282::INFO::2012-08-24 12:30:41,325::libvirtvm::1306::vm.Vm::(_run) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::VM wrapper has started
>Thread-2282::DEBUG::2012-08-24 12:30:41,328::task::588::TaskManager.Task::(_updateState) Task=`07e868ba-298f-434d-8015-f206ffa1bc0b`::moving from state init -> state preparing
>Thread-2282::INFO::2012-08-24 12:30:41,328::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='9bd82898-9672-4cc1-b7ad-ac722e00822b', spUUID='224281dd-7258-417c-a46e-dc025185e03e', imgUUID='02907a43-6d99-4271-8b28-64e14a4e354d', volUUID='5b777633-c8c8-427a-b022-59a9c36fca73', options=None)
>Thread-2282::DEBUG::2012-08-24 12:30:41,329::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`3ab077e5-d957-4438-8b13-79c8d1939f9d`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-2282::DEBUG::2012-08-24 12:30:41,330::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' for lock type 'shared'
>Thread-2282::DEBUG::2012-08-24 12:30:41,330::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free. Now locking as 'shared' (1 active user)
>Thread-2282::DEBUG::2012-08-24 12:30:41,330::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`3ab077e5-d957-4438-8b13-79c8d1939f9d`::Granted request
>Thread-2282::DEBUG::2012-08-24 12:30:41,331::task::817::TaskManager.Task::(resourceAcquired) Task=`07e868ba-298f-434d-8015-f206ffa1bc0b`::_resourcesAcquired: Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b (shared)
>Thread-2282::DEBUG::2012-08-24 12:30:41,331::task::978::TaskManager.Task::(_decref) Task=`07e868ba-298f-434d-8015-f206ffa1bc0b`::ref 1 aborting False
>Thread-2282::DEBUG::2012-08-24 12:30:41,333::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 5b777633-c8c8-427a-b022-59a9c36fca73
>Thread-2282::DEBUG::2012-08-24 12:30:41,336::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 5b777633-c8c8-427a-b022-59a9c36fca73
>Thread-2282::INFO::2012-08-24 12:30:41,337::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '2050572288', 'apparentsize': '8589934592'}
>Thread-2282::DEBUG::2012-08-24 12:30:41,337::task::1172::TaskManager.Task::(prepare) Task=`07e868ba-298f-434d-8015-f206ffa1bc0b`::finished: {'truesize': '2050572288', 'apparentsize': '8589934592'}
>Thread-2282::DEBUG::2012-08-24 12:30:41,337::task::588::TaskManager.Task::(_updateState) Task=`07e868ba-298f-434d-8015-f206ffa1bc0b`::moving from state preparing -> state finished
>Thread-2282::DEBUG::2012-08-24 12:30:41,338::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b': < ResourceRef 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', isValid: 'True' obj: 'None'>}
>Thread-2282::DEBUG::2012-08-24 12:30:41,338::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2282::DEBUG::2012-08-24 12:30:41,338::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b'
>Thread-2282::DEBUG::2012-08-24 12:30:41,339::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' (0 active users)
>Thread-2282::DEBUG::2012-08-24 12:30:41,339::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free, finding out if anyone is waiting for it.
>Thread-2282::DEBUG::2012-08-24 12:30:41,339::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', Clearing records.
>Thread-2282::DEBUG::2012-08-24 12:30:41,339::task::978::TaskManager.Task::(_decref) Task=`07e868ba-298f-434d-8015-f206ffa1bc0b`::ref 0 aborting False
>Thread-2282::INFO::2012-08-24 12:30:41,340::clientIF::233::vds::(prepareVolumePath) prepared volume path: 
>Thread-2282::DEBUG::2012-08-24 12:30:41,340::task::588::TaskManager.Task::(_updateState) Task=`7e20b836-5e3b-4803-9d3f-d68bbf606d1d`::moving from state init -> state preparing
>Thread-2282::INFO::2012-08-24 12:30:41,340::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='9bd82898-9672-4cc1-b7ad-ac722e00822b', spUUID='224281dd-7258-417c-a46e-dc025185e03e', imgUUID='02907a43-6d99-4271-8b28-64e14a4e354d', volUUID='5b777633-c8c8-427a-b022-59a9c36fca73')
>Thread-2282::DEBUG::2012-08-24 12:30:41,341::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`6e3287c0-eafd-4cd9-8374-00569150f24b`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-2282::DEBUG::2012-08-24 12:30:41,341::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' for lock type 'shared'
>Thread-2282::DEBUG::2012-08-24 12:30:41,341::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free. Now locking as 'shared' (1 active user)
>Thread-2282::DEBUG::2012-08-24 12:30:41,341::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b`ReqID=`6e3287c0-eafd-4cd9-8374-00569150f24b`::Granted request
>Thread-2282::DEBUG::2012-08-24 12:30:41,342::task::817::TaskManager.Task::(resourceAcquired) Task=`7e20b836-5e3b-4803-9d3f-d68bbf606d1d`::_resourcesAcquired: Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b (shared)
>Thread-2282::DEBUG::2012-08-24 12:30:41,342::task::978::TaskManager.Task::(_decref) Task=`7e20b836-5e3b-4803-9d3f-d68bbf606d1d`::ref 1 aborting False
>Thread-2282::DEBUG::2012-08-24 12:30:41,343::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 5b777633-c8c8-427a-b022-59a9c36fca73
>Thread-2282::INFO::2012-08-24 12:30:41,347::image::319::Storage.Image::(getChain) sdUUID=9bd82898-9672-4cc1-b7ad-ac722e00822b imgUUID=02907a43-6d99-4271-8b28-64e14a4e354d chain=[<storage.fileVolume.FileVolume object at 0x7f855c2d0350>] 
>Thread-2282::INFO::2012-08-24 12:30:41,349::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/02907a43-6d99-4271-8b28-64e14a4e354d/5b777633-c8c8-427a-b022-59a9c36fca73', 'chain': [{'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/02907a43-6d99-4271-8b28-64e14a4e354d/5b777633-c8c8-427a-b022-59a9c36fca73', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'volumeID': '5b777633-c8c8-427a-b022-59a9c36fca73', 'imageID': '02907a43-6d99-4271-8b28-64e14a4e354d'}]}
>Thread-2282::DEBUG::2012-08-24 12:30:41,349::task::1172::TaskManager.Task::(prepare) Task=`7e20b836-5e3b-4803-9d3f-d68bbf606d1d`::finished: {'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/02907a43-6d99-4271-8b28-64e14a4e354d/5b777633-c8c8-427a-b022-59a9c36fca73', 'chain': [{'path': '/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/02907a43-6d99-4271-8b28-64e14a4e354d/5b777633-c8c8-427a-b022-59a9c36fca73', 'domainID': '9bd82898-9672-4cc1-b7ad-ac722e00822b', 'volumeID': '5b777633-c8c8-427a-b022-59a9c36fca73', 'imageID': '02907a43-6d99-4271-8b28-64e14a4e354d'}]}
>Thread-2282::DEBUG::2012-08-24 12:30:41,350::task::588::TaskManager.Task::(_updateState) Task=`7e20b836-5e3b-4803-9d3f-d68bbf606d1d`::moving from state preparing -> state finished
>Thread-2282::DEBUG::2012-08-24 12:30:41,350::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b': < ResourceRef 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', isValid: 'True' obj: 'None'>}
>Thread-2282::DEBUG::2012-08-24 12:30:41,350::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2282::DEBUG::2012-08-24 12:30:41,350::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b'
>Thread-2282::DEBUG::2012-08-24 12:30:41,351::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' (0 active users)
>Thread-2282::DEBUG::2012-08-24 12:30:41,351::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b' is free, finding out if anyone is waiting for it.
>Thread-2282::DEBUG::2012-08-24 12:30:41,351::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9bd82898-9672-4cc1-b7ad-ac722e00822b', Clearing records.
>Thread-2282::DEBUG::2012-08-24 12:30:41,351::task::978::TaskManager.Task::(_decref) Task=`7e20b836-5e3b-4803-9d3f-d68bbf606d1d`::ref 0 aborting False
>Thread-2282::INFO::2012-08-24 12:30:41,352::clientIF::233::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/02907a43-6d99-4271-8b28-64e14a4e354d/5b777633-c8c8-427a-b022-59a9c36fca73
>Thread-2282::DEBUG::2012-08-24 12:30:41,359::libvirtvm::1359::vm.Vm::(_run) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>whuang</name>
>	<uuid>33dd3127-7f9c-48c5-9d26-5a86e36c3266</uuid>
>	<memory>524288</memory>
>	<currentMemory>524288</currentMemory>
>	<vcpu>1</vcpu>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/whuang.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/whuang.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>		<graphics autoport="yes" keymap="en-us" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<channel mode="secure" name="main"/>
>			<channel mode="secure" name="inputs"/>
>			<listen network="vdsm-rhevm" type="network"/>
>		</graphics>
>		<console type="pty">
>			<target port="0" type="virtio"/>
>		</console>
>		<controller type="usb">
>			<address  domain="0x0000"  function="0x2"  slot="0x01"  type="pci" bus="0x00"/>
>		</controller>
>		<video>
>			<address  domain="0x0000"  function="0x0"  slot="0x02"  type="pci" bus="0x00"/>
>			<model heads="1" type="qxl" vram="65536"/>
>		</video>
>		<interface type="bridge">
>			<address  domain="0x0000"  function="0x0"  slot="0x03"  type="pci" bus="0x00"/>
>			<mac address="00:1a:4a:a8:7a:04"/>
>			<model type="virtio"/>
>			<source bridge="rhevm"/>
>		</interface>
>		<memballoon model="virtio"/>
>		<disk device="cdrom" snapshot="no" type="file">
>			<address  bus="1"  controller="0"  target="0"  type="drive" unit="0"/>
>			<source file="" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial></serial>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<address  domain="0x0000"  function="0x0"  slot="0x05"  type="pci" bus="0x00"/>
>			<source file="/rhev/data-center/224281dd-7258-417c-a46e-dc025185e03e/9bd82898-9672-4cc1-b7ad-ac722e00822b/images/02907a43-6d99-4271-8b28-64e14a4e354d/5b777633-c8c8-427a-b022-59a9c36fca73"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>02907a43-6d99-4271-8b28-64e14a4e354d</serial>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="rhel6.3.0">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">Red Hat</entry>
>			<entry name="product">RHEV Hypervisor</entry>
>			<entry name="version">6Server-6.3.0.3.el6</entry>
>			<entry name="serial">44454C4C-4300-105A-8059-C7C04F4D3258_00:1B:21:27:4E:CE</entry>
>			<entry name="uuid">33dd3127-7f9c-48c5-9d26-5a86e36c3266</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="-43200" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Conroe</model>
>		<topology cores="1" sockets="1" threads="1"/>
>	</cpu>
></domain>
>
>Thread-2282::DEBUG::2012-08-24 12:30:41,360::vm::583::vm.Vm::(_startUnderlyingVm) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::_ongoingCreations released
>Thread-2282::ERROR::2012-08-24 12:30:41,360::vm::607::vm.Vm::(_startUnderlyingVm) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::The vm start process failed
>Traceback (most recent call last):
>  File "/usr/share/vdsm/vm.py", line 573, in _startUnderlyingVm
>    self._run()
>  File "/usr/share/vdsm/libvirtvm.py", line 1385, in _run
>    self._connection.createXML(domxml, flags),
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2533, in createXML
>    """Deprecated after 0.4.6.
>libvirtError: internal error client socket is closed
>Thread-2282::DEBUG::2012-08-24 12:30:41,363::vm::923::vm.Vm::(setDownStatus) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::Changed state to Down: internal error client socket is closed
>Thread-2285::DEBUG::2012-08-24 12:30:41,545::BindingXMLRPC::864::vds::(wrapper) client [10.66.5.12]::call vmGetStats with ('33dd3127-7f9c-48c5-9d26-5a86e36c3266',) {} flowID [149635ab]
>Thread-2285::DEBUG::2012-08-24 12:30:41,545::BindingXMLRPC::870::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down', 'hash': '0', 'exitMessage': 'internal error client socket is closed', 'vmId': '33dd3127-7f9c-48c5-9d26-5a86e36c3266', 'timeOffset': '-43200', 'exitCode': 1}]}
>Thread-2286::DEBUG::2012-08-24 12:30:41,562::BindingXMLRPC::864::vds::(wrapper) client [10.66.5.12]::call vmDestroy with ('33dd3127-7f9c-48c5-9d26-5a86e36c3266',) {} flowID [149635ab]
>Thread-2286::INFO::2012-08-24 12:30:41,562::API::301::vds::(destroy) vmContainerLock acquired by vm 33dd3127-7f9c-48c5-9d26-5a86e36c3266
>Thread-2286::DEBUG::2012-08-24 12:30:41,563::libvirtvm::2109::vm.Vm::(destroy) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::destroy Called
>Thread-2286::INFO::2012-08-24 12:30:41,563::libvirtvm::2064::vm.Vm::(releaseVm) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::Release VM resources
>Thread-2286::WARNING::2012-08-24 12:30:41,563::vm::328::vm.Vm::(_set_lastStatus) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::trying to set state to Powering down when already Down
>Thread-2286::DEBUG::2012-08-24 12:30:41,563::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/service ksmtuned retune' (cwd None)
>Thread-2286::DEBUG::2012-08-24 12:30:41,594::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-2286::DEBUG::2012-08-24 12:30:41,596::task::588::TaskManager.Task::(_updateState) Task=`65032575-c42b-432f-9c4c-91ff6cccc099`::moving from state init -> state preparing
>Thread-2286::INFO::2012-08-24 12:30:41,596::logUtils::37::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='33dd3127-7f9c-48c5-9d26-5a86e36c3266')
>Thread-2286::INFO::2012-08-24 12:30:41,598::logUtils::39::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
>Thread-2286::DEBUG::2012-08-24 12:30:41,598::task::1172::TaskManager.Task::(prepare) Task=`65032575-c42b-432f-9c4c-91ff6cccc099`::finished: None
>Thread-2286::DEBUG::2012-08-24 12:30:41,598::task::588::TaskManager.Task::(_updateState) Task=`65032575-c42b-432f-9c4c-91ff6cccc099`::moving from state preparing -> state finished
>Thread-2286::DEBUG::2012-08-24 12:30:41,599::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2286::DEBUG::2012-08-24 12:30:41,599::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2286::DEBUG::2012-08-24 12:30:41,599::task::978::TaskManager.Task::(_decref) Task=`65032575-c42b-432f-9c4c-91ff6cccc099`::ref 0 aborting False
>Thread-2286::DEBUG::2012-08-24 12:30:41,599::libvirtvm::2104::vm.Vm::(deleteVm) vmId=`33dd3127-7f9c-48c5-9d26-5a86e36c3266`::Total desktops after destroy of 33dd3127-7f9c-48c5-9d26-5a86e36c3266 is 0
>Thread-2286::DEBUG::2012-08-24 12:30:41,600::BindingXMLRPC::870::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
>Thread-2289::DEBUG::2012-08-24 12:30:45,673::task::588::TaskManager.Task::(_updateState) Task=`7e65ef68-6a94-4ed9-821e-468b32dd6be3`::moving from state init -> state preparing
>Thread-2289::INFO::2012-08-24 12:30:45,673::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2289::INFO::2012-08-24 12:30:45,673::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000943899154663', 'lastCheck': 1345782645.2456651, 'code': 0, 'valid': True}}
>Thread-2289::DEBUG::2012-08-24 12:30:45,673::task::1172::TaskManager.Task::(prepare) Task=`7e65ef68-6a94-4ed9-821e-468b32dd6be3`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000943899154663', 'lastCheck': 1345782645.2456651, 'code': 0, 'valid': True}}
>Thread-2289::DEBUG::2012-08-24 12:30:45,674::task::588::TaskManager.Task::(_updateState) Task=`7e65ef68-6a94-4ed9-821e-468b32dd6be3`::moving from state preparing -> state finished
>Thread-2289::DEBUG::2012-08-24 12:30:45,674::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2289::DEBUG::2012-08-24 12:30:45,674::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2289::DEBUG::2012-08-24 12:30:45,674::task::978::TaskManager.Task::(_decref) Task=`7e65ef68-6a94-4ed9-821e-468b32dd6be3`::ref 0 aborting False
>Thread-2295::DEBUG::2012-08-24 12:30:55,771::task::588::TaskManager.Task::(_updateState) Task=`4e351d37-c6a3-4727-aa50-9233abb94833`::moving from state init -> state preparing
>Thread-2295::INFO::2012-08-24 12:30:55,771::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2295::INFO::2012-08-24 12:30:55,771::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000961065292358', 'lastCheck': 1345782655.2503231, 'code': 0, 'valid': True}}
>Thread-2295::DEBUG::2012-08-24 12:30:55,771::task::1172::TaskManager.Task::(prepare) Task=`4e351d37-c6a3-4727-aa50-9233abb94833`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000961065292358', 'lastCheck': 1345782655.2503231, 'code': 0, 'valid': True}}
>Thread-2295::DEBUG::2012-08-24 12:30:55,772::task::588::TaskManager.Task::(_updateState) Task=`4e351d37-c6a3-4727-aa50-9233abb94833`::moving from state preparing -> state finished
>Thread-2295::DEBUG::2012-08-24 12:30:55,772::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2295::DEBUG::2012-08-24 12:30:55,772::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2295::DEBUG::2012-08-24 12:30:55,772::task::978::TaskManager.Task::(_decref) Task=`4e351d37-c6a3-4727-aa50-9233abb94833`::ref 0 aborting False
>Thread-2301::DEBUG::2012-08-24 12:31:05,871::task::588::TaskManager.Task::(_updateState) Task=`dde3348c-092f-41a9-9a9c-c4e810344ca8`::moving from state init -> state preparing
>Thread-2301::INFO::2012-08-24 12:31:05,872::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2301::INFO::2012-08-24 12:31:05,872::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000911951065063', 'lastCheck': 1345782665.2549109, 'code': 0, 'valid': True}}
>Thread-2301::DEBUG::2012-08-24 12:31:05,872::task::1172::TaskManager.Task::(prepare) Task=`dde3348c-092f-41a9-9a9c-c4e810344ca8`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000911951065063', 'lastCheck': 1345782665.2549109, 'code': 0, 'valid': True}}
>Thread-2301::DEBUG::2012-08-24 12:31:05,872::task::588::TaskManager.Task::(_updateState) Task=`dde3348c-092f-41a9-9a9c-c4e810344ca8`::moving from state preparing -> state finished
>Thread-2301::DEBUG::2012-08-24 12:31:05,873::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2301::DEBUG::2012-08-24 12:31:05,873::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2301::DEBUG::2012-08-24 12:31:05,873::task::978::TaskManager.Task::(_decref) Task=`dde3348c-092f-41a9-9a9c-c4e810344ca8`::ref 0 aborting False
>Thread-2307::DEBUG::2012-08-24 12:31:15,969::task::588::TaskManager.Task::(_updateState) Task=`9be97e2d-fa1e-44b7-8071-dba36fd9828e`::moving from state init -> state preparing
>Thread-2307::INFO::2012-08-24 12:31:15,969::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2307::INFO::2012-08-24 12:31:15,970::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00151300430298', 'lastCheck': 1345782675.260226, 'code': 0, 'valid': True}}
>Thread-2307::DEBUG::2012-08-24 12:31:15,970::task::1172::TaskManager.Task::(prepare) Task=`9be97e2d-fa1e-44b7-8071-dba36fd9828e`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00151300430298', 'lastCheck': 1345782675.260226, 'code': 0, 'valid': True}}
>Thread-2307::DEBUG::2012-08-24 12:31:15,970::task::588::TaskManager.Task::(_updateState) Task=`9be97e2d-fa1e-44b7-8071-dba36fd9828e`::moving from state preparing -> state finished
>Thread-2307::DEBUG::2012-08-24 12:31:15,970::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2307::DEBUG::2012-08-24 12:31:15,971::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2307::DEBUG::2012-08-24 12:31:15,971::task::978::TaskManager.Task::(_decref) Task=`9be97e2d-fa1e-44b7-8071-dba36fd9828e`::ref 0 aborting False
>Thread-2313::DEBUG::2012-08-24 12:31:26,070::task::588::TaskManager.Task::(_updateState) Task=`90ca710d-4270-4d88-b855-d59362608d49`::moving from state init -> state preparing
>Thread-2313::INFO::2012-08-24 12:31:26,070::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2313::INFO::2012-08-24 12:31:26,071::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000920057296753', 'lastCheck': 1345782685.2650621, 'code': 0, 'valid': True}}
>Thread-2313::DEBUG::2012-08-24 12:31:26,071::task::1172::TaskManager.Task::(prepare) Task=`90ca710d-4270-4d88-b855-d59362608d49`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000920057296753', 'lastCheck': 1345782685.2650621, 'code': 0, 'valid': True}}
>Thread-2313::DEBUG::2012-08-24 12:31:26,071::task::588::TaskManager.Task::(_updateState) Task=`90ca710d-4270-4d88-b855-d59362608d49`::moving from state preparing -> state finished
>Thread-2313::DEBUG::2012-08-24 12:31:26,071::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2313::DEBUG::2012-08-24 12:31:26,071::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2313::DEBUG::2012-08-24 12:31:26,072::task::978::TaskManager.Task::(_decref) Task=`90ca710d-4270-4d88-b855-d59362608d49`::ref 0 aborting False
>Thread-2319::DEBUG::2012-08-24 12:31:36,175::task::588::TaskManager.Task::(_updateState) Task=`91b9c7c5-0673-4cd3-8aa2-5dd3af7b04a0`::moving from state init -> state preparing
>Thread-2319::INFO::2012-08-24 12:31:36,175::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2319::INFO::2012-08-24 12:31:36,176::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000910043716431', 'lastCheck': 1345782695.2699461, 'code': 0, 'valid': True}}
>Thread-2319::DEBUG::2012-08-24 12:31:36,176::task::1172::TaskManager.Task::(prepare) Task=`91b9c7c5-0673-4cd3-8aa2-5dd3af7b04a0`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000910043716431', 'lastCheck': 1345782695.2699461, 'code': 0, 'valid': True}}
>Thread-2319::DEBUG::2012-08-24 12:31:36,176::task::588::TaskManager.Task::(_updateState) Task=`91b9c7c5-0673-4cd3-8aa2-5dd3af7b04a0`::moving from state preparing -> state finished
>Thread-2319::DEBUG::2012-08-24 12:31:36,176::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2319::DEBUG::2012-08-24 12:31:36,176::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2319::DEBUG::2012-08-24 12:31:36,177::task::978::TaskManager.Task::(_decref) Task=`91b9c7c5-0673-4cd3-8aa2-5dd3af7b04a0`::ref 0 aborting False
>Thread-2325::DEBUG::2012-08-24 12:31:46,279::task::588::TaskManager.Task::(_updateState) Task=`eca9bec1-a79c-4876-a6ce-cd861c8e3394`::moving from state init -> state preparing
>Thread-2325::INFO::2012-08-24 12:31:46,279::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2325::INFO::2012-08-24 12:31:46,280::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00094199180603', 'lastCheck': 1345782705.2750981, 'code': 0, 'valid': True}}
>Thread-2325::DEBUG::2012-08-24 12:31:46,280::task::1172::TaskManager.Task::(prepare) Task=`eca9bec1-a79c-4876-a6ce-cd861c8e3394`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00094199180603', 'lastCheck': 1345782705.2750981, 'code': 0, 'valid': True}}
>Thread-2325::DEBUG::2012-08-24 12:31:46,280::task::588::TaskManager.Task::(_updateState) Task=`eca9bec1-a79c-4876-a6ce-cd861c8e3394`::moving from state preparing -> state finished
>Thread-2325::DEBUG::2012-08-24 12:31:46,280::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2325::DEBUG::2012-08-24 12:31:46,281::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2325::DEBUG::2012-08-24 12:31:46,281::task::978::TaskManager.Task::(_decref) Task=`eca9bec1-a79c-4876-a6ce-cd861c8e3394`::ref 0 aborting False
>Thread-2331::DEBUG::2012-08-24 12:31:56,377::task::588::TaskManager.Task::(_updateState) Task=`9b9f41cb-00cf-4c2a-bc3d-4d89b2334280`::moving from state init -> state preparing
>Thread-2331::INFO::2012-08-24 12:31:56,378::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2331::INFO::2012-08-24 12:31:56,378::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000915050506592', 'lastCheck': 1345782715.279644, 'code': 0, 'valid': True}}
>Thread-2331::DEBUG::2012-08-24 12:31:56,378::task::1172::TaskManager.Task::(prepare) Task=`9b9f41cb-00cf-4c2a-bc3d-4d89b2334280`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.000915050506592', 'lastCheck': 1345782715.279644, 'code': 0, 'valid': True}}
>Thread-2331::DEBUG::2012-08-24 12:31:56,378::task::588::TaskManager.Task::(_updateState) Task=`9b9f41cb-00cf-4c2a-bc3d-4d89b2334280`::moving from state preparing -> state finished
>Thread-2331::DEBUG::2012-08-24 12:31:56,379::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2331::DEBUG::2012-08-24 12:31:56,379::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2331::DEBUG::2012-08-24 12:31:56,379::task::978::TaskManager.Task::(_decref) Task=`9b9f41cb-00cf-4c2a-bc3d-4d89b2334280`::ref 0 aborting False
>Thread-2337::DEBUG::2012-08-24 12:32:06,479::task::588::TaskManager.Task::(_updateState) Task=`836fe74e-14fc-41fe-b109-8047d6cf61d6`::moving from state init -> state preparing
>Thread-2337::INFO::2012-08-24 12:32:06,479::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2337::INFO::2012-08-24 12:32:06,479::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00095796585083', 'lastCheck': 1345782725.2841721, 'code': 0, 'valid': True}}
>Thread-2337::DEBUG::2012-08-24 12:32:06,480::task::1172::TaskManager.Task::(prepare) Task=`836fe74e-14fc-41fe-b109-8047d6cf61d6`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00095796585083', 'lastCheck': 1345782725.2841721, 'code': 0, 'valid': True}}
>Thread-2337::DEBUG::2012-08-24 12:32:06,480::task::588::TaskManager.Task::(_updateState) Task=`836fe74e-14fc-41fe-b109-8047d6cf61d6`::moving from state preparing -> state finished
>Thread-2337::DEBUG::2012-08-24 12:32:06,480::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2337::DEBUG::2012-08-24 12:32:06,480::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2337::DEBUG::2012-08-24 12:32:06,481::task::978::TaskManager.Task::(_decref) Task=`836fe74e-14fc-41fe-b109-8047d6cf61d6`::ref 0 aborting False
>Thread-2343::DEBUG::2012-08-24 12:32:16,578::task::588::TaskManager.Task::(_updateState) Task=`ae494f17-3039-4d1d-9c22-2ba81ab77a66`::moving from state init -> state preparing
>Thread-2343::INFO::2012-08-24 12:32:16,579::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2343::INFO::2012-08-24 12:32:16,579::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00152206420898', 'lastCheck': 1345782735.2896199, 'code': 0, 'valid': True}}
>Thread-2343::DEBUG::2012-08-24 12:32:16,579::task::1172::TaskManager.Task::(prepare) Task=`ae494f17-3039-4d1d-9c22-2ba81ab77a66`::finished: {'9bd82898-9672-4cc1-b7ad-ac722e00822b': {'delay': '0.00152206420898', 'lastCheck': 1345782735.2896199, 'code': 0, 'valid': True}}
>Thread-2343::DEBUG::2012-08-24 12:32:16,580::task::588::TaskManager.Task::(_updateState) Task=`ae494f17-3039-4d1d-9c22-2ba81ab77a66`::moving from state preparing -> state finished
>Thread-2343::DEBUG::2012-08-24 12:32:16,580::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2343::DEBUG::2012-08-24 12:32:16,580::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2343::DEBUG::2012-08-24 12:32:16,580::task::978::TaskManager.Task::(_decref) Task=`ae494f17-3039-4d1d-9c22-2ba81ab77a66`::ref 0 aborting False

Actions: View

Attachments on bug 851397: 606750 | 606751 | 607141 | 607142 | 607143 | 607144