[Users] SPM host in unknown status
Haim Ateya
hateya at redhat.com
Mon May 28 04:20:20 UTC 2012
After you run the manual fence operation, maintenance is essential as well (right click on host, hit it).
As for your logs on node2; it seems that manual fence command faild due to secure error (old bug of mine actually, we thought it was resolved - will search for bz later), what version are you working with (vdsm)?
As for logs on node1; as you can see vdsm fails to communicate with libvirt service; there are several reasons, please provide directory listing of /var/run/vdsm, is libvirt service is running? Do you have enough space on node?
Haim
On May 28, 2012, at 6:34, T-Sinjon <tscbj1989 at gmail.com> wrote:
> node1 vdsm.log:
> MainThread::INFO::2012-05-28 03:14:55,836::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads...
> MainThread::INFO::2012-05-28 03:14:55,836::vdsm::79::vds::(run) <_MainThread(MainThread, started 140246996211456)>
> MainThread::INFO::2012-05-28 03:14:55,836::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140246779500288)>
> MainThread::INFO::2012-05-28 03:14:55,912::vdsm::71::vds::(run) I am the actual vdsm 4.9-0
> MainThread::ERROR::2012-05-28 03:14:56,106::vdsm::74::vds::(run) Traceback (most recent call last):
> File "/usr/share/vdsm/vdsm", line 72, in run
> serve_clients(log)
> File "/usr/share/vdsm/vdsm", line 40, in serve_clients
> cif = clientIF.clientIF(log)
> File "/usr/share/vdsm/clientIF.py", line 114, in __init__
> File "/usr/share/vdsm/libvirtconnection.py", line 111, in get
> File "/usr/lib64/python2.7/site-packages/libvirt.py", line 102, in openAuth
> libvirtError: Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory
>
> MainThread::INFO::2012-05-28 03:14:56,106::vdsm::76::vds::(run) VDSM main thread ended. Waiting for 1 other threads...
> MainThread::INFO::2012-05-28 03:14:56,106::vdsm::79::vds::(run) <_MainThread(MainThread, started 140708160984832)>
> MainThread::INFO::2012-05-28 03:14:56,106::vdsm::79::vds::(run) <Thread(libvirtEventLoop, started daemon 140707944273664)>
>
> node2 vdsm.log: (sorry for the large log)
> Thread-56734::DEBUG::2012-05-28 03:15:40,507::task::588::TaskManager.Task::(_updateState) Task=`5374a489-ad78-464c-93ce-3184d12fbe5b`::moving from state init -> state preparing
> Thread-56734::INFO::2012-05-28 03:15:40,508::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56734::INFO::2012-05-28 03:15:40,509::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.0014009475708', 'lastCheck': 1338174931.256155, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00122499465942', 'lastCheck': 1338174938.066188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00152397155762', 'lastCheck': 1338174936.886322, 'code': 0, 'valid': True}}
> Thread-56734::DEBUG::2012-05-28 03:15:40,509::task::1174::TaskManager.Task::(prepare) Task=`5374a489-ad78-464c-93ce-3184d12fbe5b`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.0014009475708', 'lastCheck': 1338174931.256155, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00122499465942', 'lastCheck': 1338174938.066188, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00152397155762', 'lastCheck': 1338174936.886322, 'code': 0, 'valid': True}}
> Thread-56734::DEBUG::2012-05-28 03:15:40,510::task::588::TaskManager.Task::(_updateState) Task=`5374a489-ad78-464c-93ce-3184d12fbe5b`::moving from state preparing -> state finished
> Thread-56734::DEBUG::2012-05-28 03:15:40,511::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56734::DEBUG::2012-05-28 03:15:40,511::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56734::DEBUG::2012-05-28 03:15:40,512::task::980::TaskManager.Task::(_decref) Task=`5374a489-ad78-464c-93ce-3184d12fbe5b`::ref 0 aborting False
> Thread-56736::DEBUG::2012-05-28 03:15:41,332::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56736::DEBUG::2012-05-28 03:15:41,333::task::588::TaskManager.Task::(_updateState) Task=`39c4b239-4f85-4fae-b7b3-348650268585`::moving from state init -> state preparing
> Thread-56736::INFO::2012-05-28 03:15:41,334::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56736::INFO::2012-05-28 03:15:41,335::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56736::DEBUG::2012-05-28 03:15:41,335::task::1174::TaskManager.Task::(prepare) Task=`39c4b239-4f85-4fae-b7b3-348650268585`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56736::DEBUG::2012-05-28 03:15:41,336::task::588::TaskManager.Task::(_updateState) Task=`39c4b239-4f85-4fae-b7b3-348650268585`::moving from state preparing -> state finished
> Thread-56736::DEBUG::2012-05-28 03:15:41,337::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56736::DEBUG::2012-05-28 03:15:41,337::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56736::DEBUG::2012-05-28 03:15:41,338::task::980::TaskManager.Task::(_decref) Task=`39c4b239-4f85-4fae-b7b3-348650268585`::ref 0 aborting False
> Thread-56737::DEBUG::2012-05-28 03:15:41,825::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56737::DEBUG::2012-05-28 03:15:41,826::task::588::TaskManager.Task::(_updateState) Task=`4b92f7f8-94a6-426b-b626-65aa488e3bf8`::moving from state init -> state preparing
> Thread-56737::INFO::2012-05-28 03:15:41,827::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56737::INFO::2012-05-28 03:15:41,828::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56737::DEBUG::2012-05-28 03:15:41,828::task::1174::TaskManager.Task::(prepare) Task=`4b92f7f8-94a6-426b-b626-65aa488e3bf8`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56737::DEBUG::2012-05-28 03:15:41,829::task::588::TaskManager.Task::(_updateState) Task=`4b92f7f8-94a6-426b-b626-65aa488e3bf8`::moving from state preparing -> state finished
> Thread-56737::DEBUG::2012-05-28 03:15:41,830::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56737::DEBUG::2012-05-28 03:15:41,830::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56737::DEBUG::2012-05-28 03:15:41,831::task::980::TaskManager.Task::(_decref) Task=`4b92f7f8-94a6-426b-b626-65aa488e3bf8`::ref 0 aborting False
> Thread-56738::DEBUG::2012-05-28 03:15:41,865::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56738::DEBUG::2012-05-28 03:15:41,866::task::588::TaskManager.Task::(_updateState) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::moving from state init -> state preparing
> Thread-56738::INFO::2012-05-28 03:15:41,867::logUtils::37::dispatcher::(wrapper) Run and protect: fenceSpmStorage(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', lastOwner=1, lastLver='17', options=None)
> Thread-56738::DEBUG::2012-05-28 03:15:41,868::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef`ReqID=`8281ad30-ca07-4de6-8903-244ad562c05f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2633' at 'fenceSpmStorage'
> Thread-56738::DEBUG::2012-05-28 03:15:41,869::resourceManager::483::ResourceManager::(registerResource) Trying to register resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' for lock type 'exclusive'
> Thread-56738::DEBUG::2012-05-28 03:15:41,870::resourceManager::525::ResourceManager::(registerResource) Resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' is free. Now locking as 'exclusive' (1 active user)
> Thread-56738::DEBUG::2012-05-28 03:15:41,871::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef`ReqID=`8281ad30-ca07-4de6-8903-244ad562c05f`::Granted request
> Thread-56738::DEBUG::2012-05-28 03:15:41,871::task::819::TaskManager.Task::(resourceAcquired) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::_resourcesAcquired: Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef (exclusive)
> Thread-56738::DEBUG::2012-05-28 03:15:41,871::task::980::TaskManager.Task::(_decref) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::ref 1 aborting False
> Thread-56738::ERROR::2012-05-28 03:15:41,872::task::855::TaskManager.Task::(_setError) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::Unexpected error
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/task.py", line 863, in _run
> File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
> File "/usr/share/vdsm/storage/hsm.py", line 2634, in fenceSpmStorage
> File "/usr/share/vdsm/storage/sp.py", line 150, in forceFreeSpm
> File "/usr/share/vdsm/storage/securable.py", line 78, in wrapper
> SecureError
> Thread-56738::DEBUG::2012-05-28 03:15:41,872::task::874::TaskManager.Task::(_run) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::Task._run: 8ee680b3-39b8-49ef-b756-8d374f34d97e ('524a7003-edec-4f52-a38e-b15cadfbe3ef', 1, '17') {} failed - stopping task
> Thread-56738::DEBUG::2012-05-28 03:15:41,872::task::1201::TaskManager.Task::(stop) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::stopping in state preparing (force False)
> Thread-56738::DEBUG::2012-05-28 03:15:41,872::task::980::TaskManager.Task::(_decref) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::ref 1 aborting True
> Thread-56738::INFO::2012-05-28 03:15:41,873::task::1159::TaskManager.Task::(prepare) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::aborting: Task is aborted: '' - code 100
> Thread-56738::DEBUG::2012-05-28 03:15:41,873::task::1164::TaskManager.Task::(prepare) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::Prepare: aborted:
> Thread-56738::DEBUG::2012-05-28 03:15:41,873::task::980::TaskManager.Task::(_decref) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::ref 0 aborting True
> Thread-56738::DEBUG::2012-05-28 03:15:41,873::task::915::TaskManager.Task::(_doAbort) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::Task._doAbort: force False
> Thread-56738::DEBUG::2012-05-28 03:15:41,873::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56738::DEBUG::2012-05-28 03:15:41,874::task::588::TaskManager.Task::(_updateState) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::moving from state preparing -> state aborting
> Thread-56738::DEBUG::2012-05-28 03:15:41,874::task::537::TaskManager.Task::(__state_aborting) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::_aborting: recover policy none
> Thread-56738::DEBUG::2012-05-28 03:15:41,874::task::588::TaskManager.Task::(_updateState) Task=`8ee680b3-39b8-49ef-b756-8d374f34d97e`::moving from state aborting -> state failed
> Thread-56738::DEBUG::2012-05-28 03:15:41,874::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef': < ResourceRef 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef', isValid: 'True' obj: 'None'>}
> Thread-56738::DEBUG::2012-05-28 03:15:41,874::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56738::DEBUG::2012-05-28 03:15:41,875::resourceManager::535::ResourceManager::(releaseResource) Trying to release resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef'
> Thread-56738::DEBUG::2012-05-28 03:15:41,875::resourceManager::550::ResourceManager::(releaseResource) Released resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' (0 active users)
> Thread-56738::DEBUG::2012-05-28 03:15:41,875::resourceManager::555::ResourceManager::(releaseResource) Resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef' is free, finding out if anyone is waiting for it.
> Thread-56738::DEBUG::2012-05-28 03:15:41,875::resourceManager::562::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.524a7003-edec-4f52-a38e-b15cadfbe3ef', Clearing records.
> Thread-56738::ERROR::2012-05-28 03:15:41,876::dispatcher::93::Storage.Dispatcher.Protect::(run)
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/dispatcher.py", line 85, in run
> File "/usr/share/vdsm/storage/task.py", line 1166, in prepare
> SecureError
> Thread-26::DEBUG::2012-05-28 03:15:48,077::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=VMDomain', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=BLC', 'POOL_DOMAINS=fce72110-71ae-46be-8811-2fbeaa001ed2:Active,5e2ac537-6a73-4faf-8379-68f3ff26a75d:Active,6d931187-2c83-4c33-8693-ca2570f7c136:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=17', 'POOL_UUID=524a7003-edec-4f52-a38e-b15cadfbe3ef', 'REMOTE_PATH=xxx.xxx.xxx.xxx:/export/data/Ovirt-Domain/vmdomain', 'ROLE=Master', 'SDUUID=5e2ac537-6a73-4faf-8379-68f3ff26a75d', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=a17bf026e76daae1ff911bdbbcfa13b700c93d7e']
> Thread-56743::DEBUG::2012-05-28 03:15:50,717::task::588::TaskManager.Task::(_updateState) Task=`e58fd0e1-d2ae-41ba-9906-473933b98bb5`::moving from state init -> state preparing
> Thread-56743::INFO::2012-05-28 03:15:50,718::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56743::INFO::2012-05-28 03:15:50,719::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00115013122559', 'lastCheck': 1338174941.265202, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00145602226257', 'lastCheck': 1338174948.079344, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00129413604736', 'lastCheck': 1338174946.895659, 'code': 0, 'valid': True}}
> Thread-56743::DEBUG::2012-05-28 03:15:50,720::task::1174::TaskManager.Task::(prepare) Task=`e58fd0e1-d2ae-41ba-9906-473933b98bb5`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00115013122559', 'lastCheck': 1338174941.265202, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00145602226257', 'lastCheck': 1338174948.079344, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00129413604736', 'lastCheck': 1338174946.895659, 'code': 0, 'valid': True}}
> Thread-56743::DEBUG::2012-05-28 03:15:50,721::task::588::TaskManager.Task::(_updateState) Task=`e58fd0e1-d2ae-41ba-9906-473933b98bb5`::moving from state preparing -> state finished
> Thread-56743::DEBUG::2012-05-28 03:15:50,722::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56743::DEBUG::2012-05-28 03:15:50,722::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56743::DEBUG::2012-05-28 03:15:50,723::task::980::TaskManager.Task::(_decref) Task=`e58fd0e1-d2ae-41ba-9906-473933b98bb5`::ref 0 aborting False
> Thread-56745::DEBUG::2012-05-28 03:15:51,379::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56745::DEBUG::2012-05-28 03:15:51,380::task::588::TaskManager.Task::(_updateState) Task=`38728832-84c0-45d6-9577-277bc00f4971`::moving from state init -> state preparing
> Thread-56745::INFO::2012-05-28 03:15:51,381::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56745::INFO::2012-05-28 03:15:51,382::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56745::DEBUG::2012-05-28 03:15:51,383::task::1174::TaskManager.Task::(prepare) Task=`38728832-84c0-45d6-9577-277bc00f4971`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56745::DEBUG::2012-05-28 03:15:51,383::task::588::TaskManager.Task::(_updateState) Task=`38728832-84c0-45d6-9577-277bc00f4971`::moving from state preparing -> state finished
> Thread-56745::DEBUG::2012-05-28 03:15:51,384::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56745::DEBUG::2012-05-28 03:15:51,385::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56745::DEBUG::2012-05-28 03:15:51,385::task::980::TaskManager.Task::(_decref) Task=`38728832-84c0-45d6-9577-277bc00f4971`::ref 0 aborting False
> Thread-56750::DEBUG::2012-05-28 03:16:00,916::task::588::TaskManager.Task::(_updateState) Task=`0b24e93f-a073-464b-968b-197658c4ca83`::moving from state init -> state preparing
> Thread-56750::INFO::2012-05-28 03:16:00,917::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56750::INFO::2012-05-28 03:16:00,918::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.0014750957489', 'lastCheck': 1338174951.276538, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00123810768127', 'lastCheck': 1338174958.08727, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00193691253662', 'lastCheck': 1338174956.908427, 'code': 0, 'valid': True}}
> Thread-56750::DEBUG::2012-05-28 03:16:00,919::task::1174::TaskManager.Task::(prepare) Task=`0b24e93f-a073-464b-968b-197658c4ca83`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.0014750957489', 'lastCheck': 1338174951.276538, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00123810768127', 'lastCheck': 1338174958.08727, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00193691253662', 'lastCheck': 1338174956.908427, 'code': 0, 'valid': True}}
> Thread-56750::DEBUG::2012-05-28 03:16:00,920::task::588::TaskManager.Task::(_updateState) Task=`0b24e93f-a073-464b-968b-197658c4ca83`::moving from state preparing -> state finished
> Thread-56750::DEBUG::2012-05-28 03:16:00,921::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56750::DEBUG::2012-05-28 03:16:00,921::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56750::DEBUG::2012-05-28 03:16:00,922::task::980::TaskManager.Task::(_decref) Task=`0b24e93f-a073-464b-968b-197658c4ca83`::ref 0 aborting False
> Thread-56752::DEBUG::2012-05-28 03:16:01,429::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56752::DEBUG::2012-05-28 03:16:01,430::task::588::TaskManager.Task::(_updateState) Task=`3fb01b85-0d37-4eea-935f-e82f1e2ff76b`::moving from state init -> state preparing
> Thread-56752::INFO::2012-05-28 03:16:01,431::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56752::INFO::2012-05-28 03:16:01,432::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56752::DEBUG::2012-05-28 03:16:01,433::task::1174::TaskManager.Task::(prepare) Task=`3fb01b85-0d37-4eea-935f-e82f1e2ff76b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56752::DEBUG::2012-05-28 03:16:01,433::task::588::TaskManager.Task::(_updateState) Task=`3fb01b85-0d37-4eea-935f-e82f1e2ff76b`::moving from state preparing -> state finished
> Thread-56752::DEBUG::2012-05-28 03:16:01,434::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56752::DEBUG::2012-05-28 03:16:01,435::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56752::DEBUG::2012-05-28 03:16:01,435::task::980::TaskManager.Task::(_decref) Task=`3fb01b85-0d37-4eea-935f-e82f1e2ff76b`::ref 0 aborting False
> Thread-56757::DEBUG::2012-05-28 03:16:11,132::task::588::TaskManager.Task::(_updateState) Task=`f82a5430-0985-442f-8d58-c21bb1102190`::moving from state init -> state preparing
> Thread-56757::INFO::2012-05-28 03:16:11,133::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56757::INFO::2012-05-28 03:16:11,134::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00143098831177', 'lastCheck': 1338174961.286303, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00148105621338', 'lastCheck': 1338174968.096825, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00177407264709', 'lastCheck': 1338174966.91743, 'code': 0, 'valid': True}}
> Thread-56757::DEBUG::2012-05-28 03:16:11,134::task::1174::TaskManager.Task::(prepare) Task=`f82a5430-0985-442f-8d58-c21bb1102190`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00143098831177', 'lastCheck': 1338174961.286303, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00148105621338', 'lastCheck': 1338174968.096825, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00177407264709', 'lastCheck': 1338174966.91743, 'code': 0, 'valid': True}}
> Thread-56757::DEBUG::2012-05-28 03:16:11,135::task::588::TaskManager.Task::(_updateState) Task=`f82a5430-0985-442f-8d58-c21bb1102190`::moving from state preparing -> state finished
> Thread-56757::DEBUG::2012-05-28 03:16:11,136::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56757::DEBUG::2012-05-28 03:16:11,137::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56757::DEBUG::2012-05-28 03:16:11,137::task::980::TaskManager.Task::(_decref) Task=`f82a5430-0985-442f-8d58-c21bb1102190`::ref 0 aborting False
> Thread-56759::DEBUG::2012-05-28 03:16:11,493::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56759::DEBUG::2012-05-28 03:16:11,495::task::588::TaskManager.Task::(_updateState) Task=`b5efb22f-5d5c-4780-9090-1d220fc1842f`::moving from state init -> state preparing
> Thread-56759::INFO::2012-05-28 03:16:11,495::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56759::INFO::2012-05-28 03:16:11,496::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56759::DEBUG::2012-05-28 03:16:11,497::task::1174::TaskManager.Task::(prepare) Task=`b5efb22f-5d5c-4780-9090-1d220fc1842f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56759::DEBUG::2012-05-28 03:16:11,498::task::588::TaskManager.Task::(_updateState) Task=`b5efb22f-5d5c-4780-9090-1d220fc1842f`::moving from state preparing -> state finished
> Thread-56759::DEBUG::2012-05-28 03:16:11,498::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56759::DEBUG::2012-05-28 03:16:11,499::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56759::DEBUG::2012-05-28 03:16:11,500::task::980::TaskManager.Task::(_decref) Task=`b5efb22f-5d5c-4780-9090-1d220fc1842f`::ref 0 aborting False
> Thread-56764::DEBUG::2012-05-28 03:16:21,323::task::588::TaskManager.Task::(_updateState) Task=`20c22deb-791f-4832-a37e-54a794d7f5eb`::moving from state init -> state preparing
> Thread-56764::INFO::2012-05-28 03:16:21,324::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56764::INFO::2012-05-28 03:16:21,325::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00120186805725', 'lastCheck': 1338174981.305562, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00149893760681', 'lastCheck': 1338174978.106855, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00185894966125', 'lastCheck': 1338174976.929951, 'code': 0, 'valid': True}}
> Thread-56764::DEBUG::2012-05-28 03:16:21,325::task::1174::TaskManager.Task::(prepare) Task=`20c22deb-791f-4832-a37e-54a794d7f5eb`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00120186805725', 'lastCheck': 1338174981.305562, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00149893760681', 'lastCheck': 1338174978.106855, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00185894966125', 'lastCheck': 1338174976.929951, 'code': 0, 'valid': True}}
> Thread-56764::DEBUG::2012-05-28 03:16:21,326::task::588::TaskManager.Task::(_updateState) Task=`20c22deb-791f-4832-a37e-54a794d7f5eb`::moving from state preparing -> state finished
> Thread-56764::DEBUG::2012-05-28 03:16:21,327::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56764::DEBUG::2012-05-28 03:16:21,328::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56764::DEBUG::2012-05-28 03:16:21,328::task::980::TaskManager.Task::(_decref) Task=`20c22deb-791f-4832-a37e-54a794d7f5eb`::ref 0 aborting False
> Thread-56766::DEBUG::2012-05-28 03:16:21,542::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56766::DEBUG::2012-05-28 03:16:21,543::task::588::TaskManager.Task::(_updateState) Task=`0586a277-8536-4e37-91ed-598b47286c2f`::moving from state init -> state preparing
> Thread-56766::INFO::2012-05-28 03:16:21,544::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56766::INFO::2012-05-28 03:16:21,545::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56766::DEBUG::2012-05-28 03:16:21,545::task::1174::TaskManager.Task::(prepare) Task=`0586a277-8536-4e37-91ed-598b47286c2f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56766::DEBUG::2012-05-28 03:16:21,546::task::588::TaskManager.Task::(_updateState) Task=`0586a277-8536-4e37-91ed-598b47286c2f`::moving from state preparing -> state finished
> Thread-56766::DEBUG::2012-05-28 03:16:21,547::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56766::DEBUG::2012-05-28 03:16:21,547::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56766::DEBUG::2012-05-28 03:16:21,548::task::980::TaskManager.Task::(_decref) Task=`0586a277-8536-4e37-91ed-598b47286c2f`::ref 0 aborting False
> Thread-56771::DEBUG::2012-05-28 03:16:31,521::task::588::TaskManager.Task::(_updateState) Task=`5717ab22-77fc-4b9e-9ef1-fc37d9b23b60`::moving from state init -> state preparing
> Thread-56771::INFO::2012-05-28 03:16:31,522::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56771::INFO::2012-05-28 03:16:31,523::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00146007537842', 'lastCheck': 1338174991.315921, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00130796432495', 'lastCheck': 1338174988.116432, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00182700157166', 'lastCheck': 1338174986.942698, 'code': 0, 'valid': True}}
> Thread-56771::DEBUG::2012-05-28 03:16:31,524::task::1174::TaskManager.Task::(prepare) Task=`5717ab22-77fc-4b9e-9ef1-fc37d9b23b60`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00146007537842', 'lastCheck': 1338174991.315921, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00130796432495', 'lastCheck': 1338174988.116432, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00182700157166', 'lastCheck': 1338174986.942698, 'code': 0, 'valid': True}}
> Thread-56771::DEBUG::2012-05-28 03:16:31,524::task::588::TaskManager.Task::(_updateState) Task=`5717ab22-77fc-4b9e-9ef1-fc37d9b23b60`::moving from state preparing -> state finished
> Thread-56771::DEBUG::2012-05-28 03:16:31,525::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56771::DEBUG::2012-05-28 03:16:31,526::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56771::DEBUG::2012-05-28 03:16:31,526::task::980::TaskManager.Task::(_decref) Task=`5717ab22-77fc-4b9e-9ef1-fc37d9b23b60`::ref 0 aborting False
> Thread-56773::DEBUG::2012-05-28 03:16:31,592::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56773::DEBUG::2012-05-28 03:16:31,593::task::588::TaskManager.Task::(_updateState) Task=`752dbe30-c5e5-45a3-b7e0-81a19564ec4f`::moving from state init -> state preparing
> Thread-56773::INFO::2012-05-28 03:16:31,594::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56773::INFO::2012-05-28 03:16:31,595::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56773::DEBUG::2012-05-28 03:16:31,596::task::1174::TaskManager.Task::(prepare) Task=`752dbe30-c5e5-45a3-b7e0-81a19564ec4f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56773::DEBUG::2012-05-28 03:16:31,596::task::588::TaskManager.Task::(_updateState) Task=`752dbe30-c5e5-45a3-b7e0-81a19564ec4f`::moving from state preparing -> state finished
> Thread-56773::DEBUG::2012-05-28 03:16:31,597::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56773::DEBUG::2012-05-28 03:16:31,598::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56773::DEBUG::2012-05-28 03:16:31,598::task::980::TaskManager.Task::(_decref) Task=`752dbe30-c5e5-45a3-b7e0-81a19564ec4f`::ref 0 aborting False
> Thread-56778::DEBUG::2012-05-28 03:16:41,641::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56778::DEBUG::2012-05-28 03:16:41,643::task::588::TaskManager.Task::(_updateState) Task=`5b9dcf88-4aaf-4649-8895-4c1d9bfcc2db`::moving from state init -> state preparing
> Thread-56778::INFO::2012-05-28 03:16:41,643::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56778::INFO::2012-05-28 03:16:41,644::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56778::DEBUG::2012-05-28 03:16:41,645::task::1174::TaskManager.Task::(prepare) Task=`5b9dcf88-4aaf-4649-8895-4c1d9bfcc2db`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56778::DEBUG::2012-05-28 03:16:41,646::task::588::TaskManager.Task::(_updateState) Task=`5b9dcf88-4aaf-4649-8895-4c1d9bfcc2db`::moving from state preparing -> state finished
> Thread-56778::DEBUG::2012-05-28 03:16:41,646::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56778::DEBUG::2012-05-28 03:16:41,647::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56778::DEBUG::2012-05-28 03:16:41,648::task::980::TaskManager.Task::(_decref) Task=`5b9dcf88-4aaf-4649-8895-4c1d9bfcc2db`::ref 0 aborting False
> Thread-56779::DEBUG::2012-05-28 03:16:41,731::task::588::TaskManager.Task::(_updateState) Task=`f3855ff9-49dc-4da1-ab42-3f717ca2242f`::moving from state init -> state preparing
> Thread-56779::INFO::2012-05-28 03:16:41,732::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56779::INFO::2012-05-28 03:16:41,733::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00130009651184', 'lastCheck': 1338175001.325553, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0015070438385', 'lastCheck': 1338174998.126787, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00195598602295', 'lastCheck': 1338174996.955508, 'code': 0, 'valid': True}}
> Thread-56779::DEBUG::2012-05-28 03:16:41,734::task::1174::TaskManager.Task::(prepare) Task=`f3855ff9-49dc-4da1-ab42-3f717ca2242f`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00130009651184', 'lastCheck': 1338175001.325553, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0015070438385', 'lastCheck': 1338174998.126787, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00195598602295', 'lastCheck': 1338174996.955508, 'code': 0, 'valid': True}}
> Thread-56779::DEBUG::2012-05-28 03:16:41,735::task::588::TaskManager.Task::(_updateState) Task=`f3855ff9-49dc-4da1-ab42-3f717ca2242f`::moving from state preparing -> state finished
> Thread-56779::DEBUG::2012-05-28 03:16:41,736::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56779::DEBUG::2012-05-28 03:16:41,736::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56779::DEBUG::2012-05-28 03:16:41,737::task::980::TaskManager.Task::(_decref) Task=`f3855ff9-49dc-4da1-ab42-3f717ca2242f`::ref 0 aborting False
> Thread-56785::DEBUG::2012-05-28 03:16:51,691::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56785::DEBUG::2012-05-28 03:16:51,693::task::588::TaskManager.Task::(_updateState) Task=`f7791e70-ed9d-438f-b90a-6de44ccc77df`::moving from state init -> state preparing
> Thread-56785::INFO::2012-05-28 03:16:51,693::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56785::INFO::2012-05-28 03:16:51,694::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56785::DEBUG::2012-05-28 03:16:51,695::task::1174::TaskManager.Task::(prepare) Task=`f7791e70-ed9d-438f-b90a-6de44ccc77df`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56785::DEBUG::2012-05-28 03:16:51,696::task::588::TaskManager.Task::(_updateState) Task=`f7791e70-ed9d-438f-b90a-6de44ccc77df`::moving from state preparing -> state finished
> Thread-56785::DEBUG::2012-05-28 03:16:51,696::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56785::DEBUG::2012-05-28 03:16:51,697::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56785::DEBUG::2012-05-28 03:16:51,698::task::980::TaskManager.Task::(_decref) Task=`f7791e70-ed9d-438f-b90a-6de44ccc77df`::ref 0 aborting False
> Thread-56786::DEBUG::2012-05-28 03:16:51,943::task::588::TaskManager.Task::(_updateState) Task=`ae37d8af-31d5-4248-8109-0c5edc0eeb72`::moving from state init -> state preparing
> Thread-56786::INFO::2012-05-28 03:16:51,943::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56786::INFO::2012-05-28 03:16:51,944::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00257992744446', 'lastCheck': 1338175011.337062, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00142002105713', 'lastCheck': 1338175008.138333, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0016028881073', 'lastCheck': 1338175006.965758, 'code': 0, 'valid': True}}
> Thread-56786::DEBUG::2012-05-28 03:16:51,945::task::1174::TaskManager.Task::(prepare) Task=`ae37d8af-31d5-4248-8109-0c5edc0eeb72`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00257992744446', 'lastCheck': 1338175011.337062, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00142002105713', 'lastCheck': 1338175008.138333, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0016028881073', 'lastCheck': 1338175006.965758, 'code': 0, 'valid': True}}
> Thread-56786::DEBUG::2012-05-28 03:16:51,946::task::588::TaskManager.Task::(_updateState) Task=`ae37d8af-31d5-4248-8109-0c5edc0eeb72`::moving from state preparing -> state finished
> Thread-56786::DEBUG::2012-05-28 03:16:51,947::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56786::DEBUG::2012-05-28 03:16:51,947::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56786::DEBUG::2012-05-28 03:16:51,948::task::980::TaskManager.Task::(_decref) Task=`ae37d8af-31d5-4248-8109-0c5edc0eeb72`::ref 0 aborting False
> Thread-56792::DEBUG::2012-05-28 03:17:01,741::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56792::DEBUG::2012-05-28 03:17:01,742::task::588::TaskManager.Task::(_updateState) Task=`2efcfeb7-a6c1-432f-b09e-3409520a5f89`::moving from state init -> state preparing
> Thread-56792::INFO::2012-05-28 03:17:01,743::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56792::INFO::2012-05-28 03:17:01,744::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56792::DEBUG::2012-05-28 03:17:01,744::task::1174::TaskManager.Task::(prepare) Task=`2efcfeb7-a6c1-432f-b09e-3409520a5f89`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56792::DEBUG::2012-05-28 03:17:01,745::task::588::TaskManager.Task::(_updateState) Task=`2efcfeb7-a6c1-432f-b09e-3409520a5f89`::moving from state preparing -> state finished
> Thread-56792::DEBUG::2012-05-28 03:17:01,746::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56792::DEBUG::2012-05-28 03:17:01,746::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56792::DEBUG::2012-05-28 03:17:01,747::task::980::TaskManager.Task::(_decref) Task=`2efcfeb7-a6c1-432f-b09e-3409520a5f89`::ref 0 aborting False
> Thread-56793::DEBUG::2012-05-28 03:17:02,137::task::588::TaskManager.Task::(_updateState) Task=`513c7e7e-7a78-4fc6-a497-d4810bd35c08`::moving from state init -> state preparing
> Thread-56793::INFO::2012-05-28 03:17:02,138::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56793::INFO::2012-05-28 03:17:02,139::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00146794319153', 'lastCheck': 1338175021.346104, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00128602981567', 'lastCheck': 1338175018.146864, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00149917602539', 'lastCheck': 1338175016.975937, 'code': 0, 'valid': True}}
> Thread-56793::DEBUG::2012-05-28 03:17:02,140::task::1174::TaskManager.Task::(prepare) Task=`513c7e7e-7a78-4fc6-a497-d4810bd35c08`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00146794319153', 'lastCheck': 1338175021.346104, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00128602981567', 'lastCheck': 1338175018.146864, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00149917602539', 'lastCheck': 1338175016.975937, 'code': 0, 'valid': True}}
> Thread-56793::DEBUG::2012-05-28 03:17:02,141::task::588::TaskManager.Task::(_updateState) Task=`513c7e7e-7a78-4fc6-a497-d4810bd35c08`::moving from state preparing -> state finished
> Thread-56793::DEBUG::2012-05-28 03:17:02,141::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56793::DEBUG::2012-05-28 03:17:02,142::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56793::DEBUG::2012-05-28 03:17:02,143::task::980::TaskManager.Task::(_decref) Task=`513c7e7e-7a78-4fc6-a497-d4810bd35c08`::ref 0 aborting False
> Thread-56799::DEBUG::2012-05-28 03:17:11,789::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56799::DEBUG::2012-05-28 03:17:11,790::task::588::TaskManager.Task::(_updateState) Task=`f4493a0e-87ed-49df-bb50-ff78c781c686`::moving from state init -> state preparing
> Thread-56799::INFO::2012-05-28 03:17:11,791::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56799::INFO::2012-05-28 03:17:11,792::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56799::DEBUG::2012-05-28 03:17:11,792::task::1174::TaskManager.Task::(prepare) Task=`f4493a0e-87ed-49df-bb50-ff78c781c686`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56799::DEBUG::2012-05-28 03:17:11,793::task::588::TaskManager.Task::(_updateState) Task=`f4493a0e-87ed-49df-bb50-ff78c781c686`::moving from state preparing -> state finished
> Thread-56799::DEBUG::2012-05-28 03:17:11,794::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56799::DEBUG::2012-05-28 03:17:11,794::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56799::DEBUG::2012-05-28 03:17:11,795::task::980::TaskManager.Task::(_decref) Task=`f4493a0e-87ed-49df-bb50-ff78c781c686`::ref 0 aborting False
> Thread-56800::DEBUG::2012-05-28 03:17:12,334::task::588::TaskManager.Task::(_updateState) Task=`1ea724d6-c05e-46f5-bd1c-dab69d7dd1dc`::moving from state init -> state preparing
> Thread-56800::INFO::2012-05-28 03:17:12,334::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56800::INFO::2012-05-28 03:17:12,335::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00105905532837', 'lastCheck': 1338175031.355215, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00141787528992', 'lastCheck': 1338175028.156488, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00145602226257', 'lastCheck': 1338175026.986184, 'code': 0, 'valid': True}}
> Thread-56800::DEBUG::2012-05-28 03:17:12,336::task::1174::TaskManager.Task::(prepare) Task=`1ea724d6-c05e-46f5-bd1c-dab69d7dd1dc`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00105905532837', 'lastCheck': 1338175031.355215, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00141787528992', 'lastCheck': 1338175028.156488, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00145602226257', 'lastCheck': 1338175026.986184, 'code': 0, 'valid': True}}
> Thread-56800::DEBUG::2012-05-28 03:17:12,337::task::588::TaskManager.Task::(_updateState) Task=`1ea724d6-c05e-46f5-bd1c-dab69d7dd1dc`::moving from state preparing -> state finished
> Thread-56800::DEBUG::2012-05-28 03:17:12,338::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56800::DEBUG::2012-05-28 03:17:12,338::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56800::DEBUG::2012-05-28 03:17:12,339::task::980::TaskManager.Task::(_decref) Task=`1ea724d6-c05e-46f5-bd1c-dab69d7dd1dc`::ref 0 aborting False
> Thread-56806::DEBUG::2012-05-28 03:17:21,831::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56806::DEBUG::2012-05-28 03:17:21,832::task::588::TaskManager.Task::(_updateState) Task=`06654530-d2e3-4dec-a811-10bd4b4e7c70`::moving from state init -> state preparing
> Thread-56806::INFO::2012-05-28 03:17:21,833::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56806::INFO::2012-05-28 03:17:21,834::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56806::DEBUG::2012-05-28 03:17:21,835::task::1174::TaskManager.Task::(prepare) Task=`06654530-d2e3-4dec-a811-10bd4b4e7c70`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56806::DEBUG::2012-05-28 03:17:21,835::task::588::TaskManager.Task::(_updateState) Task=`06654530-d2e3-4dec-a811-10bd4b4e7c70`::moving from state preparing -> state finished
> Thread-56806::DEBUG::2012-05-28 03:17:21,836::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56806::DEBUG::2012-05-28 03:17:21,836::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56806::DEBUG::2012-05-28 03:17:21,837::task::980::TaskManager.Task::(_decref) Task=`06654530-d2e3-4dec-a811-10bd4b4e7c70`::ref 0 aborting False
> Thread-56807::DEBUG::2012-05-28 03:17:22,541::task::588::TaskManager.Task::(_updateState) Task=`49132eb7-1f0c-4e1a-bb1a-719e8687e3e5`::moving from state init -> state preparing
> Thread-56807::INFO::2012-05-28 03:17:22,542::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56807::INFO::2012-05-28 03:17:22,543::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00123596191406', 'lastCheck': 1338175041.36586, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00138688087463', 'lastCheck': 1338175038.1667, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00125789642334', 'lastCheck': 1338175036.996167, 'code': 0, 'valid': True}}
> Thread-56807::DEBUG::2012-05-28 03:17:22,544::task::1174::TaskManager.Task::(prepare) Task=`49132eb7-1f0c-4e1a-bb1a-719e8687e3e5`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00123596191406', 'lastCheck': 1338175041.36586, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00138688087463', 'lastCheck': 1338175038.1667, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00125789642334', 'lastCheck': 1338175036.996167, 'code': 0, 'valid': True}}
> Thread-56807::DEBUG::2012-05-28 03:17:22,545::task::588::TaskManager.Task::(_updateState) Task=`49132eb7-1f0c-4e1a-bb1a-719e8687e3e5`::moving from state preparing -> state finished
> Thread-56807::DEBUG::2012-05-28 03:17:22,545::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56807::DEBUG::2012-05-28 03:17:22,546::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56807::DEBUG::2012-05-28 03:17:22,547::task::980::TaskManager.Task::(_decref) Task=`49132eb7-1f0c-4e1a-bb1a-719e8687e3e5`::ref 0 aborting False
> Thread-56813::DEBUG::2012-05-28 03:17:31,886::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56813::DEBUG::2012-05-28 03:17:31,887::task::588::TaskManager.Task::(_updateState) Task=`656dcbf2-61d2-41c8-b13b-246fc3f42320`::moving from state init -> state preparing
> Thread-56813::INFO::2012-05-28 03:17:31,888::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56813::INFO::2012-05-28 03:17:31,889::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56813::DEBUG::2012-05-28 03:17:31,889::task::1174::TaskManager.Task::(prepare) Task=`656dcbf2-61d2-41c8-b13b-246fc3f42320`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56813::DEBUG::2012-05-28 03:17:31,890::task::588::TaskManager.Task::(_updateState) Task=`656dcbf2-61d2-41c8-b13b-246fc3f42320`::moving from state preparing -> state finished
> Thread-56813::DEBUG::2012-05-28 03:17:31,891::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56813::DEBUG::2012-05-28 03:17:31,891::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56813::DEBUG::2012-05-28 03:17:31,892::task::980::TaskManager.Task::(_decref) Task=`656dcbf2-61d2-41c8-b13b-246fc3f42320`::ref 0 aborting False
> Thread-56814::DEBUG::2012-05-28 03:17:32,738::task::588::TaskManager.Task::(_updateState) Task=`53ace160-1b3c-4a73-9f0c-7f65e79b7956`::moving from state init -> state preparing
> Thread-56814::INFO::2012-05-28 03:17:32,739::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56814::INFO::2012-05-28 03:17:32,740::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141310691833', 'lastCheck': 1338175051.375892, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00151896476746', 'lastCheck': 1338175048.176782, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00130605697632', 'lastCheck': 1338175047.005668, 'code': 0, 'valid': True}}
> Thread-56814::DEBUG::2012-05-28 03:17:32,741::task::1174::TaskManager.Task::(prepare) Task=`53ace160-1b3c-4a73-9f0c-7f65e79b7956`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141310691833', 'lastCheck': 1338175051.375892, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00151896476746', 'lastCheck': 1338175048.176782, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00130605697632', 'lastCheck': 1338175047.005668, 'code': 0, 'valid': True}}
> Thread-56814::DEBUG::2012-05-28 03:17:32,742::task::588::TaskManager.Task::(_updateState) Task=`53ace160-1b3c-4a73-9f0c-7f65e79b7956`::moving from state preparing -> state finished
> Thread-56814::DEBUG::2012-05-28 03:17:32,742::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56814::DEBUG::2012-05-28 03:17:32,743::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56814::DEBUG::2012-05-28 03:17:32,743::task::980::TaskManager.Task::(_decref) Task=`53ace160-1b3c-4a73-9f0c-7f65e79b7956`::ref 0 aborting False
> Thread-56820::DEBUG::2012-05-28 03:17:41,934::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56820::DEBUG::2012-05-28 03:17:41,936::task::588::TaskManager.Task::(_updateState) Task=`f269aaa5-ae89-40f3-a3d9-6eeba3363fff`::moving from state init -> state preparing
> Thread-56820::INFO::2012-05-28 03:17:41,936::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56820::INFO::2012-05-28 03:17:41,937::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56820::DEBUG::2012-05-28 03:17:41,938::task::1174::TaskManager.Task::(prepare) Task=`f269aaa5-ae89-40f3-a3d9-6eeba3363fff`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56820::DEBUG::2012-05-28 03:17:41,939::task::588::TaskManager.Task::(_updateState) Task=`f269aaa5-ae89-40f3-a3d9-6eeba3363fff`::moving from state preparing -> state finished
> Thread-56820::DEBUG::2012-05-28 03:17:41,939::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56820::DEBUG::2012-05-28 03:17:41,940::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56820::DEBUG::2012-05-28 03:17:41,941::task::980::TaskManager.Task::(_decref) Task=`f269aaa5-ae89-40f3-a3d9-6eeba3363fff`::ref 0 aborting False
> Thread-56821::DEBUG::2012-05-28 03:17:42,936::task::588::TaskManager.Task::(_updateState) Task=`48656e47-318b-431c-9a65-3497cf116647`::moving from state init -> state preparing
> Thread-56821::INFO::2012-05-28 03:17:42,937::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56821::INFO::2012-05-28 03:17:42,938::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00127100944519', 'lastCheck': 1338175061.385365, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00120496749878', 'lastCheck': 1338175058.186244, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0014979839325', 'lastCheck': 1338175057.016019, 'code': 0, 'valid': True}}
> Thread-56821::DEBUG::2012-05-28 03:17:42,939::task::1174::TaskManager.Task::(prepare) Task=`48656e47-318b-431c-9a65-3497cf116647`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00127100944519', 'lastCheck': 1338175061.385365, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00120496749878', 'lastCheck': 1338175058.186244, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0014979839325', 'lastCheck': 1338175057.016019, 'code': 0, 'valid': True}}
> Thread-56821::DEBUG::2012-05-28 03:17:42,940::task::588::TaskManager.Task::(_updateState) Task=`48656e47-318b-431c-9a65-3497cf116647`::moving from state preparing -> state finished
> Thread-56821::DEBUG::2012-05-28 03:17:42,940::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56821::DEBUG::2012-05-28 03:17:42,941::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56821::DEBUG::2012-05-28 03:17:42,942::task::980::TaskManager.Task::(_decref) Task=`48656e47-318b-431c-9a65-3497cf116647`::ref 0 aborting False
> Thread-56827::DEBUG::2012-05-28 03:17:51,988::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56827::DEBUG::2012-05-28 03:17:51,989::task::588::TaskManager.Task::(_updateState) Task=`c7ebbcac-9438-40b0-997c-27bdbda50bdb`::moving from state init -> state preparing
> Thread-56827::INFO::2012-05-28 03:17:51,990::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56827::INFO::2012-05-28 03:17:51,991::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56827::DEBUG::2012-05-28 03:17:51,992::task::1174::TaskManager.Task::(prepare) Task=`c7ebbcac-9438-40b0-997c-27bdbda50bdb`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56827::DEBUG::2012-05-28 03:17:51,992::task::588::TaskManager.Task::(_updateState) Task=`c7ebbcac-9438-40b0-997c-27bdbda50bdb`::moving from state preparing -> state finished
> Thread-56827::DEBUG::2012-05-28 03:17:51,993::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56827::DEBUG::2012-05-28 03:17:51,994::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56827::DEBUG::2012-05-28 03:17:51,994::task::980::TaskManager.Task::(_decref) Task=`c7ebbcac-9438-40b0-997c-27bdbda50bdb`::ref 0 aborting False
> Thread-56828::DEBUG::2012-05-28 03:17:53,151::task::588::TaskManager.Task::(_updateState) Task=`23acd09a-65bb-4f83-b2b0-3676140b0cda`::moving from state init -> state preparing
> Thread-56828::INFO::2012-05-28 03:17:53,152::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56828::INFO::2012-05-28 03:17:53,153::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00128722190857', 'lastCheck': 1338175071.395135, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00151491165161', 'lastCheck': 1338175068.197441, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00175714492798', 'lastCheck': 1338175067.028897, 'code': 0, 'valid': True}}
> Thread-56828::DEBUG::2012-05-28 03:17:53,153::task::1174::TaskManager.Task::(prepare) Task=`23acd09a-65bb-4f83-b2b0-3676140b0cda`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00128722190857', 'lastCheck': 1338175071.395135, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00151491165161', 'lastCheck': 1338175068.197441, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00175714492798', 'lastCheck': 1338175067.028897, 'code': 0, 'valid': True}}
> Thread-56828::DEBUG::2012-05-28 03:17:53,154::task::588::TaskManager.Task::(_updateState) Task=`23acd09a-65bb-4f83-b2b0-3676140b0cda`::moving from state preparing -> state finished
> Thread-56828::DEBUG::2012-05-28 03:17:53,155::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56828::DEBUG::2012-05-28 03:17:53,155::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56828::DEBUG::2012-05-28 03:17:53,156::task::980::TaskManager.Task::(_decref) Task=`23acd09a-65bb-4f83-b2b0-3676140b0cda`::ref 0 aborting False
> Thread-56834::DEBUG::2012-05-28 03:18:02,038::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56834::DEBUG::2012-05-28 03:18:02,039::task::588::TaskManager.Task::(_updateState) Task=`a0f11dce-81fa-4be6-aa84-d0fdc9976be4`::moving from state init -> state preparing
> Thread-56834::INFO::2012-05-28 03:18:02,040::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56834::INFO::2012-05-28 03:18:02,041::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56834::DEBUG::2012-05-28 03:18:02,042::task::1174::TaskManager.Task::(prepare) Task=`a0f11dce-81fa-4be6-aa84-d0fdc9976be4`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56834::DEBUG::2012-05-28 03:18:02,042::task::588::TaskManager.Task::(_updateState) Task=`a0f11dce-81fa-4be6-aa84-d0fdc9976be4`::moving from state preparing -> state finished
> Thread-56834::DEBUG::2012-05-28 03:18:02,043::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56834::DEBUG::2012-05-28 03:18:02,044::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56834::DEBUG::2012-05-28 03:18:02,044::task::980::TaskManager.Task::(_decref) Task=`a0f11dce-81fa-4be6-aa84-d0fdc9976be4`::ref 0 aborting False
> Thread-56835::DEBUG::2012-05-28 03:18:03,344::task::588::TaskManager.Task::(_updateState) Task=`f4f68b23-3ccc-4435-acbe-d843ec15f315`::moving from state init -> state preparing
> Thread-56835::INFO::2012-05-28 03:18:03,345::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56835::INFO::2012-05-28 03:18:03,346::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142383575439', 'lastCheck': 1338175081.405448, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0016040802002', 'lastCheck': 1338175078.207242, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00149083137512', 'lastCheck': 1338175077.036792, 'code': 0, 'valid': True}}
> Thread-56835::DEBUG::2012-05-28 03:18:03,346::task::1174::TaskManager.Task::(prepare) Task=`f4f68b23-3ccc-4435-acbe-d843ec15f315`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142383575439', 'lastCheck': 1338175081.405448, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0016040802002', 'lastCheck': 1338175078.207242, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00149083137512', 'lastCheck': 1338175077.036792, 'code': 0, 'valid': True}}
> Thread-56835::DEBUG::2012-05-28 03:18:03,347::task::588::TaskManager.Task::(_updateState) Task=`f4f68b23-3ccc-4435-acbe-d843ec15f315`::moving from state preparing -> state finished
> Thread-56835::DEBUG::2012-05-28 03:18:03,348::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56835::DEBUG::2012-05-28 03:18:03,348::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56835::DEBUG::2012-05-28 03:18:03,349::task::980::TaskManager.Task::(_decref) Task=`f4f68b23-3ccc-4435-acbe-d843ec15f315`::ref 0 aborting False
> Thread-56841::DEBUG::2012-05-28 03:18:12,087::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56841::DEBUG::2012-05-28 03:18:12,088::task::588::TaskManager.Task::(_updateState) Task=`e2c3fe37-a5d1-4263-a2c1-d59301959374`::moving from state init -> state preparing
> Thread-56841::INFO::2012-05-28 03:18:12,089::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56841::INFO::2012-05-28 03:18:12,090::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56841::DEBUG::2012-05-28 03:18:12,090::task::1174::TaskManager.Task::(prepare) Task=`e2c3fe37-a5d1-4263-a2c1-d59301959374`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56841::DEBUG::2012-05-28 03:18:12,091::task::588::TaskManager.Task::(_updateState) Task=`e2c3fe37-a5d1-4263-a2c1-d59301959374`::moving from state preparing -> state finished
> Thread-56841::DEBUG::2012-05-28 03:18:12,092::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56841::DEBUG::2012-05-28 03:18:12,092::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56841::DEBUG::2012-05-28 03:18:12,093::task::980::TaskManager.Task::(_decref) Task=`e2c3fe37-a5d1-4263-a2c1-d59301959374`::ref 0 aborting False
> Thread-56842::DEBUG::2012-05-28 03:18:13,554::task::588::TaskManager.Task::(_updateState) Task=`c7a32a44-9030-4f03-aadf-267e368c6417`::moving from state init -> state preparing
> Thread-56842::INFO::2012-05-28 03:18:13,554::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56842::INFO::2012-05-28 03:18:13,556::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00156211853027', 'lastCheck': 1338175091.415912, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00146508216858', 'lastCheck': 1338175088.21675, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00190496444702', 'lastCheck': 1338175087.049977, 'code': 0, 'valid': True}}
> Thread-56842::DEBUG::2012-05-28 03:18:13,556::task::1174::TaskManager.Task::(prepare) Task=`c7a32a44-9030-4f03-aadf-267e368c6417`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00156211853027', 'lastCheck': 1338175091.415912, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00146508216858', 'lastCheck': 1338175088.21675, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00190496444702', 'lastCheck': 1338175087.049977, 'code': 0, 'valid': True}}
> Thread-56842::DEBUG::2012-05-28 03:18:13,557::task::588::TaskManager.Task::(_updateState) Task=`c7a32a44-9030-4f03-aadf-267e368c6417`::moving from state preparing -> state finished
> Thread-56842::DEBUG::2012-05-28 03:18:13,558::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56842::DEBUG::2012-05-28 03:18:13,558::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56842::DEBUG::2012-05-28 03:18:13,559::task::980::TaskManager.Task::(_decref) Task=`c7a32a44-9030-4f03-aadf-267e368c6417`::ref 0 aborting False
> Thread-56848::DEBUG::2012-05-28 03:18:22,136::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56848::DEBUG::2012-05-28 03:18:22,137::task::588::TaskManager.Task::(_updateState) Task=`f558b4e9-8c18-44eb-8690-ba0e44f2f667`::moving from state init -> state preparing
> Thread-56848::INFO::2012-05-28 03:18:22,138::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56848::INFO::2012-05-28 03:18:22,139::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56848::DEBUG::2012-05-28 03:18:22,139::task::1174::TaskManager.Task::(prepare) Task=`f558b4e9-8c18-44eb-8690-ba0e44f2f667`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56848::DEBUG::2012-05-28 03:18:22,140::task::588::TaskManager.Task::(_updateState) Task=`f558b4e9-8c18-44eb-8690-ba0e44f2f667`::moving from state preparing -> state finished
> Thread-56848::DEBUG::2012-05-28 03:18:22,141::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56848::DEBUG::2012-05-28 03:18:22,141::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56848::DEBUG::2012-05-28 03:18:22,142::task::980::TaskManager.Task::(_decref) Task=`f558b4e9-8c18-44eb-8690-ba0e44f2f667`::ref 0 aborting False
> Thread-56849::DEBUG::2012-05-28 03:18:23,747::task::588::TaskManager.Task::(_updateState) Task=`782848e8-5784-4eb6-a962-12a8ca573d8c`::moving from state init -> state preparing
> Thread-56849::INFO::2012-05-28 03:18:23,748::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56849::INFO::2012-05-28 03:18:23,749::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00139188766479', 'lastCheck': 1338175101.425565, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00169515609741', 'lastCheck': 1338175098.227214, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00200009346008', 'lastCheck': 1338175097.062642, 'code': 0, 'valid': True}}
> Thread-56849::DEBUG::2012-05-28 03:18:23,750::task::1174::TaskManager.Task::(prepare) Task=`782848e8-5784-4eb6-a962-12a8ca573d8c`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00139188766479', 'lastCheck': 1338175101.425565, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00169515609741', 'lastCheck': 1338175098.227214, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00200009346008', 'lastCheck': 1338175097.062642, 'code': 0, 'valid': True}}
> Thread-56849::DEBUG::2012-05-28 03:18:23,751::task::588::TaskManager.Task::(_updateState) Task=`782848e8-5784-4eb6-a962-12a8ca573d8c`::moving from state preparing -> state finished
> Thread-56849::DEBUG::2012-05-28 03:18:23,751::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56849::DEBUG::2012-05-28 03:18:23,752::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56849::DEBUG::2012-05-28 03:18:23,753::task::980::TaskManager.Task::(_decref) Task=`782848e8-5784-4eb6-a962-12a8ca573d8c`::ref 0 aborting False
> Thread-56855::DEBUG::2012-05-28 03:18:32,184::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56855::DEBUG::2012-05-28 03:18:32,185::task::588::TaskManager.Task::(_updateState) Task=`7995b9b1-34ec-4c00-bd20-5d522c60969d`::moving from state init -> state preparing
> Thread-56855::INFO::2012-05-28 03:18:32,186::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56855::INFO::2012-05-28 03:18:32,187::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56855::DEBUG::2012-05-28 03:18:32,188::task::1174::TaskManager.Task::(prepare) Task=`7995b9b1-34ec-4c00-bd20-5d522c60969d`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56855::DEBUG::2012-05-28 03:18:32,188::task::588::TaskManager.Task::(_updateState) Task=`7995b9b1-34ec-4c00-bd20-5d522c60969d`::moving from state preparing -> state finished
> Thread-56855::DEBUG::2012-05-28 03:18:32,189::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56855::DEBUG::2012-05-28 03:18:32,190::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56855::DEBUG::2012-05-28 03:18:32,190::task::980::TaskManager.Task::(_decref) Task=`7995b9b1-34ec-4c00-bd20-5d522c60969d`::ref 0 aborting False
> Thread-56856::DEBUG::2012-05-28 03:18:33,943::task::588::TaskManager.Task::(_updateState) Task=`6f40f32e-5510-4c96-9f45-40bd2f42c3d8`::moving from state init -> state preparing
> Thread-56856::INFO::2012-05-28 03:18:33,944::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56856::INFO::2012-05-28 03:18:33,945::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142502784729', 'lastCheck': 1338175111.435746, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00128602981567', 'lastCheck': 1338175108.236528, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00130701065063', 'lastCheck': 1338175107.074024, 'code': 0, 'valid': True}}
> Thread-56856::DEBUG::2012-05-28 03:18:33,946::task::1174::TaskManager.Task::(prepare) Task=`6f40f32e-5510-4c96-9f45-40bd2f42c3d8`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142502784729', 'lastCheck': 1338175111.435746, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00128602981567', 'lastCheck': 1338175108.236528, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00130701065063', 'lastCheck': 1338175107.074024, 'code': 0, 'valid': True}}
> Thread-56856::DEBUG::2012-05-28 03:18:33,947::task::588::TaskManager.Task::(_updateState) Task=`6f40f32e-5510-4c96-9f45-40bd2f42c3d8`::moving from state preparing -> state finished
> Thread-56856::DEBUG::2012-05-28 03:18:33,947::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56856::DEBUG::2012-05-28 03:18:33,948::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56856::DEBUG::2012-05-28 03:18:33,949::task::980::TaskManager.Task::(_decref) Task=`6f40f32e-5510-4c96-9f45-40bd2f42c3d8`::ref 0 aborting False
> Thread-56862::DEBUG::2012-05-28 03:18:42,266::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56862::DEBUG::2012-05-28 03:18:42,267::task::588::TaskManager.Task::(_updateState) Task=`662900fd-250b-4326-983d-e2a68f4953c3`::moving from state init -> state preparing
> Thread-56862::INFO::2012-05-28 03:18:42,268::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56862::INFO::2012-05-28 03:18:42,269::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56862::DEBUG::2012-05-28 03:18:42,270::task::1174::TaskManager.Task::(prepare) Task=`662900fd-250b-4326-983d-e2a68f4953c3`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56862::DEBUG::2012-05-28 03:18:42,271::task::588::TaskManager.Task::(_updateState) Task=`662900fd-250b-4326-983d-e2a68f4953c3`::moving from state preparing -> state finished
> Thread-56862::DEBUG::2012-05-28 03:18:42,271::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56862::DEBUG::2012-05-28 03:18:42,272::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56862::DEBUG::2012-05-28 03:18:42,273::task::980::TaskManager.Task::(_decref) Task=`662900fd-250b-4326-983d-e2a68f4953c3`::ref 0 aborting False
> Thread-56863::DEBUG::2012-05-28 03:18:44,136::task::588::TaskManager.Task::(_updateState) Task=`cdcef619-d7f2-4e60-a99a-97a30045738c`::moving from state init -> state preparing
> Thread-56863::INFO::2012-05-28 03:18:44,137::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56863::INFO::2012-05-28 03:18:44,138::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141000747681', 'lastCheck': 1338175121.445622, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0010199546814', 'lastCheck': 1338175118.245903, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00184297561646', 'lastCheck': 1338175117.086533, 'code': 0, 'valid': True}}
> Thread-56863::DEBUG::2012-05-28 03:18:44,138::task::1174::TaskManager.Task::(prepare) Task=`cdcef619-d7f2-4e60-a99a-97a30045738c`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141000747681', 'lastCheck': 1338175121.445622, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0010199546814', 'lastCheck': 1338175118.245903, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00184297561646', 'lastCheck': 1338175117.086533, 'code': 0, 'valid': True}}
> Thread-56863::DEBUG::2012-05-28 03:18:44,139::task::588::TaskManager.Task::(_updateState) Task=`cdcef619-d7f2-4e60-a99a-97a30045738c`::moving from state preparing -> state finished
> Thread-56863::DEBUG::2012-05-28 03:18:44,140::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56863::DEBUG::2012-05-28 03:18:44,140::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56863::DEBUG::2012-05-28 03:18:44,141::task::980::TaskManager.Task::(_decref) Task=`cdcef619-d7f2-4e60-a99a-97a30045738c`::ref 0 aborting False
> Thread-56869::DEBUG::2012-05-28 03:18:52,315::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56869::DEBUG::2012-05-28 03:18:52,316::task::588::TaskManager.Task::(_updateState) Task=`eb89f547-bb0d-482d-a2ac-fe19af1cc6bc`::moving from state init -> state preparing
> Thread-56869::INFO::2012-05-28 03:18:52,317::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56869::INFO::2012-05-28 03:18:52,318::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56869::DEBUG::2012-05-28 03:18:52,318::task::1174::TaskManager.Task::(prepare) Task=`eb89f547-bb0d-482d-a2ac-fe19af1cc6bc`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56869::DEBUG::2012-05-28 03:18:52,319::task::588::TaskManager.Task::(_updateState) Task=`eb89f547-bb0d-482d-a2ac-fe19af1cc6bc`::moving from state preparing -> state finished
> Thread-56869::DEBUG::2012-05-28 03:18:52,320::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56869::DEBUG::2012-05-28 03:18:52,320::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56869::DEBUG::2012-05-28 03:18:52,321::task::980::TaskManager.Task::(_decref) Task=`eb89f547-bb0d-482d-a2ac-fe19af1cc6bc`::ref 0 aborting False
> Thread-56870::DEBUG::2012-05-28 03:18:54,326::task::588::TaskManager.Task::(_updateState) Task=`aa4bc4bb-f9df-4691-93c1-2c79577b98bb`::moving from state init -> state preparing
> Thread-56870::INFO::2012-05-28 03:18:54,327::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56870::INFO::2012-05-28 03:18:54,328::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141406059265', 'lastCheck': 1338175131.455501, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00167608261108', 'lastCheck': 1338175128.25812, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00165891647339', 'lastCheck': 1338175127.096497, 'code': 0, 'valid': True}}
> Thread-56870::DEBUG::2012-05-28 03:18:54,329::task::1174::TaskManager.Task::(prepare) Task=`aa4bc4bb-f9df-4691-93c1-2c79577b98bb`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141406059265', 'lastCheck': 1338175131.455501, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00167608261108', 'lastCheck': 1338175128.25812, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00165891647339', 'lastCheck': 1338175127.096497, 'code': 0, 'valid': True}}
> Thread-56870::DEBUG::2012-05-28 03:18:54,330::task::588::TaskManager.Task::(_updateState) Task=`aa4bc4bb-f9df-4691-93c1-2c79577b98bb`::moving from state preparing -> state finished
> Thread-56870::DEBUG::2012-05-28 03:18:54,330::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56870::DEBUG::2012-05-28 03:18:54,331::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56870::DEBUG::2012-05-28 03:18:54,332::task::980::TaskManager.Task::(_decref) Task=`aa4bc4bb-f9df-4691-93c1-2c79577b98bb`::ref 0 aborting False
> Thread-56875::DEBUG::2012-05-28 03:19:02,361::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56875::DEBUG::2012-05-28 03:19:02,363::task::588::TaskManager.Task::(_updateState) Task=`f0eee7d7-5d12-452b-a148-88383240483b`::moving from state init -> state preparing
> Thread-56875::INFO::2012-05-28 03:19:02,364::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56875::INFO::2012-05-28 03:19:02,364::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56875::DEBUG::2012-05-28 03:19:02,365::task::1174::TaskManager.Task::(prepare) Task=`f0eee7d7-5d12-452b-a148-88383240483b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56875::DEBUG::2012-05-28 03:19:02,366::task::588::TaskManager.Task::(_updateState) Task=`f0eee7d7-5d12-452b-a148-88383240483b`::moving from state preparing -> state finished
> Thread-56875::DEBUG::2012-05-28 03:19:02,366::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56875::DEBUG::2012-05-28 03:19:02,367::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56875::DEBUG::2012-05-28 03:19:02,368::task::980::TaskManager.Task::(_decref) Task=`f0eee7d7-5d12-452b-a148-88383240483b`::ref 0 aborting False
> Thread-56877::DEBUG::2012-05-28 03:19:04,518::task::588::TaskManager.Task::(_updateState) Task=`cc53854a-e65d-4a56-932e-c8b85ec73bb8`::moving from state init -> state preparing
> Thread-56877::INFO::2012-05-28 03:19:04,519::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56877::INFO::2012-05-28 03:19:04,520::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142812728882', 'lastCheck': 1338175141.465798, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00160598754883', 'lastCheck': 1338175138.267357, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00205516815186', 'lastCheck': 1338175137.107303, 'code': 0, 'valid': True}}
> Thread-56877::DEBUG::2012-05-28 03:19:04,520::task::1174::TaskManager.Task::(prepare) Task=`cc53854a-e65d-4a56-932e-c8b85ec73bb8`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142812728882', 'lastCheck': 1338175141.465798, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00160598754883', 'lastCheck': 1338175138.267357, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00205516815186', 'lastCheck': 1338175137.107303, 'code': 0, 'valid': True}}
> Thread-56877::DEBUG::2012-05-28 03:19:04,521::task::588::TaskManager.Task::(_updateState) Task=`cc53854a-e65d-4a56-932e-c8b85ec73bb8`::moving from state preparing -> state finished
> Thread-56877::DEBUG::2012-05-28 03:19:04,522::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56877::DEBUG::2012-05-28 03:19:04,522::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56877::DEBUG::2012-05-28 03:19:04,523::task::980::TaskManager.Task::(_decref) Task=`cc53854a-e65d-4a56-932e-c8b85ec73bb8`::ref 0 aborting False
> Thread-56882::DEBUG::2012-05-28 03:19:12,409::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56882::DEBUG::2012-05-28 03:19:12,410::task::588::TaskManager.Task::(_updateState) Task=`9f1329e9-8d29-46a6-9e08-dec6ba081463`::moving from state init -> state preparing
> Thread-56882::INFO::2012-05-28 03:19:12,411::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56882::INFO::2012-05-28 03:19:12,412::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56882::DEBUG::2012-05-28 03:19:12,413::task::1174::TaskManager.Task::(prepare) Task=`9f1329e9-8d29-46a6-9e08-dec6ba081463`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56882::DEBUG::2012-05-28 03:19:12,413::task::588::TaskManager.Task::(_updateState) Task=`9f1329e9-8d29-46a6-9e08-dec6ba081463`::moving from state preparing -> state finished
> Thread-56882::DEBUG::2012-05-28 03:19:12,414::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56882::DEBUG::2012-05-28 03:19:12,414::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56882::DEBUG::2012-05-28 03:19:12,415::task::980::TaskManager.Task::(_decref) Task=`9f1329e9-8d29-46a6-9e08-dec6ba081463`::ref 0 aborting False
> Thread-56884::DEBUG::2012-05-28 03:19:14,721::task::588::TaskManager.Task::(_updateState) Task=`0b93a2af-f1a7-4a47-86ee-524058784086`::moving from state init -> state preparing
> Thread-56884::INFO::2012-05-28 03:19:14,722::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56884::INFO::2012-05-28 03:19:14,723::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00129413604736', 'lastCheck': 1338175151.475591, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00171303749084', 'lastCheck': 1338175148.277164, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0018789768219', 'lastCheck': 1338175147.120321, 'code': 0, 'valid': True}}
> Thread-56884::DEBUG::2012-05-28 03:19:14,723::task::1174::TaskManager.Task::(prepare) Task=`0b93a2af-f1a7-4a47-86ee-524058784086`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00129413604736', 'lastCheck': 1338175151.475591, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00171303749084', 'lastCheck': 1338175148.277164, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0018789768219', 'lastCheck': 1338175147.120321, 'code': 0, 'valid': True}}
> Thread-56884::DEBUG::2012-05-28 03:19:14,724::task::588::TaskManager.Task::(_updateState) Task=`0b93a2af-f1a7-4a47-86ee-524058784086`::moving from state preparing -> state finished
> Thread-56884::DEBUG::2012-05-28 03:19:14,725::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56884::DEBUG::2012-05-28 03:19:14,725::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56884::DEBUG::2012-05-28 03:19:14,726::task::980::TaskManager.Task::(_decref) Task=`0b93a2af-f1a7-4a47-86ee-524058784086`::ref 0 aborting False
> Thread-56889::DEBUG::2012-05-28 03:19:22,458::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56889::DEBUG::2012-05-28 03:19:22,459::task::588::TaskManager.Task::(_updateState) Task=`2708c524-6c22-444d-b1b8-26bba6637f2b`::moving from state init -> state preparing
> Thread-56889::INFO::2012-05-28 03:19:22,460::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56889::INFO::2012-05-28 03:19:22,461::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56889::DEBUG::2012-05-28 03:19:22,462::task::1174::TaskManager.Task::(prepare) Task=`2708c524-6c22-444d-b1b8-26bba6637f2b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56889::DEBUG::2012-05-28 03:19:22,463::task::588::TaskManager.Task::(_updateState) Task=`2708c524-6c22-444d-b1b8-26bba6637f2b`::moving from state preparing -> state finished
> Thread-56889::DEBUG::2012-05-28 03:19:22,463::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56889::DEBUG::2012-05-28 03:19:22,464::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56889::DEBUG::2012-05-28 03:19:22,465::task::980::TaskManager.Task::(_decref) Task=`2708c524-6c22-444d-b1b8-26bba6637f2b`::ref 0 aborting False
> Thread-56891::DEBUG::2012-05-28 03:19:24,908::task::588::TaskManager.Task::(_updateState) Task=`6a3d04d2-f4e6-4b7e-957f-2e83e0896f33`::moving from state init -> state preparing
> Thread-56891::INFO::2012-05-28 03:19:24,909::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56891::INFO::2012-05-28 03:19:24,910::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00108504295349', 'lastCheck': 1338175161.48503, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00139307975769', 'lastCheck': 1338175158.286835, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00184178352356', 'lastCheck': 1338175157.132717, 'code': 0, 'valid': True}}
> Thread-56891::DEBUG::2012-05-28 03:19:24,911::task::1174::TaskManager.Task::(prepare) Task=`6a3d04d2-f4e6-4b7e-957f-2e83e0896f33`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00108504295349', 'lastCheck': 1338175161.48503, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00139307975769', 'lastCheck': 1338175158.286835, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00184178352356', 'lastCheck': 1338175157.132717, 'code': 0, 'valid': True}}
> Thread-56891::DEBUG::2012-05-28 03:19:24,912::task::588::TaskManager.Task::(_updateState) Task=`6a3d04d2-f4e6-4b7e-957f-2e83e0896f33`::moving from state preparing -> state finished
> Thread-56891::DEBUG::2012-05-28 03:19:24,912::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56891::DEBUG::2012-05-28 03:19:24,913::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56891::DEBUG::2012-05-28 03:19:24,914::task::980::TaskManager.Task::(_decref) Task=`6a3d04d2-f4e6-4b7e-957f-2e83e0896f33`::ref 0 aborting False
> Thread-56896::DEBUG::2012-05-28 03:19:32,513::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56896::DEBUG::2012-05-28 03:19:32,514::task::588::TaskManager.Task::(_updateState) Task=`5263d438-5b32-4eb4-9d7c-64ab08594f33`::moving from state init -> state preparing
> Thread-56896::INFO::2012-05-28 03:19:32,515::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56896::INFO::2012-05-28 03:19:32,516::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56896::DEBUG::2012-05-28 03:19:32,517::task::1174::TaskManager.Task::(prepare) Task=`5263d438-5b32-4eb4-9d7c-64ab08594f33`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56896::DEBUG::2012-05-28 03:19:32,517::task::588::TaskManager.Task::(_updateState) Task=`5263d438-5b32-4eb4-9d7c-64ab08594f33`::moving from state preparing -> state finished
> Thread-56896::DEBUG::2012-05-28 03:19:32,518::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56896::DEBUG::2012-05-28 03:19:32,519::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56896::DEBUG::2012-05-28 03:19:32,519::task::980::TaskManager.Task::(_decref) Task=`5263d438-5b32-4eb4-9d7c-64ab08594f33`::ref 0 aborting False
> Thread-56898::DEBUG::2012-05-28 03:19:35,100::task::588::TaskManager.Task::(_updateState) Task=`f3d31ef6-d64f-4222-8582-3b93eee5910c`::moving from state init -> state preparing
> Thread-56898::INFO::2012-05-28 03:19:35,101::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56898::INFO::2012-05-28 03:19:35,102::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142216682434', 'lastCheck': 1338175171.495628, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00156998634338', 'lastCheck': 1338175168.296831, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00170207023621', 'lastCheck': 1338175167.144922, 'code': 0, 'valid': True}}
> Thread-56898::DEBUG::2012-05-28 03:19:35,103::task::1174::TaskManager.Task::(prepare) Task=`f3d31ef6-d64f-4222-8582-3b93eee5910c`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00142216682434', 'lastCheck': 1338175171.495628, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00156998634338', 'lastCheck': 1338175168.296831, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00170207023621', 'lastCheck': 1338175167.144922, 'code': 0, 'valid': True}}
> Thread-56898::DEBUG::2012-05-28 03:19:35,104::task::588::TaskManager.Task::(_updateState) Task=`f3d31ef6-d64f-4222-8582-3b93eee5910c`::moving from state preparing -> state finished
> Thread-56898::DEBUG::2012-05-28 03:19:35,104::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56898::DEBUG::2012-05-28 03:19:35,105::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56898::DEBUG::2012-05-28 03:19:35,106::task::980::TaskManager.Task::(_decref) Task=`f3d31ef6-d64f-4222-8582-3b93eee5910c`::ref 0 aborting False
> Thread-56903::DEBUG::2012-05-28 03:19:42,561::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56903::DEBUG::2012-05-28 03:19:42,563::task::588::TaskManager.Task::(_updateState) Task=`a87e820d-d8d1-48e8-9a13-7d5afb095f5b`::moving from state init -> state preparing
> Thread-56903::INFO::2012-05-28 03:19:42,563::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56903::INFO::2012-05-28 03:19:42,564::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56903::DEBUG::2012-05-28 03:19:42,565::task::1174::TaskManager.Task::(prepare) Task=`a87e820d-d8d1-48e8-9a13-7d5afb095f5b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56903::DEBUG::2012-05-28 03:19:42,566::task::588::TaskManager.Task::(_updateState) Task=`a87e820d-d8d1-48e8-9a13-7d5afb095f5b`::moving from state preparing -> state finished
> Thread-56903::DEBUG::2012-05-28 03:19:42,566::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56903::DEBUG::2012-05-28 03:19:42,567::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56903::DEBUG::2012-05-28 03:19:42,568::task::980::TaskManager.Task::(_decref) Task=`a87e820d-d8d1-48e8-9a13-7d5afb095f5b`::ref 0 aborting False
> Thread-56905::DEBUG::2012-05-28 03:19:45,293::task::588::TaskManager.Task::(_updateState) Task=`8ef58f73-7dc4-43a0-a9cb-4c34541d1cbb`::moving from state init -> state preparing
> Thread-56905::INFO::2012-05-28 03:19:45,294::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56905::INFO::2012-05-28 03:19:45,295::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00112390518188', 'lastCheck': 1338175181.50506, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00104904174805', 'lastCheck': 1338175178.30603, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00154089927673', 'lastCheck': 1338175177.155919, 'code': 0, 'valid': True}}
> Thread-56905::DEBUG::2012-05-28 03:19:45,295::task::1174::TaskManager.Task::(prepare) Task=`8ef58f73-7dc4-43a0-a9cb-4c34541d1cbb`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00112390518188', 'lastCheck': 1338175181.50506, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00104904174805', 'lastCheck': 1338175178.30603, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00154089927673', 'lastCheck': 1338175177.155919, 'code': 0, 'valid': True}}
> Thread-56905::DEBUG::2012-05-28 03:19:45,296::task::588::TaskManager.Task::(_updateState) Task=`8ef58f73-7dc4-43a0-a9cb-4c34541d1cbb`::moving from state preparing -> state finished
> Thread-56905::DEBUG::2012-05-28 03:19:45,297::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56905::DEBUG::2012-05-28 03:19:45,297::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56905::DEBUG::2012-05-28 03:19:45,298::task::980::TaskManager.Task::(_decref) Task=`8ef58f73-7dc4-43a0-a9cb-4c34541d1cbb`::ref 0 aborting False
> Thread-56910::DEBUG::2012-05-28 03:19:52,610::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56910::DEBUG::2012-05-28 03:19:52,611::task::588::TaskManager.Task::(_updateState) Task=`548e82e4-17df-46f1-827a-27b136a58d93`::moving from state init -> state preparing
> Thread-56910::INFO::2012-05-28 03:19:52,612::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56910::INFO::2012-05-28 03:19:52,613::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56910::DEBUG::2012-05-28 03:19:52,614::task::1174::TaskManager.Task::(prepare) Task=`548e82e4-17df-46f1-827a-27b136a58d93`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56910::DEBUG::2012-05-28 03:19:52,615::task::588::TaskManager.Task::(_updateState) Task=`548e82e4-17df-46f1-827a-27b136a58d93`::moving from state preparing -> state finished
> Thread-56910::DEBUG::2012-05-28 03:19:52,615::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56910::DEBUG::2012-05-28 03:19:52,616::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56910::DEBUG::2012-05-28 03:19:52,616::task::980::TaskManager.Task::(_decref) Task=`548e82e4-17df-46f1-827a-27b136a58d93`::ref 0 aborting False
> Thread-56912::DEBUG::2012-05-28 03:19:55,489::task::588::TaskManager.Task::(_updateState) Task=`8528ed17-1773-4c6a-ae73-903e7506edc4`::moving from state init -> state preparing
> Thread-56912::INFO::2012-05-28 03:19:55,490::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56912::INFO::2012-05-28 03:19:55,491::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00149893760681', 'lastCheck': 1338175191.515354, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00145602226257', 'lastCheck': 1338175188.317232, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0016610622406', 'lastCheck': 1338175187.166205, 'code': 0, 'valid': True}}
> Thread-56912::DEBUG::2012-05-28 03:19:55,492::task::1174::TaskManager.Task::(prepare) Task=`8528ed17-1773-4c6a-ae73-903e7506edc4`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00149893760681', 'lastCheck': 1338175191.515354, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00145602226257', 'lastCheck': 1338175188.317232, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0016610622406', 'lastCheck': 1338175187.166205, 'code': 0, 'valid': True}}
> Thread-56912::DEBUG::2012-05-28 03:19:55,493::task::588::TaskManager.Task::(_updateState) Task=`8528ed17-1773-4c6a-ae73-903e7506edc4`::moving from state preparing -> state finished
> Thread-56912::DEBUG::2012-05-28 03:19:55,493::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56912::DEBUG::2012-05-28 03:19:55,494::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56912::DEBUG::2012-05-28 03:19:55,495::task::980::TaskManager.Task::(_decref) Task=`8528ed17-1773-4c6a-ae73-903e7506edc4`::ref 0 aborting False
> Thread-56917::DEBUG::2012-05-28 03:20:02,677::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56917::DEBUG::2012-05-28 03:20:02,678::task::588::TaskManager.Task::(_updateState) Task=`4bff1b0b-0fb7-43f3-a891-49c83a123977`::moving from state init -> state preparing
> Thread-56917::INFO::2012-05-28 03:20:02,679::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56917::INFO::2012-05-28 03:20:02,680::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56917::DEBUG::2012-05-28 03:20:02,681::task::1174::TaskManager.Task::(prepare) Task=`4bff1b0b-0fb7-43f3-a891-49c83a123977`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56917::DEBUG::2012-05-28 03:20:02,681::task::588::TaskManager.Task::(_updateState) Task=`4bff1b0b-0fb7-43f3-a891-49c83a123977`::moving from state preparing -> state finished
> Thread-56917::DEBUG::2012-05-28 03:20:02,682::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56917::DEBUG::2012-05-28 03:20:02,683::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56917::DEBUG::2012-05-28 03:20:02,683::task::980::TaskManager.Task::(_decref) Task=`4bff1b0b-0fb7-43f3-a891-49c83a123977`::ref 0 aborting False
> Thread-56919::DEBUG::2012-05-28 03:20:05,687::task::588::TaskManager.Task::(_updateState) Task=`369222f4-2262-496b-9893-238884727675`::moving from state init -> state preparing
> Thread-56919::INFO::2012-05-28 03:20:05,688::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56919::INFO::2012-05-28 03:20:05,689::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00213313102722', 'lastCheck': 1338175201.528354, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00161290168762', 'lastCheck': 1338175198.327144, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00187110900879', 'lastCheck': 1338175197.176457, 'code': 0, 'valid': True}}
> Thread-56919::DEBUG::2012-05-28 03:20:05,690::task::1174::TaskManager.Task::(prepare) Task=`369222f4-2262-496b-9893-238884727675`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00213313102722', 'lastCheck': 1338175201.528354, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00161290168762', 'lastCheck': 1338175198.327144, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00187110900879', 'lastCheck': 1338175197.176457, 'code': 0, 'valid': True}}
> Thread-56919::DEBUG::2012-05-28 03:20:05,691::task::588::TaskManager.Task::(_updateState) Task=`369222f4-2262-496b-9893-238884727675`::moving from state preparing -> state finished
> Thread-56919::DEBUG::2012-05-28 03:20:05,691::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56919::DEBUG::2012-05-28 03:20:05,692::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56919::DEBUG::2012-05-28 03:20:05,693::task::980::TaskManager.Task::(_decref) Task=`369222f4-2262-496b-9893-238884727675`::ref 0 aborting False
> Thread-56924::DEBUG::2012-05-28 03:20:12,726::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56924::DEBUG::2012-05-28 03:20:12,727::task::588::TaskManager.Task::(_updateState) Task=`0c42c194-9cc3-41ac-9648-a980ad788338`::moving from state init -> state preparing
> Thread-56924::INFO::2012-05-28 03:20:12,728::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56924::INFO::2012-05-28 03:20:12,729::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56924::DEBUG::2012-05-28 03:20:12,730::task::1174::TaskManager.Task::(prepare) Task=`0c42c194-9cc3-41ac-9648-a980ad788338`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56924::DEBUG::2012-05-28 03:20:12,731::task::588::TaskManager.Task::(_updateState) Task=`0c42c194-9cc3-41ac-9648-a980ad788338`::moving from state preparing -> state finished
> Thread-56924::DEBUG::2012-05-28 03:20:12,731::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56924::DEBUG::2012-05-28 03:20:12,732::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56924::DEBUG::2012-05-28 03:20:12,733::task::980::TaskManager.Task::(_decref) Task=`0c42c194-9cc3-41ac-9648-a980ad788338`::ref 0 aborting False
> Thread-56926::DEBUG::2012-05-28 03:20:15,884::task::588::TaskManager.Task::(_updateState) Task=`42db93af-35a1-44d2-8b1c-1056b094c515`::moving from state init -> state preparing
> Thread-56926::INFO::2012-05-28 03:20:15,885::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56926::INFO::2012-05-28 03:20:15,886::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00151801109314', 'lastCheck': 1338175211.536796, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0017991065979', 'lastCheck': 1338175208.337203, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00146102905273', 'lastCheck': 1338175207.186681, 'code': 0, 'valid': True}}
> Thread-56926::DEBUG::2012-05-28 03:20:15,886::task::1174::TaskManager.Task::(prepare) Task=`42db93af-35a1-44d2-8b1c-1056b094c515`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00151801109314', 'lastCheck': 1338175211.536796, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.0017991065979', 'lastCheck': 1338175208.337203, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00146102905273', 'lastCheck': 1338175207.186681, 'code': 0, 'valid': True}}
> Thread-56926::DEBUG::2012-05-28 03:20:15,887::task::588::TaskManager.Task::(_updateState) Task=`42db93af-35a1-44d2-8b1c-1056b094c515`::moving from state preparing -> state finished
> Thread-56926::DEBUG::2012-05-28 03:20:15,888::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56926::DEBUG::2012-05-28 03:20:15,888::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56926::DEBUG::2012-05-28 03:20:15,889::task::980::TaskManager.Task::(_decref) Task=`42db93af-35a1-44d2-8b1c-1056b094c515`::ref 0 aborting False
> Thread-56931::DEBUG::2012-05-28 03:20:22,774::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56931::DEBUG::2012-05-28 03:20:22,776::task::588::TaskManager.Task::(_updateState) Task=`458107ff-7945-41de-b4a8-75a79a8b0c3d`::moving from state init -> state preparing
> Thread-56931::INFO::2012-05-28 03:20:22,776::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56931::INFO::2012-05-28 03:20:22,777::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56931::DEBUG::2012-05-28 03:20:22,778::task::1174::TaskManager.Task::(prepare) Task=`458107ff-7945-41de-b4a8-75a79a8b0c3d`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56931::DEBUG::2012-05-28 03:20:22,779::task::588::TaskManager.Task::(_updateState) Task=`458107ff-7945-41de-b4a8-75a79a8b0c3d`::moving from state preparing -> state finished
> Thread-56931::DEBUG::2012-05-28 03:20:22,779::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56931::DEBUG::2012-05-28 03:20:22,780::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56931::DEBUG::2012-05-28 03:20:22,781::task::980::TaskManager.Task::(_decref) Task=`458107ff-7945-41de-b4a8-75a79a8b0c3d`::ref 0 aborting False
> Thread-56933::DEBUG::2012-05-28 03:20:26,076::task::588::TaskManager.Task::(_updateState) Task=`dd239c6d-9c7a-4884-845b-47815ca75c1d`::moving from state init -> state preparing
> Thread-56933::INFO::2012-05-28 03:20:26,077::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56933::INFO::2012-05-28 03:20:26,078::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00121998786926', 'lastCheck': 1338175221.545588, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00145983695984', 'lastCheck': 1338175218.346951, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00132298469543', 'lastCheck': 1338175217.198239, 'code': 0, 'valid': True}}
> Thread-56933::DEBUG::2012-05-28 03:20:26,079::task::1174::TaskManager.Task::(prepare) Task=`dd239c6d-9c7a-4884-845b-47815ca75c1d`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00121998786926', 'lastCheck': 1338175221.545588, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00145983695984', 'lastCheck': 1338175218.346951, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00132298469543', 'lastCheck': 1338175217.198239, 'code': 0, 'valid': True}}
> Thread-56933::DEBUG::2012-05-28 03:20:26,080::task::588::TaskManager.Task::(_updateState) Task=`dd239c6d-9c7a-4884-845b-47815ca75c1d`::moving from state preparing -> state finished
> Thread-56933::DEBUG::2012-05-28 03:20:26,080::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56933::DEBUG::2012-05-28 03:20:26,081::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56933::DEBUG::2012-05-28 03:20:26,082::task::980::TaskManager.Task::(_decref) Task=`dd239c6d-9c7a-4884-845b-47815ca75c1d`::ref 0 aborting False
> Thread-56938::DEBUG::2012-05-28 03:20:32,822::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56938::DEBUG::2012-05-28 03:20:32,823::task::588::TaskManager.Task::(_updateState) Task=`69cc05d9-7670-4029-9353-77c1e9682d2a`::moving from state init -> state preparing
> Thread-56938::INFO::2012-05-28 03:20:32,824::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56938::INFO::2012-05-28 03:20:32,825::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56938::DEBUG::2012-05-28 03:20:32,826::task::1174::TaskManager.Task::(prepare) Task=`69cc05d9-7670-4029-9353-77c1e9682d2a`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56938::DEBUG::2012-05-28 03:20:32,826::task::588::TaskManager.Task::(_updateState) Task=`69cc05d9-7670-4029-9353-77c1e9682d2a`::moving from state preparing -> state finished
> Thread-56938::DEBUG::2012-05-28 03:20:32,827::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56938::DEBUG::2012-05-28 03:20:32,828::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56938::DEBUG::2012-05-28 03:20:32,828::task::980::TaskManager.Task::(_decref) Task=`69cc05d9-7670-4029-9353-77c1e9682d2a`::ref 0 aborting False
> Thread-56940::DEBUG::2012-05-28 03:20:36,279::task::588::TaskManager.Task::(_updateState) Task=`90d564b4-e61a-45be-bfb6-8e01c461464c`::moving from state init -> state preparing
> Thread-56940::INFO::2012-05-28 03:20:36,280::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56940::INFO::2012-05-28 03:20:36,281::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00169110298157', 'lastCheck': 1338175231.556109, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00133609771729', 'lastCheck': 1338175228.356622, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0012149810791', 'lastCheck': 1338175227.244507, 'code': 0, 'valid': True}}
> Thread-56940::DEBUG::2012-05-28 03:20:36,282::task::1174::TaskManager.Task::(prepare) Task=`90d564b4-e61a-45be-bfb6-8e01c461464c`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00169110298157', 'lastCheck': 1338175231.556109, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00133609771729', 'lastCheck': 1338175228.356622, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0012149810791', 'lastCheck': 1338175227.244507, 'code': 0, 'valid': True}}
> Thread-56940::DEBUG::2012-05-28 03:20:36,282::task::588::TaskManager.Task::(_updateState) Task=`90d564b4-e61a-45be-bfb6-8e01c461464c`::moving from state preparing -> state finished
> Thread-56940::DEBUG::2012-05-28 03:20:36,283::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56940::DEBUG::2012-05-28 03:20:36,284::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56940::DEBUG::2012-05-28 03:20:36,284::task::980::TaskManager.Task::(_decref) Task=`90d564b4-e61a-45be-bfb6-8e01c461464c`::ref 0 aborting False
> Thread-56945::DEBUG::2012-05-28 03:20:42,871::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56945::DEBUG::2012-05-28 03:20:42,872::task::588::TaskManager.Task::(_updateState) Task=`388b6b84-7409-4f55-8f90-74c7aa9d1b01`::moving from state init -> state preparing
> Thread-56945::INFO::2012-05-28 03:20:42,873::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56945::INFO::2012-05-28 03:20:42,874::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56945::DEBUG::2012-05-28 03:20:42,875::task::1174::TaskManager.Task::(prepare) Task=`388b6b84-7409-4f55-8f90-74c7aa9d1b01`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56945::DEBUG::2012-05-28 03:20:42,875::task::588::TaskManager.Task::(_updateState) Task=`388b6b84-7409-4f55-8f90-74c7aa9d1b01`::moving from state preparing -> state finished
> Thread-56945::DEBUG::2012-05-28 03:20:42,876::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56945::DEBUG::2012-05-28 03:20:42,876::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56945::DEBUG::2012-05-28 03:20:42,877::task::980::TaskManager.Task::(_decref) Task=`388b6b84-7409-4f55-8f90-74c7aa9d1b01`::ref 0 aborting False
> Thread-56947::DEBUG::2012-05-28 03:20:46,472::task::588::TaskManager.Task::(_updateState) Task=`82d9ab88-ea59-413a-ab16-236604876de7`::moving from state init -> state preparing
> Thread-56947::INFO::2012-05-28 03:20:46,473::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56947::INFO::2012-05-28 03:20:46,474::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00122499465942', 'lastCheck': 1338175241.565494, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00244998931885', 'lastCheck': 1338175238.369767, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0427939891815', 'lastCheck': 1338175237.29732, 'code': 0, 'valid': True}}
> Thread-56947::DEBUG::2012-05-28 03:20:46,475::task::1174::TaskManager.Task::(prepare) Task=`82d9ab88-ea59-413a-ab16-236604876de7`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00122499465942', 'lastCheck': 1338175241.565494, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00244998931885', 'lastCheck': 1338175238.369767, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.0427939891815', 'lastCheck': 1338175237.29732, 'code': 0, 'valid': True}}
> Thread-56947::DEBUG::2012-05-28 03:20:46,475::task::588::TaskManager.Task::(_updateState) Task=`82d9ab88-ea59-413a-ab16-236604876de7`::moving from state preparing -> state finished
> Thread-56947::DEBUG::2012-05-28 03:20:46,476::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56947::DEBUG::2012-05-28 03:20:46,477::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56947::DEBUG::2012-05-28 03:20:46,477::task::980::TaskManager.Task::(_decref) Task=`82d9ab88-ea59-413a-ab16-236604876de7`::ref 0 aborting False
> Thread-56952::DEBUG::2012-05-28 03:20:52,921::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56952::DEBUG::2012-05-28 03:20:52,922::task::588::TaskManager.Task::(_updateState) Task=`10ec6d58-3495-4c0c-837e-869d547d3322`::moving from state init -> state preparing
> Thread-56952::INFO::2012-05-28 03:20:52,923::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56952::INFO::2012-05-28 03:20:52,924::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56952::DEBUG::2012-05-28 03:20:52,925::task::1174::TaskManager.Task::(prepare) Task=`10ec6d58-3495-4c0c-837e-869d547d3322`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56952::DEBUG::2012-05-28 03:20:52,926::task::588::TaskManager.Task::(_updateState) Task=`10ec6d58-3495-4c0c-837e-869d547d3322`::moving from state preparing -> state finished
> Thread-56952::DEBUG::2012-05-28 03:20:52,926::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56952::DEBUG::2012-05-28 03:20:52,927::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56952::DEBUG::2012-05-28 03:20:52,927::task::980::TaskManager.Task::(_decref) Task=`10ec6d58-3495-4c0c-837e-869d547d3322`::ref 0 aborting False
> Thread-56954::DEBUG::2012-05-28 03:20:56,684::task::588::TaskManager.Task::(_updateState) Task=`b5ece2e7-eae6-41cd-869c-880abe928f6e`::moving from state init -> state preparing
> Thread-56954::INFO::2012-05-28 03:20:56,685::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56954::INFO::2012-05-28 03:20:56,686::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141596794128', 'lastCheck': 1338175251.575526, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190401077271', 'lastCheck': 1338175248.385359, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00176906585693', 'lastCheck': 1338175247.307218, 'code': 0, 'valid': True}}
> Thread-56954::DEBUG::2012-05-28 03:20:56,687::task::1174::TaskManager.Task::(prepare) Task=`b5ece2e7-eae6-41cd-869c-880abe928f6e`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00141596794128', 'lastCheck': 1338175251.575526, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00190401077271', 'lastCheck': 1338175248.385359, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00176906585693', 'lastCheck': 1338175247.307218, 'code': 0, 'valid': True}}
> Thread-56954::DEBUG::2012-05-28 03:20:56,688::task::588::TaskManager.Task::(_updateState) Task=`b5ece2e7-eae6-41cd-869c-880abe928f6e`::moving from state preparing -> state finished
> Thread-56954::DEBUG::2012-05-28 03:20:56,688::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56954::DEBUG::2012-05-28 03:20:56,689::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56954::DEBUG::2012-05-28 03:20:56,690::task::980::TaskManager.Task::(_decref) Task=`b5ece2e7-eae6-41cd-869c-880abe928f6e`::ref 0 aborting False
> Thread-56959::DEBUG::2012-05-28 03:21:02,969::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56959::DEBUG::2012-05-28 03:21:02,971::task::588::TaskManager.Task::(_updateState) Task=`48ad0981-11fb-4cf9-b954-cb7c301c0272`::moving from state init -> state preparing
> Thread-56959::INFO::2012-05-28 03:21:02,971::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56959::INFO::2012-05-28 03:21:02,972::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56959::DEBUG::2012-05-28 03:21:02,973::task::1174::TaskManager.Task::(prepare) Task=`48ad0981-11fb-4cf9-b954-cb7c301c0272`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56959::DEBUG::2012-05-28 03:21:02,974::task::588::TaskManager.Task::(_updateState) Task=`48ad0981-11fb-4cf9-b954-cb7c301c0272`::moving from state preparing -> state finished
> Thread-56959::DEBUG::2012-05-28 03:21:02,974::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56959::DEBUG::2012-05-28 03:21:02,975::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56959::DEBUG::2012-05-28 03:21:02,976::task::980::TaskManager.Task::(_decref) Task=`48ad0981-11fb-4cf9-b954-cb7c301c0272`::ref 0 aborting False
> Thread-56961::DEBUG::2012-05-28 03:21:06,878::task::588::TaskManager.Task::(_updateState) Task=`16065043-c96c-4865-acb9-b6bd7094aa17`::moving from state init -> state preparing
> Thread-56961::INFO::2012-05-28 03:21:06,879::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56961::INFO::2012-05-28 03:21:06,880::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00164604187012', 'lastCheck': 1338175261.586043, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00171995162964', 'lastCheck': 1338175258.399656, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00198912620544', 'lastCheck': 1338175257.317448, 'code': 0, 'valid': True}}
> Thread-56961::DEBUG::2012-05-28 03:21:06,880::task::1174::TaskManager.Task::(prepare) Task=`16065043-c96c-4865-acb9-b6bd7094aa17`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00164604187012', 'lastCheck': 1338175261.586043, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00171995162964', 'lastCheck': 1338175258.399656, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00198912620544', 'lastCheck': 1338175257.317448, 'code': 0, 'valid': True}}
> Thread-56961::DEBUG::2012-05-28 03:21:06,881::task::588::TaskManager.Task::(_updateState) Task=`16065043-c96c-4865-acb9-b6bd7094aa17`::moving from state preparing -> state finished
> Thread-56961::DEBUG::2012-05-28 03:21:06,882::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56961::DEBUG::2012-05-28 03:21:06,882::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56961::DEBUG::2012-05-28 03:21:06,883::task::980::TaskManager.Task::(_decref) Task=`16065043-c96c-4865-acb9-b6bd7094aa17`::ref 0 aborting False
> Thread-56965::DEBUG::2012-05-28 03:21:13,018::clientIF::261::Storage.Dispatcher.Protect::(wrapper) [172.30.0.229]
> Thread-56965::DEBUG::2012-05-28 03:21:13,019::task::588::TaskManager.Task::(_updateState) Task=`a2b6f77b-c443-440c-80a0-c8afe27c6629`::moving from state init -> state preparing
> Thread-56965::INFO::2012-05-28 03:21:13,020::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='524a7003-edec-4f52-a38e-b15cadfbe3ef', options=None)
> Thread-56965::INFO::2012-05-28 03:21:13,021::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56965::DEBUG::2012-05-28 03:21:13,022::task::1174::TaskManager.Task::(prepare) Task=`a2b6f77b-c443-440c-80a0-c8afe27c6629`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'Free', 'spmLver': 17}}
> Thread-56965::DEBUG::2012-05-28 03:21:13,022::task::588::TaskManager.Task::(_updateState) Task=`a2b6f77b-c443-440c-80a0-c8afe27c6629`::moving from state preparing -> state finished
> Thread-56965::DEBUG::2012-05-28 03:21:13,023::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56965::DEBUG::2012-05-28 03:21:13,024::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56965::DEBUG::2012-05-28 03:21:13,024::task::980::TaskManager.Task::(_decref) Task=`a2b6f77b-c443-440c-80a0-c8afe27c6629`::ref 0 aborting False
> Thread-56968::DEBUG::2012-05-28 03:21:17,091::task::588::TaskManager.Task::(_updateState) Task=`8a53fed3-fa89-4317-86ab-96b029f52afc`::moving from state init -> state preparing
> Thread-56968::INFO::2012-05-28 03:21:17,092::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
> Thread-56968::INFO::2012-05-28 03:21:17,093::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00132322311401', 'lastCheck': 1338175271.595521, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00182509422302', 'lastCheck': 1338175268.408193, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00145196914673', 'lastCheck': 1338175267.326476, 'code': 0, 'valid': True}}
> Thread-56968::DEBUG::2012-05-28 03:21:17,094::task::1174::TaskManager.Task::(prepare) Task=`8a53fed3-fa89-4317-86ab-96b029f52afc`::finished: {'fce72110-71ae-46be-8811-2fbeaa001ed2': {'delay': '0.00132322311401', 'lastCheck': 1338175271.595521, 'code': 0, 'valid': True}, '5e2ac537-6a73-4faf-8379-68f3ff26a75d': {'delay': '0.00182509422302', 'lastCheck': 1338175268.408193, 'code': 0, 'valid': True}, '6d931187-2c83-4c33-8693-ca2570f7c136': {'delay': '0.00145196914673', 'lastCheck': 1338175267.326476, 'code': 0, 'valid': True}}
> Thread-56968::DEBUG::2012-05-28 03:21:17,095::task::588::TaskManager.Task::(_updateState) Task=`8a53fed3-fa89-4317-86ab-96b029f52afc`::moving from state preparing -> state finished
> Thread-56968::DEBUG::2012-05-28 03:21:17,095::resourceManager::806::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
> Thread-56968::DEBUG::2012-05-28 03:21:17,096::resourceManager::841::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
> Thread-56968::DEBUG::2012-05-28 03:21:17,097::task::980::TaskManager.Task::(_decref) Task=`8a53fed3-fa89-4317-86ab-96b029f52afc`::ref 0 aborting False
>
> On 28 May, 2012, at 11:09 AM, Shu Ming wrote:
>
>> How about your /var/log/vdsm.log in the two nodes? It seems that VDSM got some problems.
>>
>> On 2012-5-28 11:04, T-Sinjon wrote:
>>>
>>> 1,on node1, vdsm seems strange , it's sleeping
>>> [root at ovirt-node-1 ~]# systemctl status vdsmd.service
>>> vdsmd.service - Virtual Desktop Server Manager
>>> Loaded: loaded (/lib/systemd/system/vdsmd.service; enabled)
>>> Active: active (running) since Mon, 28 May 2012 02:43:22 +0000; 9min ago
>>> Process: 1157 ExecStart=/lib/systemd/systemd-vdsmd start (code=exited, status=0/SUCCESS)
>>> Main PID: 2228 (respawn)
>>> CGroup: name=systemd:/system/vdsmd.service
>>> ├ 2228 /bin/bash -e /usr/share/vdsm/respawn --minlifetime...
>>> └ 3573 sleep 900
>>> 2,no firewall blocked
>>> 3,network is ok, i can ssh into node1 from engine
>>>
>>> I have used the fence option (confirm host has been rebooted), but SPM did not changed to other node, below is the engine.log when i do this action:
>>>
>>> 2012-05-28 10:49:51,846 INFO [org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand] (pool-5-thread-49) [72d88732] Lock Acquired to object EngineLock [exclusiveLocks= key: org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand value: ae567034-5d8e-11e1-bdc9-a7168ad4d39f
>>> , sharedLocks= ]
>>> 2012-05-28 10:49:51,847 INFO [org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand] (pool-5-thread-49) [72d88732] Running command: FenceVdsManualyCommand internal: false. Entities affected : ID: ae567034-5d8e-11e1-bdc9-a7168ad4d39f Type: VDS
>>> 2012-05-28 10:49:51,927 INFO [org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand] (pool-5-thread-49) [72d88732] Trying to fence spm ovirt-node-1.local via vds ovirt-node-2.local
>>> 2012-05-28 10:49:51,933 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FenceSpmStorageVDSCommand] (pool-5-thread-49) [72d88732] START, FenceSpmStorageVDSCommand(vdsId = a522a6a6-a72e-11e1-baa3-bba876a88ef4, storagePoolId = 524a7003-edec-4f52-a38e-b15cadfbe3ef, prevId=1, prevLVER=17), log id: 530cb694
>>> 2012-05-28 10:49:51,965 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-5-thread-49) [72d88732] Command org.ovirt.engine.core.vdsbroker.vdsbroker.FenceSpmStorageVDSCommand return value
>>> Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusOnlyReturnForXmlRpc
>>> mStatus Class Name: org.ovirt.engine.core.vdsbroker.vdsbroker.StatusForXmlRpc
>>> mCode 654
>>> mMessage Not SPM
>>>
>>>
>>> 2012-05-28 10:49:51,966 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase] (pool-5-thread-49) [72d88732] Vds: ovirt-node-2.local
>>> 2012-05-28 10:49:51,966
>>> [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (pool-5-thread-49) [72d88732] Command FenceSpmStorageVDS execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM
>>> 2012-05-28 10:49:51,966 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FenceSpmStorageVDSCommand] (pool-5-thread-49) [72d88732] FINISH, FenceSpmStorageVDSCommand, log id: 530cb694
>>> 2012-05-28 10:49:51,967 WARN [org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand] (pool-5-thread-49) [72d88732] Could not fence spm on vds ovirt-node-2.local
>>> 2012-05-28 10:49:51,971 ERROR [org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand] (pool-5-thread-49) [72d88732] Transaction rolled-back for command: org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand.
>>> 2012-05-28 10:49:51,971 INFO [org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand] (pool-5-thread-49) [72d88732] Lock freed to object EngineLock [exclusiveLocks= key: org.ovirt.engine.core.bll.storage.FenceVdsManualyCommand value: ae567034-5d8e-11e1-bdc9-a7168ad4d39f
>>> , sharedLocks= ]
>>> 2012-05-28 10:49:57,457 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-79) hostFromVds::selectedVds - ovirt-node-2.local, spmStatus Free, storage pool BLC
>>> 2012-05-28 10:49:57,461 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-79) SPM Init: could not find reported vds or not up - pool:BLC vds_spm_id: 1
>>> 2012-05-28 10:49:57,466 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-79) SPM selection - vds seems as spm ovirt-node-1.local
>>> 2012-05-28 10:49:57,466 WARN [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-79) spm vds is non responsive, stopping spm selection.
>>> 2012-05-28 10:50:00,002 INFO [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-87) Checking autorecoverable hosts
>>> 2012-05-28 10:50:00,004 INFO [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-87) Checking autorecoverable hosts done
>>> 2012-05-28 10:50:00,004 INFO [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-87) Checking autorecoverable storage domains
>>> 2012-05-28 10:50:00,006 INFO [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-87) Checking autorecoverable storage domains done
>>> 2012-05-28 10:50:07,502 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-93) hostFromVds::selectedVds - ovirt-node-2.local, spmStatus Free, storage pool BLC
>>> 2012-05-28 10:50:07,505 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-93) SPM Init: could not find reported vds or not up - pool:BLC vds_spm_id: 1
>>> 2012-05-28 10:50:07,510 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-93) SPM selection - vds seems as spm ovirt-node-1.local
>>> 2012-05-28 10:50:07,510 WARN [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-93) spm vds is non responsive, stopping spm selection.
>>> 2012-05-28 10:50:17,551 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-34) hostFromVds::selectedVds - ovirt-node-2.local, spmStatus Free, storage pool BLC
>>> 2012-05-28 10:50:17,554 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-34) SPM Init: could not find reported vds or not up - pool:BLC vds_spm_id: 1
>>> 2012-05-28 10:50:17,559 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-34) SPM selection - vds seems as spm ovirt-node-1.local
>>> 2012-05-28 10:50:17,559 WARN [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-34) spm vds is non responsive, stopping spm selection.
>>> 2012-05-28 10:50:27,609 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-92) hostFromVds::selectedVds - ovirt-node-2.local, spmStatus Free, storage pool BLC
>>> 2012-05-28 10:50:27,612 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-92) SPM Init: could not find reported vds or not up - pool:BLC vds_spm_id: 1
>>> 2012-05-28 10:50:27,617 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-92) SPM selection - vds seems as spm ovirt-node-1.local
>>> 2012-05-28 10:50:27,618 WARN [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-92) spm vds is non responsive, stopping spm selection.
>>> 2012-05-28 10:50:37,652 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-67) hostFromVds::selectedVds - ovirt-node-2.local, spmStatus Free, storage pool BLC
>>> 2012-05-28 10:50:37,656 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-67) SPM Init: could not find reported vds or not up - pool:BLC vds_spm_id: 1
>>> 2012-05-28 10:50:37,661 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-67) SPM selection - vds seems as spm ovirt-node-1.local
>>> 2012-05-28 10:50:37,662 WARN [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-67) spm vds is non responsive, stopping spm selection.
>>> 2012-05-28 10:50:47,709 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-34) hostFromVds::selectedVds - ovirt-node-2.local, spmStatus Free, storage pool BLC
>>> 2012-05-28 10:50:47,712 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-34) SPM Init: could not find reported vds or not up - pool:BLC vds_spm_id: 1
>>>
>>> On 28 May, 2012, at 12:08 AM, Haim Ateya wrote:
>>>
>>>> Hi, first question that comes to mind is why host is in non-responsive state?
>>>> Please check the following:
>>>> 1. vdsmd service is running on host side
>>>> 2. No firewall is blocking comm. in and out
>>>> 3. No network issue between host and manager
>>>>
>>>> Now, for your question, you can use the manual fence option (confirm host has been rebooted), which will free spm role for faulty host, and engine will elect new spm.
>>>>
>>>> Haim
>>>>
>>>> On May 27, 2012, at 18:32, T-Sinjon <tscbj1989 at gmail.com> wrote:
>>>>
>>>>> Description of problem:
>>>>>
>>>>> i have 2 nodes
>>>>> ovirt-node1.local Non Responsive SPM
>>>>> ovirt-node2.local Up None
>>>>>
>>>>> The SPM node stuck in Non-responsive status, it can't be actived,
>>>>> all vms in the node went into Unknown status and the master vm domain became inactived
>>>>>
>>>>> when i do "Maintenace" action to node1, it says:
>>>>> Error: Cannot switch Host to Maintenance mode.
>>>>> Host still has running VMs on it and is in Non-Responsive state.
>>>>>
>>>>> but there has no vm running in node1 , it only has 2 vms in Unknown status
>>>>>
>>>>> Because I can't active the SPM host , so i can't active the vm storage domain
>>>>>
>>>>> 1,How can i migrated the SPM role to other host in my data center , such us node2?
>>>>> 2,How can i send the node1 to UP status?(I have did 'confirm the host has been Rebooted' action , and rebooted the node1, but it did no sense)
>>>>>
>>>>> _______________________________________________
>>>>> Users mailing list
>>>>> Users at ovirt.org
>>>>> http://lists.ovirt.org/mailman/listinfo/users
>>>
>>>
>>>
>>> _______________________________________________
>>> Users mailing list
>>> Users at ovirt.org
>>> http://lists.ovirt.org/mailman/listinfo/users
>>
>>
>> --
>> Shu Ming <shuming at linux.vnet.ibm.com>
>> IBM China Systems and Technology Laboratory
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20120528/62100321/attachment-0001.html>
More information about the Users
mailing list