Attachment 575738 Details for Bug 810499 – vdsm log

vdsm log

vdsm.log (text/x-log), 193.93 KB, created by Jakub Libosvar on 2012-04-06 13:07:07 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jakub Libosvar

Created: 2012-04-06 13:07:07 UTC

Size: 193.93 KB

patch

obsolete

>Thread-935::DEBUG::2012-04-06 14:54:58,280::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-935::DEBUG::2012-04-06 14:54:58,281::task::588::TaskManager.Task::(_updateState) Task=`151a56a1-7939-4bca-b822-7487c76f54a5`::moving from state init -> state preparing
>Thread-935::INFO::2012-04-06 14:54:58,281::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'example.com:/export/1234', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd4c6b700-7f5e-4cfa-aee2-fe51cbf9dce6', 'port': ''}], options=None)
>Thread-935::DEBUG::2012-04-06 14:54:58,282::mount::124::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6 example.com:/export/1234 /rhev/data-center/mnt/example.com:_export_1234' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:54:59,716::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:54:59,785::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0357673 s, 28.6 MB/s\n'; <rc> = 0
>Thread-936::DEBUG::2012-04-06 14:55:00,231::task::588::TaskManager.Task::(_updateState) Task=`2db42e79-0dbd-4099-ba8c-e8257a4fc709`::moving from state init -> state preparing
>Thread-936::INFO::2012-04-06 14:55:00,231::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-936::INFO::2012-04-06 14:55:00,231::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000612020492554', 'lastCheck': 1333716892.021451, 'code': 0, 'valid': True}}
>Thread-936::DEBUG::2012-04-06 14:55:00,232::task::1172::TaskManager.Task::(prepare) Task=`2db42e79-0dbd-4099-ba8c-e8257a4fc709`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000612020492554', 'lastCheck': 1333716892.021451, 'code': 0, 'valid': True}}
>Thread-936::DEBUG::2012-04-06 14:55:00,232::task::588::TaskManager.Task::(_updateState) Task=`2db42e79-0dbd-4099-ba8c-e8257a4fc709`::moving from state preparing -> state finished
>Thread-936::DEBUG::2012-04-06 14:55:00,232::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-936::DEBUG::2012-04-06 14:55:00,233::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-936::DEBUG::2012-04-06 14:55:00,233::task::978::TaskManager.Task::(_decref) Task=`2db42e79-0dbd-4099-ba8c-e8257a4fc709`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:01,794::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:01,863::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.034893 s, 29.3 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:03,872::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:03,944::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.034988 s, 29.3 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:05,952::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:06,040::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0411473 s, 24.9 MB/s\n'; <rc> = 0
>Thread-941::DEBUG::2012-04-06 14:55:06,772::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-941::DEBUG::2012-04-06 14:55:06,772::task::588::TaskManager.Task::(_updateState) Task=`fff91c5d-b1e4-4d56-85b4-268d819d16f3`::moving from state init -> state preparing
>Thread-941::INFO::2012-04-06 14:55:06,773::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-941::INFO::2012-04-06 14:55:06,773::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-941::DEBUG::2012-04-06 14:55:06,773::task::1172::TaskManager.Task::(prepare) Task=`fff91c5d-b1e4-4d56-85b4-268d819d16f3`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-941::DEBUG::2012-04-06 14:55:06,774::task::588::TaskManager.Task::(_updateState) Task=`fff91c5d-b1e4-4d56-85b4-268d819d16f3`::moving from state preparing -> state finished
>Thread-941::DEBUG::2012-04-06 14:55:06,774::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-941::DEBUG::2012-04-06 14:55:06,774::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-941::DEBUG::2012-04-06 14:55:06,775::task::978::TaskManager.Task::(_decref) Task=`fff91c5d-b1e4-4d56-85b4-268d819d16f3`::ref 0 aborting False
>Thread-942::DEBUG::2012-04-06 14:55:06,778::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-942::DEBUG::2012-04-06 14:55:06,779::task::588::TaskManager.Task::(_updateState) Task=`918a039f-ad08-49ba-aa8a-7fc4d7d2dd93`::moving from state init -> state preparing
>Thread-942::INFO::2012-04-06 14:55:06,779::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-942::DEBUG::2012-04-06 14:55:06,780::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`7cb20638-3056-465c-950e-e1e91587c720`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-942::DEBUG::2012-04-06 14:55:06,780::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-942::DEBUG::2012-04-06 14:55:06,780::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-942::DEBUG::2012-04-06 14:55:06,781::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`7cb20638-3056-465c-950e-e1e91587c720`::Granted request
>Thread-942::DEBUG::2012-04-06 14:55:06,781::task::817::TaskManager.Task::(resourceAcquired) Task=`918a039f-ad08-49ba-aa8a-7fc4d7d2dd93`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-942::DEBUG::2012-04-06 14:55:06,781::task::978::TaskManager.Task::(_decref) Task=`918a039f-ad08-49ba-aa8a-7fc4d7d2dd93`::ref 1 aborting False
>Thread-942::INFO::2012-04-06 14:55:06,782::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-942::DEBUG::2012-04-06 14:55:06,783::task::1172::TaskManager.Task::(prepare) Task=`918a039f-ad08-49ba-aa8a-7fc4d7d2dd93`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-942::DEBUG::2012-04-06 14:55:06,783::task::588::TaskManager.Task::(_updateState) Task=`918a039f-ad08-49ba-aa8a-7fc4d7d2dd93`::moving from state preparing -> state finished
>Thread-942::DEBUG::2012-04-06 14:55:06,783::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-942::DEBUG::2012-04-06 14:55:06,784::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-942::DEBUG::2012-04-06 14:55:06,784::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-942::DEBUG::2012-04-06 14:55:06,784::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-942::DEBUG::2012-04-06 14:55:06,785::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-942::DEBUG::2012-04-06 14:55:06,785::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-942::DEBUG::2012-04-06 14:55:06,785::task::978::TaskManager.Task::(_decref) Task=`918a039f-ad08-49ba-aa8a-7fc4d7d2dd93`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:08,048::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:08,118::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0357457 s, 28.6 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:10,126::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:10,197::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0364138 s, 28.1 MB/s\n'; <rc> = 0
>Thread-944::DEBUG::2012-04-06 14:55:10,387::task::588::TaskManager.Task::(_updateState) Task=`df9de524-dca5-4160-9abd-af85021b9dd3`::moving from state init -> state preparing
>Thread-944::INFO::2012-04-06 14:55:10,387::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-944::INFO::2012-04-06 14:55:10,387::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00115990638733', 'lastCheck': 1333716902.024379, 'code': 0, 'valid': True}}
>Thread-944::DEBUG::2012-04-06 14:55:10,388::task::1172::TaskManager.Task::(prepare) Task=`df9de524-dca5-4160-9abd-af85021b9dd3`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00115990638733', 'lastCheck': 1333716902.024379, 'code': 0, 'valid': True}}
>Thread-944::DEBUG::2012-04-06 14:55:10,388::task::588::TaskManager.Task::(_updateState) Task=`df9de524-dca5-4160-9abd-af85021b9dd3`::moving from state preparing -> state finished
>Thread-944::DEBUG::2012-04-06 14:55:10,388::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-944::DEBUG::2012-04-06 14:55:10,388::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-944::DEBUG::2012-04-06 14:55:10,389::task::978::TaskManager.Task::(_decref) Task=`df9de524-dca5-4160-9abd-af85021b9dd3`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:12,205::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:12,277::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0370267 s, 27.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:14,285::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:14,356::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360406 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:16,364::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:16,435::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0366863 s, 27.9 MB/s\n'; <rc> = 0
>Thread-949::DEBUG::2012-04-06 14:55:16,813::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-949::DEBUG::2012-04-06 14:55:16,822::task::588::TaskManager.Task::(_updateState) Task=`652836b5-1dce-453a-99d9-cf00b2d5078d`::moving from state init -> state preparing
>Thread-949::INFO::2012-04-06 14:55:16,823::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-949::INFO::2012-04-06 14:55:16,823::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-949::DEBUG::2012-04-06 14:55:16,823::task::1172::TaskManager.Task::(prepare) Task=`652836b5-1dce-453a-99d9-cf00b2d5078d`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-949::DEBUG::2012-04-06 14:55:16,824::task::588::TaskManager.Task::(_updateState) Task=`652836b5-1dce-453a-99d9-cf00b2d5078d`::moving from state preparing -> state finished
>Thread-949::DEBUG::2012-04-06 14:55:16,824::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-949::DEBUG::2012-04-06 14:55:16,824::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-949::DEBUG::2012-04-06 14:55:16,825::task::978::TaskManager.Task::(_decref) Task=`652836b5-1dce-453a-99d9-cf00b2d5078d`::ref 0 aborting False
>Thread-950::DEBUG::2012-04-06 14:55:16,829::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-950::DEBUG::2012-04-06 14:55:16,830::task::588::TaskManager.Task::(_updateState) Task=`7555bb44-e54f-4b3e-b289-3bb2ea11f58f`::moving from state init -> state preparing
>Thread-950::INFO::2012-04-06 14:55:16,830::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-950::DEBUG::2012-04-06 14:55:16,830::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`0d2382ad-d5cf-46b1-9853-dffdf3e68217`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-950::DEBUG::2012-04-06 14:55:16,831::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-950::DEBUG::2012-04-06 14:55:16,831::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-950::DEBUG::2012-04-06 14:55:16,831::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`0d2382ad-d5cf-46b1-9853-dffdf3e68217`::Granted request
>Thread-950::DEBUG::2012-04-06 14:55:16,833::task::817::TaskManager.Task::(resourceAcquired) Task=`7555bb44-e54f-4b3e-b289-3bb2ea11f58f`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-950::DEBUG::2012-04-06 14:55:16,833::task::978::TaskManager.Task::(_decref) Task=`7555bb44-e54f-4b3e-b289-3bb2ea11f58f`::ref 1 aborting False
>Thread-950::INFO::2012-04-06 14:55:16,834::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-950::DEBUG::2012-04-06 14:55:16,834::task::1172::TaskManager.Task::(prepare) Task=`7555bb44-e54f-4b3e-b289-3bb2ea11f58f`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-950::DEBUG::2012-04-06 14:55:16,834::task::588::TaskManager.Task::(_updateState) Task=`7555bb44-e54f-4b3e-b289-3bb2ea11f58f`::moving from state preparing -> state finished
>Thread-950::DEBUG::2012-04-06 14:55:16,835::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-950::DEBUG::2012-04-06 14:55:16,835::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-950::DEBUG::2012-04-06 14:55:16,835::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-950::DEBUG::2012-04-06 14:55:16,835::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-950::DEBUG::2012-04-06 14:55:16,836::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-950::DEBUG::2012-04-06 14:55:16,836::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-950::DEBUG::2012-04-06 14:55:16,836::task::978::TaskManager.Task::(_decref) Task=`7555bb44-e54f-4b3e-b289-3bb2ea11f58f`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:18,444::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:18,517::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0389443 s, 26.3 MB/s\n'; <rc> = 0
>Thread-952::DEBUG::2012-04-06 14:55:20,483::task::588::TaskManager.Task::(_updateState) Task=`53509bf2-6a3c-4f8e-b00d-cc302d609069`::moving from state init -> state preparing
>Thread-952::INFO::2012-04-06 14:55:20,483::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-952::INFO::2012-04-06 14:55:20,484::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0228168964386', 'lastCheck': 1333716912.048697, 'code': 0, 'valid': True}}
>Thread-952::DEBUG::2012-04-06 14:55:20,484::task::1172::TaskManager.Task::(prepare) Task=`53509bf2-6a3c-4f8e-b00d-cc302d609069`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0228168964386', 'lastCheck': 1333716912.048697, 'code': 0, 'valid': True}}
>Thread-952::DEBUG::2012-04-06 14:55:20,484::task::588::TaskManager.Task::(_updateState) Task=`53509bf2-6a3c-4f8e-b00d-cc302d609069`::moving from state preparing -> state finished
>Thread-952::DEBUG::2012-04-06 14:55:20,485::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-952::DEBUG::2012-04-06 14:55:20,485::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-952::DEBUG::2012-04-06 14:55:20,485::task::978::TaskManager.Task::(_decref) Task=`53509bf2-6a3c-4f8e-b00d-cc302d609069`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:20,525::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:20,594::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0358113 s, 28.6 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:22,602::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:22,672::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360242 s, 28.4 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2012-04-06 14:55:24,248::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 319.
>Thread-642::DEBUG::2012-04-06 14:55:24,439::task::588::TaskManager.Task::(_updateState) Task=`7664f807-a398-46d2-9a90-906327284b52`::moving from state init -> state preparing
>Thread-642::INFO::2012-04-06 14:55:24,439::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5a526aab-7488-4e8d-a05a-73a3c27db31c', spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', imgUUID='816042f6-b056-42fd-8154-e766aec76bfd', volUUID='8718328b-f49c-4f3d-b7d8-a51702424f1c', options=None)
>Thread-642::DEBUG::2012-04-06 14:55:24,440::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`b294ea65-6e19-4b62-807c-b471a2dde7f9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2496' at 'getVolumeSize'
>Thread-642::DEBUG::2012-04-06 14:55:24,440::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' for lock type 'shared'
>Thread-642::DEBUG::2012-04-06 14:55:24,440::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free. Now locking as 'shared' (1 active user)
>Thread-642::DEBUG::2012-04-06 14:55:24,440::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`b294ea65-6e19-4b62-807c-b471a2dde7f9`::Granted request
>Thread-642::DEBUG::2012-04-06 14:55:24,441::task::817::TaskManager.Task::(resourceAcquired) Task=`7664f807-a398-46d2-9a90-906327284b52`::_resourcesAcquired: Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c (shared)
>Thread-642::DEBUG::2012-04-06 14:55:24,441::task::978::TaskManager.Task::(_decref) Task=`7664f807-a398-46d2-9a90-906327284b52`::ref 1 aborting False
>Thread-642::INFO::2012-04-06 14:55:24,442::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '10737418240', 'apparentsize': '10737418240'}
>Thread-642::DEBUG::2012-04-06 14:55:24,442::task::1172::TaskManager.Task::(prepare) Task=`7664f807-a398-46d2-9a90-906327284b52`::finished: {'truesize': '10737418240', 'apparentsize': '10737418240'}
>Thread-642::DEBUG::2012-04-06 14:55:24,442::task::588::TaskManager.Task::(_updateState) Task=`7664f807-a398-46d2-9a90-906327284b52`::moving from state preparing -> state finished
>Thread-642::DEBUG::2012-04-06 14:55:24,443::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c': < ResourceRef 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', isValid: 'True' obj: 'None'>}
>Thread-642::DEBUG::2012-04-06 14:55:24,443::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-642::DEBUG::2012-04-06 14:55:24,443::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c'
>Thread-642::DEBUG::2012-04-06 14:55:24,444::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' (0 active users)
>Thread-642::DEBUG::2012-04-06 14:55:24,444::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free, finding out if anyone is waiting for it.
>Thread-642::DEBUG::2012-04-06 14:55:24,444::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', Clearing records.
>Thread-642::DEBUG::2012-04-06 14:55:24,444::task::978::TaskManager.Task::(_decref) Task=`7664f807-a398-46d2-9a90-906327284b52`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:24,680::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:24,751::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0364026 s, 28.1 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:26,759::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:26,828::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.035725 s, 28.7 MB/s\n'; <rc> = 0
>Thread-957::DEBUG::2012-04-06 14:55:26,857::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-957::DEBUG::2012-04-06 14:55:26,858::task::588::TaskManager.Task::(_updateState) Task=`afaa1fb2-432d-42b8-8768-80c6d3b0e4bc`::moving from state init -> state preparing
>Thread-957::INFO::2012-04-06 14:55:26,858::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-957::INFO::2012-04-06 14:55:26,859::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-957::DEBUG::2012-04-06 14:55:26,859::task::1172::TaskManager.Task::(prepare) Task=`afaa1fb2-432d-42b8-8768-80c6d3b0e4bc`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-957::DEBUG::2012-04-06 14:55:26,859::task::588::TaskManager.Task::(_updateState) Task=`afaa1fb2-432d-42b8-8768-80c6d3b0e4bc`::moving from state preparing -> state finished
>Thread-957::DEBUG::2012-04-06 14:55:26,860::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-957::DEBUG::2012-04-06 14:55:26,860::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-957::DEBUG::2012-04-06 14:55:26,860::task::978::TaskManager.Task::(_decref) Task=`afaa1fb2-432d-42b8-8768-80c6d3b0e4bc`::ref 0 aborting False
>Thread-958::DEBUG::2012-04-06 14:55:26,864::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-958::DEBUG::2012-04-06 14:55:26,864::task::588::TaskManager.Task::(_updateState) Task=`ff3a8815-e8f3-4d50-bfb3-4dbb4bd82c12`::moving from state init -> state preparing
>Thread-958::INFO::2012-04-06 14:55:26,865::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-958::DEBUG::2012-04-06 14:55:26,865::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`b09695bd-5ac9-4a69-ab50-bd63f7a96688`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-958::DEBUG::2012-04-06 14:55:26,865::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-958::DEBUG::2012-04-06 14:55:26,866::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-958::DEBUG::2012-04-06 14:55:26,866::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`b09695bd-5ac9-4a69-ab50-bd63f7a96688`::Granted request
>Thread-958::DEBUG::2012-04-06 14:55:26,866::task::817::TaskManager.Task::(resourceAcquired) Task=`ff3a8815-e8f3-4d50-bfb3-4dbb4bd82c12`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-958::DEBUG::2012-04-06 14:55:26,867::task::978::TaskManager.Task::(_decref) Task=`ff3a8815-e8f3-4d50-bfb3-4dbb4bd82c12`::ref 1 aborting False
>Thread-958::INFO::2012-04-06 14:55:26,868::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-958::DEBUG::2012-04-06 14:55:26,868::task::1172::TaskManager.Task::(prepare) Task=`ff3a8815-e8f3-4d50-bfb3-4dbb4bd82c12`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-958::DEBUG::2012-04-06 14:55:26,868::task::588::TaskManager.Task::(_updateState) Task=`ff3a8815-e8f3-4d50-bfb3-4dbb4bd82c12`::moving from state preparing -> state finished
>Thread-958::DEBUG::2012-04-06 14:55:26,868::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-958::DEBUG::2012-04-06 14:55:26,869::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-958::DEBUG::2012-04-06 14:55:26,869::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-958::DEBUG::2012-04-06 14:55:26,869::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-958::DEBUG::2012-04-06 14:55:26,870::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-958::DEBUG::2012-04-06 14:55:26,870::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-958::DEBUG::2012-04-06 14:55:26,870::task::978::TaskManager.Task::(_decref) Task=`ff3a8815-e8f3-4d50-bfb3-4dbb4bd82c12`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:28,836::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:28,907::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0364929 s, 28.1 MB/s\n'; <rc> = 0
>Thread-960::DEBUG::2012-04-06 14:55:30,574::task::588::TaskManager.Task::(_updateState) Task=`4631d046-e72d-4d0f-8bc9-d322063b3ace`::moving from state init -> state preparing
>Thread-960::INFO::2012-04-06 14:55:30,575::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-960::INFO::2012-04-06 14:55:30,575::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000685930252075', 'lastCheck': 1333716922.051399, 'code': 0, 'valid': True}}
>Thread-960::DEBUG::2012-04-06 14:55:30,575::task::1172::TaskManager.Task::(prepare) Task=`4631d046-e72d-4d0f-8bc9-d322063b3ace`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000685930252075', 'lastCheck': 1333716922.051399, 'code': 0, 'valid': True}}
>Thread-960::DEBUG::2012-04-06 14:55:30,576::task::588::TaskManager.Task::(_updateState) Task=`4631d046-e72d-4d0f-8bc9-d322063b3ace`::moving from state preparing -> state finished
>Thread-960::DEBUG::2012-04-06 14:55:30,576::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-960::DEBUG::2012-04-06 14:55:30,576::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-960::DEBUG::2012-04-06 14:55:30,576::task::978::TaskManager.Task::(_decref) Task=`4631d046-e72d-4d0f-8bc9-d322063b3ace`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:30,915::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:30,985::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0361932 s, 28.3 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:32,993::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:33,064::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0363788 s, 28.1 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:35,072::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:35,141::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0359514 s, 28.5 MB/s\n'; <rc> = 0
>Thread-965::DEBUG::2012-04-06 14:55:36,891::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-965::DEBUG::2012-04-06 14:55:36,892::task::588::TaskManager.Task::(_updateState) Task=`fe0735bf-e69a-4586-8316-fe03666c56c9`::moving from state init -> state preparing
>Thread-965::INFO::2012-04-06 14:55:36,892::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-965::INFO::2012-04-06 14:55:36,893::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-965::DEBUG::2012-04-06 14:55:36,893::task::1172::TaskManager.Task::(prepare) Task=`fe0735bf-e69a-4586-8316-fe03666c56c9`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-965::DEBUG::2012-04-06 14:55:36,893::task::588::TaskManager.Task::(_updateState) Task=`fe0735bf-e69a-4586-8316-fe03666c56c9`::moving from state preparing -> state finished
>Thread-965::DEBUG::2012-04-06 14:55:36,893::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-965::DEBUG::2012-04-06 14:55:36,894::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-965::DEBUG::2012-04-06 14:55:36,894::task::978::TaskManager.Task::(_decref) Task=`fe0735bf-e69a-4586-8316-fe03666c56c9`::ref 0 aborting False
>Thread-966::DEBUG::2012-04-06 14:55:36,898::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-966::DEBUG::2012-04-06 14:55:36,898::task::588::TaskManager.Task::(_updateState) Task=`0caeabf4-83fb-4063-98e5-68853bda95c4`::moving from state init -> state preparing
>Thread-966::INFO::2012-04-06 14:55:36,899::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-966::DEBUG::2012-04-06 14:55:36,899::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`849087c0-5354-42c1-af22-f3def015a17a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-966::DEBUG::2012-04-06 14:55:36,899::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-966::DEBUG::2012-04-06 14:55:36,900::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-966::DEBUG::2012-04-06 14:55:36,900::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`849087c0-5354-42c1-af22-f3def015a17a`::Granted request
>Thread-966::DEBUG::2012-04-06 14:55:36,900::task::817::TaskManager.Task::(resourceAcquired) Task=`0caeabf4-83fb-4063-98e5-68853bda95c4`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-966::DEBUG::2012-04-06 14:55:36,901::task::978::TaskManager.Task::(_decref) Task=`0caeabf4-83fb-4063-98e5-68853bda95c4`::ref 1 aborting False
>Thread-966::INFO::2012-04-06 14:55:36,901::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-966::DEBUG::2012-04-06 14:55:36,902::task::1172::TaskManager.Task::(prepare) Task=`0caeabf4-83fb-4063-98e5-68853bda95c4`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-966::DEBUG::2012-04-06 14:55:36,902::task::588::TaskManager.Task::(_updateState) Task=`0caeabf4-83fb-4063-98e5-68853bda95c4`::moving from state preparing -> state finished
>Thread-966::DEBUG::2012-04-06 14:55:36,902::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-966::DEBUG::2012-04-06 14:55:36,903::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-966::DEBUG::2012-04-06 14:55:36,903::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-966::DEBUG::2012-04-06 14:55:36,903::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-966::DEBUG::2012-04-06 14:55:36,903::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-966::DEBUG::2012-04-06 14:55:36,904::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-966::DEBUG::2012-04-06 14:55:36,904::task::978::TaskManager.Task::(_decref) Task=`0caeabf4-83fb-4063-98e5-68853bda95c4`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:37,149::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:37,219::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0356081 s, 28.8 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:39,227::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:39,297::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.035868 s, 28.5 MB/s\n'; <rc> = 0
>Thread-968::DEBUG::2012-04-06 14:55:40,670::task::588::TaskManager.Task::(_updateState) Task=`72c3097e-8e93-4587-acee-fb47652b59b1`::moving from state init -> state preparing
>Thread-968::INFO::2012-04-06 14:55:40,670::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-968::INFO::2012-04-06 14:55:40,671::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000577926635742', 'lastCheck': 1333716932.0535159, 'code': 0, 'valid': True}}
>Thread-968::DEBUG::2012-04-06 14:55:40,671::task::1172::TaskManager.Task::(prepare) Task=`72c3097e-8e93-4587-acee-fb47652b59b1`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000577926635742', 'lastCheck': 1333716932.0535159, 'code': 0, 'valid': True}}
>Thread-968::DEBUG::2012-04-06 14:55:40,671::task::588::TaskManager.Task::(_updateState) Task=`72c3097e-8e93-4587-acee-fb47652b59b1`::moving from state preparing -> state finished
>Thread-968::DEBUG::2012-04-06 14:55:40,672::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-968::DEBUG::2012-04-06 14:55:40,672::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-968::DEBUG::2012-04-06 14:55:40,672::task::978::TaskManager.Task::(_decref) Task=`72c3097e-8e93-4587-acee-fb47652b59b1`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:41,304::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:41,376::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0375556 s, 27.3 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:43,382::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:43,455::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0378453 s, 27.1 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:45,464::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:45,534::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0350119 s, 29.2 MB/s\n'; <rc> = 0
>Thread-973::DEBUG::2012-04-06 14:55:46,925::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-973::DEBUG::2012-04-06 14:55:46,925::task::588::TaskManager.Task::(_updateState) Task=`10701c36-5c59-4a27-816b-55e05377a8dc`::moving from state init -> state preparing
>Thread-973::INFO::2012-04-06 14:55:46,926::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-973::INFO::2012-04-06 14:55:46,926::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-973::DEBUG::2012-04-06 14:55:46,926::task::1172::TaskManager.Task::(prepare) Task=`10701c36-5c59-4a27-816b-55e05377a8dc`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-973::DEBUG::2012-04-06 14:55:46,927::task::588::TaskManager.Task::(_updateState) Task=`10701c36-5c59-4a27-816b-55e05377a8dc`::moving from state preparing -> state finished
>Thread-973::DEBUG::2012-04-06 14:55:46,927::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-973::DEBUG::2012-04-06 14:55:46,927::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-973::DEBUG::2012-04-06 14:55:46,928::task::978::TaskManager.Task::(_decref) Task=`10701c36-5c59-4a27-816b-55e05377a8dc`::ref 0 aborting False
>Thread-974::DEBUG::2012-04-06 14:55:46,931::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-974::DEBUG::2012-04-06 14:55:46,932::task::588::TaskManager.Task::(_updateState) Task=`3fd34b14-46f8-4d43-adc1-86d956edcbc8`::moving from state init -> state preparing
>Thread-974::INFO::2012-04-06 14:55:46,932::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-974::DEBUG::2012-04-06 14:55:46,932::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`dbf41540-0ee4-48a0-8b03-373a97b7a11e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-974::DEBUG::2012-04-06 14:55:46,933::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-974::DEBUG::2012-04-06 14:55:46,933::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-974::DEBUG::2012-04-06 14:55:46,933::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`dbf41540-0ee4-48a0-8b03-373a97b7a11e`::Granted request
>Thread-974::DEBUG::2012-04-06 14:55:46,934::task::817::TaskManager.Task::(resourceAcquired) Task=`3fd34b14-46f8-4d43-adc1-86d956edcbc8`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-974::DEBUG::2012-04-06 14:55:46,934::task::978::TaskManager.Task::(_decref) Task=`3fd34b14-46f8-4d43-adc1-86d956edcbc8`::ref 1 aborting False
>Thread-974::INFO::2012-04-06 14:55:46,935::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-974::DEBUG::2012-04-06 14:55:46,935::task::1172::TaskManager.Task::(prepare) Task=`3fd34b14-46f8-4d43-adc1-86d956edcbc8`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-974::DEBUG::2012-04-06 14:55:46,935::task::588::TaskManager.Task::(_updateState) Task=`3fd34b14-46f8-4d43-adc1-86d956edcbc8`::moving from state preparing -> state finished
>Thread-974::DEBUG::2012-04-06 14:55:46,936::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-974::DEBUG::2012-04-06 14:55:46,936::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-974::DEBUG::2012-04-06 14:55:46,936::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-974::DEBUG::2012-04-06 14:55:46,936::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-974::DEBUG::2012-04-06 14:55:46,937::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-974::DEBUG::2012-04-06 14:55:46,937::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-974::DEBUG::2012-04-06 14:55:46,937::task::978::TaskManager.Task::(_decref) Task=`3fd34b14-46f8-4d43-adc1-86d956edcbc8`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:47,540::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:47,615::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0362601 s, 28.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:49,624::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:49,694::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036208 s, 28.3 MB/s\n'; <rc> = 0
>Thread-976::DEBUG::2012-04-06 14:55:50,771::task::588::TaskManager.Task::(_updateState) Task=`9a66e7c2-bf92-435d-adba-6716afc347fb`::moving from state init -> state preparing
>Thread-976::INFO::2012-04-06 14:55:50,772::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-976::INFO::2012-04-06 14:55:50,772::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000764846801758', 'lastCheck': 1333716942.055799, 'code': 0, 'valid': True}}
>Thread-976::DEBUG::2012-04-06 14:55:50,772::task::1172::TaskManager.Task::(prepare) Task=`9a66e7c2-bf92-435d-adba-6716afc347fb`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000764846801758', 'lastCheck': 1333716942.055799, 'code': 0, 'valid': True}}
>Thread-976::DEBUG::2012-04-06 14:55:50,772::task::588::TaskManager.Task::(_updateState) Task=`9a66e7c2-bf92-435d-adba-6716afc347fb`::moving from state preparing -> state finished
>Thread-976::DEBUG::2012-04-06 14:55:50,773::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-976::DEBUG::2012-04-06 14:55:50,773::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-976::DEBUG::2012-04-06 14:55:50,773::task::978::TaskManager.Task::(_decref) Task=`9a66e7c2-bf92-435d-adba-6716afc347fb`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:51,703::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:51,773::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0362623 s, 28.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:55:53,780::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:53,851::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0344465 s, 29.7 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2012-04-06 14:55:54,253::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 319.
>Thread-393::DEBUG::2012-04-06 14:55:55,647::task::588::TaskManager.Task::(_updateState) Task=`6e19e813-1090-490d-8140-c4521e4b8853`::moving from state init -> state preparing
>Thread-393::INFO::2012-04-06 14:55:55,647::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5a526aab-7488-4e8d-a05a-73a3c27db31c', spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', imgUUID='0cdee4ac-5c14-4c63-8d5e-c16b540b3ce7', volUUID='a8fd1587-9932-4cb8-ac78-b2f709a749af', options=None)
>Thread-393::DEBUG::2012-04-06 14:55:55,648::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`2ac7fcac-370b-415d-866d-5419b02e51f6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2496' at 'getVolumeSize'
>Thread-393::DEBUG::2012-04-06 14:55:55,648::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' for lock type 'shared'
>Thread-393::DEBUG::2012-04-06 14:55:55,649::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free. Now locking as 'shared' (1 active user)
>Thread-393::DEBUG::2012-04-06 14:55:55,649::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`2ac7fcac-370b-415d-866d-5419b02e51f6`::Granted request
>Thread-393::DEBUG::2012-04-06 14:55:55,649::task::817::TaskManager.Task::(resourceAcquired) Task=`6e19e813-1090-490d-8140-c4521e4b8853`::_resourcesAcquired: Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c (shared)
>Thread-393::DEBUG::2012-04-06 14:55:55,650::task::978::TaskManager.Task::(_decref) Task=`6e19e813-1090-490d-8140-c4521e4b8853`::ref 1 aborting False
>Thread-393::INFO::2012-04-06 14:55:55,650::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '4294967296', 'apparentsize': '4294967296'}
>Thread-393::DEBUG::2012-04-06 14:55:55,650::task::1172::TaskManager.Task::(prepare) Task=`6e19e813-1090-490d-8140-c4521e4b8853`::finished: {'truesize': '4294967296', 'apparentsize': '4294967296'}
>Thread-393::DEBUG::2012-04-06 14:55:55,651::task::588::TaskManager.Task::(_updateState) Task=`6e19e813-1090-490d-8140-c4521e4b8853`::moving from state preparing -> state finished
>Thread-393::DEBUG::2012-04-06 14:55:55,651::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c': < ResourceRef 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', isValid: 'True' obj: 'None'>}
>Thread-393::DEBUG::2012-04-06 14:55:55,651::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-393::DEBUG::2012-04-06 14:55:55,651::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c'
>Thread-393::DEBUG::2012-04-06 14:55:55,652::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' (0 active users)
>Thread-393::DEBUG::2012-04-06 14:55:55,652::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free, finding out if anyone is waiting for it.
>Thread-393::DEBUG::2012-04-06 14:55:55,652::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', Clearing records.
>Thread-393::DEBUG::2012-04-06 14:55:55,652::task::978::TaskManager.Task::(_decref) Task=`6e19e813-1090-490d-8140-c4521e4b8853`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:55,859::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:55,927::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.033709 s, 30.4 MB/s\n'; <rc> = 0
>Thread-981::DEBUG::2012-04-06 14:55:56,960::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-981::DEBUG::2012-04-06 14:55:56,960::task::588::TaskManager.Task::(_updateState) Task=`137f9e68-e304-4363-af7e-ff2c2825e9d1`::moving from state init -> state preparing
>Thread-981::INFO::2012-04-06 14:55:56,961::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-981::INFO::2012-04-06 14:55:56,961::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-981::DEBUG::2012-04-06 14:55:56,961::task::1172::TaskManager.Task::(prepare) Task=`137f9e68-e304-4363-af7e-ff2c2825e9d1`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-981::DEBUG::2012-04-06 14:55:56,962::task::588::TaskManager.Task::(_updateState) Task=`137f9e68-e304-4363-af7e-ff2c2825e9d1`::moving from state preparing -> state finished
>Thread-981::DEBUG::2012-04-06 14:55:56,962::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-981::DEBUG::2012-04-06 14:55:56,962::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-981::DEBUG::2012-04-06 14:55:56,963::task::978::TaskManager.Task::(_decref) Task=`137f9e68-e304-4363-af7e-ff2c2825e9d1`::ref 0 aborting False
>Thread-982::DEBUG::2012-04-06 14:55:56,966::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-982::DEBUG::2012-04-06 14:55:56,967::task::588::TaskManager.Task::(_updateState) Task=`fbda5691-a739-48e2-89f9-64f97bd8a47a`::moving from state init -> state preparing
>Thread-982::INFO::2012-04-06 14:55:56,967::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-982::DEBUG::2012-04-06 14:55:56,968::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`537f30bf-c208-4451-8e4c-590c69ccb9f2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-982::DEBUG::2012-04-06 14:55:56,968::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-982::DEBUG::2012-04-06 14:55:56,968::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-982::DEBUG::2012-04-06 14:55:56,969::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`537f30bf-c208-4451-8e4c-590c69ccb9f2`::Granted request
>Thread-982::DEBUG::2012-04-06 14:55:56,969::task::817::TaskManager.Task::(resourceAcquired) Task=`fbda5691-a739-48e2-89f9-64f97bd8a47a`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-982::DEBUG::2012-04-06 14:55:56,969::task::978::TaskManager.Task::(_decref) Task=`fbda5691-a739-48e2-89f9-64f97bd8a47a`::ref 1 aborting False
>Thread-982::INFO::2012-04-06 14:55:56,970::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-982::DEBUG::2012-04-06 14:55:56,970::task::1172::TaskManager.Task::(prepare) Task=`fbda5691-a739-48e2-89f9-64f97bd8a47a`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-982::DEBUG::2012-04-06 14:55:56,971::task::588::TaskManager.Task::(_updateState) Task=`fbda5691-a739-48e2-89f9-64f97bd8a47a`::moving from state preparing -> state finished
>Thread-982::DEBUG::2012-04-06 14:55:56,971::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-982::DEBUG::2012-04-06 14:55:56,971::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-982::DEBUG::2012-04-06 14:55:56,972::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-982::DEBUG::2012-04-06 14:55:56,972::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-982::DEBUG::2012-04-06 14:55:56,972::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-982::DEBUG::2012-04-06 14:55:56,973::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-982::DEBUG::2012-04-06 14:55:56,973::task::978::TaskManager.Task::(_decref) Task=`fbda5691-a739-48e2-89f9-64f97bd8a47a`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:55:57,933::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:55:58,004::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0369902 s, 27.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:00,013::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:00,083::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360238 s, 28.4 MB/s\n'; <rc> = 0
>Thread-984::DEBUG::2012-04-06 14:56:00,871::task::588::TaskManager.Task::(_updateState) Task=`ed20388b-563f-42a8-96ff-b73a93ca4ad0`::moving from state init -> state preparing
>Thread-984::INFO::2012-04-06 14:56:00,871::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-984::INFO::2012-04-06 14:56:00,871::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000611066818237', 'lastCheck': 1333716952.057965, 'code': 0, 'valid': True}}
>Thread-984::DEBUG::2012-04-06 14:56:00,872::task::1172::TaskManager.Task::(prepare) Task=`ed20388b-563f-42a8-96ff-b73a93ca4ad0`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000611066818237', 'lastCheck': 1333716952.057965, 'code': 0, 'valid': True}}
>Thread-984::DEBUG::2012-04-06 14:56:00,872::task::588::TaskManager.Task::(_updateState) Task=`ed20388b-563f-42a8-96ff-b73a93ca4ad0`::moving from state preparing -> state finished
>Thread-984::DEBUG::2012-04-06 14:56:00,872::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-984::DEBUG::2012-04-06 14:56:00,872::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-984::DEBUG::2012-04-06 14:56:00,873::task::978::TaskManager.Task::(_decref) Task=`ed20388b-563f-42a8-96ff-b73a93ca4ad0`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:02,091::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:02,157::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.032967 s, 31.1 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:04,166::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:04,236::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0363294 s, 28.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:06,244::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:06,315::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0363538 s, 28.2 MB/s\n'; <rc> = 0
>Thread-989::DEBUG::2012-04-06 14:56:06,991::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-989::DEBUG::2012-04-06 14:56:06,992::task::588::TaskManager.Task::(_updateState) Task=`96fcd87c-afe7-45e4-a138-5aa0dc2f49c5`::moving from state init -> state preparing
>Thread-989::INFO::2012-04-06 14:56:06,992::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-989::INFO::2012-04-06 14:56:06,993::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-989::DEBUG::2012-04-06 14:56:06,993::task::1172::TaskManager.Task::(prepare) Task=`96fcd87c-afe7-45e4-a138-5aa0dc2f49c5`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-989::DEBUG::2012-04-06 14:56:06,993::task::588::TaskManager.Task::(_updateState) Task=`96fcd87c-afe7-45e4-a138-5aa0dc2f49c5`::moving from state preparing -> state finished
>Thread-989::DEBUG::2012-04-06 14:56:06,994::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-989::DEBUG::2012-04-06 14:56:06,994::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-989::DEBUG::2012-04-06 14:56:06,994::task::978::TaskManager.Task::(_decref) Task=`96fcd87c-afe7-45e4-a138-5aa0dc2f49c5`::ref 0 aborting False
>Thread-990::DEBUG::2012-04-06 14:56:06,998::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-990::DEBUG::2012-04-06 14:56:06,999::task::588::TaskManager.Task::(_updateState) Task=`49399ede-1521-41b3-b40c-7a19ddaa117a`::moving from state init -> state preparing
>Thread-990::INFO::2012-04-06 14:56:06,999::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-990::DEBUG::2012-04-06 14:56:07,000::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`0f110a20-9c61-4fae-842f-81cfed6846e6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-990::DEBUG::2012-04-06 14:56:07,000::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-990::DEBUG::2012-04-06 14:56:07,000::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-990::DEBUG::2012-04-06 14:56:07,000::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`0f110a20-9c61-4fae-842f-81cfed6846e6`::Granted request
>Thread-990::DEBUG::2012-04-06 14:56:07,001::task::817::TaskManager.Task::(resourceAcquired) Task=`49399ede-1521-41b3-b40c-7a19ddaa117a`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-990::DEBUG::2012-04-06 14:56:07,001::task::978::TaskManager.Task::(_decref) Task=`49399ede-1521-41b3-b40c-7a19ddaa117a`::ref 1 aborting False
>Thread-990::INFO::2012-04-06 14:56:07,002::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-990::DEBUG::2012-04-06 14:56:07,002::task::1172::TaskManager.Task::(prepare) Task=`49399ede-1521-41b3-b40c-7a19ddaa117a`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-990::DEBUG::2012-04-06 14:56:07,003::task::588::TaskManager.Task::(_updateState) Task=`49399ede-1521-41b3-b40c-7a19ddaa117a`::moving from state preparing -> state finished
>Thread-990::DEBUG::2012-04-06 14:56:07,003::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-990::DEBUG::2012-04-06 14:56:07,003::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-990::DEBUG::2012-04-06 14:56:07,004::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-990::DEBUG::2012-04-06 14:56:07,004::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-990::DEBUG::2012-04-06 14:56:07,004::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-990::DEBUG::2012-04-06 14:56:07,004::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-990::DEBUG::2012-04-06 14:56:07,005::task::978::TaskManager.Task::(_decref) Task=`49399ede-1521-41b3-b40c-7a19ddaa117a`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:08,323::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:08,395::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0369914 s, 27.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:10,403::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:10,472::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0356268 s, 28.7 MB/s\n'; <rc> = 0
>Thread-992::DEBUG::2012-04-06 14:56:11,003::task::588::TaskManager.Task::(_updateState) Task=`57a33028-c175-41a5-9f70-3b6e2e4460b7`::moving from state init -> state preparing
>Thread-992::INFO::2012-04-06 14:56:11,004::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-992::INFO::2012-04-06 14:56:11,004::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000599145889282', 'lastCheck': 1333716962.060003, 'code': 0, 'valid': True}}
>Thread-992::DEBUG::2012-04-06 14:56:11,004::task::1172::TaskManager.Task::(prepare) Task=`57a33028-c175-41a5-9f70-3b6e2e4460b7`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000599145889282', 'lastCheck': 1333716962.060003, 'code': 0, 'valid': True}}
>Thread-992::DEBUG::2012-04-06 14:56:11,005::task::588::TaskManager.Task::(_updateState) Task=`57a33028-c175-41a5-9f70-3b6e2e4460b7`::moving from state preparing -> state finished
>Thread-992::DEBUG::2012-04-06 14:56:11,005::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-992::DEBUG::2012-04-06 14:56:11,005::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-992::DEBUG::2012-04-06 14:56:11,005::task::978::TaskManager.Task::(_decref) Task=`57a33028-c175-41a5-9f70-3b6e2e4460b7`::ref 0 aborting False
>Thread-79::DEBUG::2012-04-06 14:56:12,060::lvm::301::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgck --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"a%36006048c0714062ba4b91f6a904bc07f|36006048c12952607a6254682d950135a|36006048c14e9eb8f668dfc53ea5995ca|36006048c78acaa6eac8ebc05bf73dee1|36006048cc786b195adb3de2b6d613cbc|36006048ce7ff8320bd02378f18cf9712%\\", \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " 5a526aab-7488-4e8d-a05a-73a3c27db31c' (cwd None)
>Thread-79::DEBUG::2012-04-06 14:56:12,275::lvm::301::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:12,479::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:12,550::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036112 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:14,561::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:14,631::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0361196 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:16,640::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:16,710::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036129 s, 28.3 MB/s\n'; <rc> = 0
>Thread-996::DEBUG::2012-04-06 14:56:17,024::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-996::DEBUG::2012-04-06 14:56:17,025::task::588::TaskManager.Task::(_updateState) Task=`55212b25-55ef-47fd-9103-30620e9cffb8`::moving from state init -> state preparing
>Thread-996::INFO::2012-04-06 14:56:17,025::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-996::INFO::2012-04-06 14:56:17,026::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-996::DEBUG::2012-04-06 14:56:17,026::task::1172::TaskManager.Task::(prepare) Task=`55212b25-55ef-47fd-9103-30620e9cffb8`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-996::DEBUG::2012-04-06 14:56:17,026::task::588::TaskManager.Task::(_updateState) Task=`55212b25-55ef-47fd-9103-30620e9cffb8`::moving from state preparing -> state finished
>Thread-996::DEBUG::2012-04-06 14:56:17,027::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-996::DEBUG::2012-04-06 14:56:17,027::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-996::DEBUG::2012-04-06 14:56:17,027::task::978::TaskManager.Task::(_decref) Task=`55212b25-55ef-47fd-9103-30620e9cffb8`::ref 0 aborting False
>Thread-997::DEBUG::2012-04-06 14:56:17,031::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-997::DEBUG::2012-04-06 14:56:17,031::task::588::TaskManager.Task::(_updateState) Task=`8e609eff-f3bb-40d8-8569-c504db94bc59`::moving from state init -> state preparing
>Thread-997::INFO::2012-04-06 14:56:17,032::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-997::DEBUG::2012-04-06 14:56:17,032::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`8d5616fe-112a-4f49-85b5-b25813d01493`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-997::DEBUG::2012-04-06 14:56:17,033::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-997::DEBUG::2012-04-06 14:56:17,033::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-997::DEBUG::2012-04-06 14:56:17,033::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`8d5616fe-112a-4f49-85b5-b25813d01493`::Granted request
>Thread-997::DEBUG::2012-04-06 14:56:17,034::task::817::TaskManager.Task::(resourceAcquired) Task=`8e609eff-f3bb-40d8-8569-c504db94bc59`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-997::DEBUG::2012-04-06 14:56:17,034::task::978::TaskManager.Task::(_decref) Task=`8e609eff-f3bb-40d8-8569-c504db94bc59`::ref 1 aborting False
>Thread-997::INFO::2012-04-06 14:56:17,035::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-997::DEBUG::2012-04-06 14:56:17,035::task::1172::TaskManager.Task::(prepare) Task=`8e609eff-f3bb-40d8-8569-c504db94bc59`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-997::DEBUG::2012-04-06 14:56:17,035::task::588::TaskManager.Task::(_updateState) Task=`8e609eff-f3bb-40d8-8569-c504db94bc59`::moving from state preparing -> state finished
>Thread-997::DEBUG::2012-04-06 14:56:17,036::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-997::DEBUG::2012-04-06 14:56:17,036::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-997::DEBUG::2012-04-06 14:56:17,036::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-997::DEBUG::2012-04-06 14:56:17,037::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-997::DEBUG::2012-04-06 14:56:17,037::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-997::DEBUG::2012-04-06 14:56:17,037::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-997::DEBUG::2012-04-06 14:56:17,038::task::978::TaskManager.Task::(_decref) Task=`8e609eff-f3bb-40d8-8569-c504db94bc59`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:18,718::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:18,787::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360558 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:20,796::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:20,868::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0393041 s, 26.1 MB/s\n'; <rc> = 0
>Thread-1000::DEBUG::2012-04-06 14:56:21,101::task::588::TaskManager.Task::(_updateState) Task=`42c0cdf7-0076-4287-a3f4-3e5d2e4a17c7`::moving from state init -> state preparing
>Thread-1000::INFO::2012-04-06 14:56:21,101::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1000::INFO::2012-04-06 14:56:21,102::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000924110412598', 'lastCheck': 1333716972.2779989, 'code': 0, 'valid': True}}
>Thread-1000::DEBUG::2012-04-06 14:56:21,102::task::1172::TaskManager.Task::(prepare) Task=`42c0cdf7-0076-4287-a3f4-3e5d2e4a17c7`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.000924110412598', 'lastCheck': 1333716972.2779989, 'code': 0, 'valid': True}}
>Thread-1000::DEBUG::2012-04-06 14:56:21,102::task::588::TaskManager.Task::(_updateState) Task=`42c0cdf7-0076-4287-a3f4-3e5d2e4a17c7`::moving from state preparing -> state finished
>Thread-1000::DEBUG::2012-04-06 14:56:21,103::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1000::DEBUG::2012-04-06 14:56:21,103::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1000::DEBUG::2012-04-06 14:56:21,103::task::978::TaskManager.Task::(_decref) Task=`42c0cdf7-0076-4287-a3f4-3e5d2e4a17c7`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:22,877::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:22,947::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0365764 s, 28.0 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2012-04-06 14:56:24,277::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 319.
>Thread-642::DEBUG::2012-04-06 14:56:24,485::task::588::TaskManager.Task::(_updateState) Task=`ad782b3c-2dc7-4c1a-b78f-e227b9507eb0`::moving from state init -> state preparing
>Thread-642::INFO::2012-04-06 14:56:24,486::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5a526aab-7488-4e8d-a05a-73a3c27db31c', spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', imgUUID='816042f6-b056-42fd-8154-e766aec76bfd', volUUID='8718328b-f49c-4f3d-b7d8-a51702424f1c', options=None)
>Thread-642::DEBUG::2012-04-06 14:56:24,486::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`f9ec235d-2dfa-4399-ae00-dbf7b36b5338`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2496' at 'getVolumeSize'
>Thread-642::DEBUG::2012-04-06 14:56:24,486::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' for lock type 'shared'
>Thread-642::DEBUG::2012-04-06 14:56:24,487::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free. Now locking as 'shared' (1 active user)
>Thread-642::DEBUG::2012-04-06 14:56:24,487::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`f9ec235d-2dfa-4399-ae00-dbf7b36b5338`::Granted request
>Thread-642::DEBUG::2012-04-06 14:56:24,488::task::817::TaskManager.Task::(resourceAcquired) Task=`ad782b3c-2dc7-4c1a-b78f-e227b9507eb0`::_resourcesAcquired: Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c (shared)
>Thread-642::DEBUG::2012-04-06 14:56:24,488::task::978::TaskManager.Task::(_decref) Task=`ad782b3c-2dc7-4c1a-b78f-e227b9507eb0`::ref 1 aborting False
>Thread-642::INFO::2012-04-06 14:56:24,489::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '10737418240', 'apparentsize': '10737418240'}
>Thread-642::DEBUG::2012-04-06 14:56:24,489::task::1172::TaskManager.Task::(prepare) Task=`ad782b3c-2dc7-4c1a-b78f-e227b9507eb0`::finished: {'truesize': '10737418240', 'apparentsize': '10737418240'}
>Thread-642::DEBUG::2012-04-06 14:56:24,489::task::588::TaskManager.Task::(_updateState) Task=`ad782b3c-2dc7-4c1a-b78f-e227b9507eb0`::moving from state preparing -> state finished
>Thread-642::DEBUG::2012-04-06 14:56:24,489::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c': < ResourceRef 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', isValid: 'True' obj: 'None'>}
>Thread-642::DEBUG::2012-04-06 14:56:24,490::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-642::DEBUG::2012-04-06 14:56:24,490::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c'
>Thread-642::DEBUG::2012-04-06 14:56:24,490::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' (0 active users)
>Thread-642::DEBUG::2012-04-06 14:56:24,491::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free, finding out if anyone is waiting for it.
>Thread-642::DEBUG::2012-04-06 14:56:24,491::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', Clearing records.
>Thread-642::DEBUG::2012-04-06 14:56:24,491::task::978::TaskManager.Task::(_decref) Task=`ad782b3c-2dc7-4c1a-b78f-e227b9507eb0`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:24,955::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:25,027::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0378583 s, 27.0 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:27,035::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Thread-1004::DEBUG::2012-04-06 14:56:27,063::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1004::DEBUG::2012-04-06 14:56:27,064::task::588::TaskManager.Task::(_updateState) Task=`a2fd6cd8-43e4-4d28-bad3-68e8c2e39d26`::moving from state init -> state preparing
>Thread-1004::INFO::2012-04-06 14:56:27,064::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1004::INFO::2012-04-06 14:56:27,065::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1004::DEBUG::2012-04-06 14:56:27,065::task::1172::TaskManager.Task::(prepare) Task=`a2fd6cd8-43e4-4d28-bad3-68e8c2e39d26`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1004::DEBUG::2012-04-06 14:56:27,065::task::588::TaskManager.Task::(_updateState) Task=`a2fd6cd8-43e4-4d28-bad3-68e8c2e39d26`::moving from state preparing -> state finished
>Thread-1004::DEBUG::2012-04-06 14:56:27,066::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1004::DEBUG::2012-04-06 14:56:27,066::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1004::DEBUG::2012-04-06 14:56:27,066::task::978::TaskManager.Task::(_decref) Task=`a2fd6cd8-43e4-4d28-bad3-68e8c2e39d26`::ref 0 aborting False
>Thread-1005::DEBUG::2012-04-06 14:56:27,071::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1005::DEBUG::2012-04-06 14:56:27,071::task::588::TaskManager.Task::(_updateState) Task=`b54fbfee-2620-4b4e-ae4c-519a102e5fa8`::moving from state init -> state preparing
>Thread-1005::INFO::2012-04-06 14:56:27,072::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1005::DEBUG::2012-04-06 14:56:27,072::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`6bcb7b52-520b-4093-94f1-c152e76de785`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1005::DEBUG::2012-04-06 14:56:27,073::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1005::DEBUG::2012-04-06 14:56:27,073::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1005::DEBUG::2012-04-06 14:56:27,074::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`6bcb7b52-520b-4093-94f1-c152e76de785`::Granted request
>Thread-1005::DEBUG::2012-04-06 14:56:27,074::task::817::TaskManager.Task::(resourceAcquired) Task=`b54fbfee-2620-4b4e-ae4c-519a102e5fa8`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1005::DEBUG::2012-04-06 14:56:27,074::task::978::TaskManager.Task::(_decref) Task=`b54fbfee-2620-4b4e-ae4c-519a102e5fa8`::ref 1 aborting False
>Thread-1005::INFO::2012-04-06 14:56:27,075::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1005::DEBUG::2012-04-06 14:56:27,076::task::1172::TaskManager.Task::(prepare) Task=`b54fbfee-2620-4b4e-ae4c-519a102e5fa8`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1005::DEBUG::2012-04-06 14:56:27,076::task::588::TaskManager.Task::(_updateState) Task=`b54fbfee-2620-4b4e-ae4c-519a102e5fa8`::moving from state preparing -> state finished
>Thread-1005::DEBUG::2012-04-06 14:56:27,077::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1005::DEBUG::2012-04-06 14:56:27,077::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1005::DEBUG::2012-04-06 14:56:27,077::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1005::DEBUG::2012-04-06 14:56:27,078::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1005::DEBUG::2012-04-06 14:56:27,078::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1005::DEBUG::2012-04-06 14:56:27,079::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1005::DEBUG::2012-04-06 14:56:27,079::task::978::TaskManager.Task::(_decref) Task=`b54fbfee-2620-4b4e-ae4c-519a102e5fa8`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:27,125::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0521567 s, 19.6 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:29,132::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:29,206::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.037804 s, 27.1 MB/s\n'; <rc> = 0
>Thread-1008::DEBUG::2012-04-06 14:56:31,196::task::588::TaskManager.Task::(_updateState) Task=`114d7e37-d9e6-45c6-ba3b-14daf2bbb103`::moving from state init -> state preparing
>Thread-1008::INFO::2012-04-06 14:56:31,196::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1008::INFO::2012-04-06 14:56:31,196::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00475597381592', 'lastCheck': 1333716982.284199, 'code': 0, 'valid': True}}
>Thread-1008::DEBUG::2012-04-06 14:56:31,197::task::1172::TaskManager.Task::(prepare) Task=`114d7e37-d9e6-45c6-ba3b-14daf2bbb103`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00475597381592', 'lastCheck': 1333716982.284199, 'code': 0, 'valid': True}}
>Thread-1008::DEBUG::2012-04-06 14:56:31,197::task::588::TaskManager.Task::(_updateState) Task=`114d7e37-d9e6-45c6-ba3b-14daf2bbb103`::moving from state preparing -> state finished
>Thread-1008::DEBUG::2012-04-06 14:56:31,197::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1008::DEBUG::2012-04-06 14:56:31,197::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1008::DEBUG::2012-04-06 14:56:31,198::task::978::TaskManager.Task::(_decref) Task=`114d7e37-d9e6-45c6-ba3b-14daf2bbb103`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:31,214::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:31,285::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360603 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:33,293::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:33,365::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0372695 s, 27.5 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:35,374::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:35,444::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036453 s, 28.1 MB/s\n'; <rc> = 0
>Thread-1012::DEBUG::2012-04-06 14:56:37,103::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1012::DEBUG::2012-04-06 14:56:37,104::task::588::TaskManager.Task::(_updateState) Task=`cbf769b7-5c10-4ae3-bafe-5ff87662180b`::moving from state init -> state preparing
>Thread-1012::INFO::2012-04-06 14:56:37,104::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1012::INFO::2012-04-06 14:56:37,105::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1012::DEBUG::2012-04-06 14:56:37,105::task::1172::TaskManager.Task::(prepare) Task=`cbf769b7-5c10-4ae3-bafe-5ff87662180b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1012::DEBUG::2012-04-06 14:56:37,105::task::588::TaskManager.Task::(_updateState) Task=`cbf769b7-5c10-4ae3-bafe-5ff87662180b`::moving from state preparing -> state finished
>Thread-1012::DEBUG::2012-04-06 14:56:37,105::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1012::DEBUG::2012-04-06 14:56:37,106::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1012::DEBUG::2012-04-06 14:56:37,106::task::978::TaskManager.Task::(_decref) Task=`cbf769b7-5c10-4ae3-bafe-5ff87662180b`::ref 0 aborting False
>Thread-1013::DEBUG::2012-04-06 14:56:37,110::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1013::DEBUG::2012-04-06 14:56:37,110::task::588::TaskManager.Task::(_updateState) Task=`b21c2fcd-10a8-4913-816f-df7fb6947b9c`::moving from state init -> state preparing
>Thread-1013::INFO::2012-04-06 14:56:37,111::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1013::DEBUG::2012-04-06 14:56:37,111::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`79b8a334-a5fa-4c6d-910d-36fc99b8d9d9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1013::DEBUG::2012-04-06 14:56:37,111::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1013::DEBUG::2012-04-06 14:56:37,112::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1013::DEBUG::2012-04-06 14:56:37,112::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`79b8a334-a5fa-4c6d-910d-36fc99b8d9d9`::Granted request
>Thread-1013::DEBUG::2012-04-06 14:56:37,113::task::817::TaskManager.Task::(resourceAcquired) Task=`b21c2fcd-10a8-4913-816f-df7fb6947b9c`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1013::DEBUG::2012-04-06 14:56:37,113::task::978::TaskManager.Task::(_decref) Task=`b21c2fcd-10a8-4913-816f-df7fb6947b9c`::ref 1 aborting False
>Thread-1013::INFO::2012-04-06 14:56:37,114::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1013::DEBUG::2012-04-06 14:56:37,114::task::1172::TaskManager.Task::(prepare) Task=`b21c2fcd-10a8-4913-816f-df7fb6947b9c`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1013::DEBUG::2012-04-06 14:56:37,114::task::588::TaskManager.Task::(_updateState) Task=`b21c2fcd-10a8-4913-816f-df7fb6947b9c`::moving from state preparing -> state finished
>Thread-1013::DEBUG::2012-04-06 14:56:37,115::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1013::DEBUG::2012-04-06 14:56:37,115::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1013::DEBUG::2012-04-06 14:56:37,115::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1013::DEBUG::2012-04-06 14:56:37,115::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1013::DEBUG::2012-04-06 14:56:37,116::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1013::DEBUG::2012-04-06 14:56:37,116::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1013::DEBUG::2012-04-06 14:56:37,116::task::978::TaskManager.Task::(_decref) Task=`b21c2fcd-10a8-4913-816f-df7fb6947b9c`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:37,452::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:37,528::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0417477 s, 24.5 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:39,536::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:39,612::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0419484 s, 24.4 MB/s\n'; <rc> = 0
>Thread-1016::DEBUG::2012-04-06 14:56:41,296::task::588::TaskManager.Task::(_updateState) Task=`8a8b9ea6-eec4-40a5-9383-f3c038237da7`::moving from state init -> state preparing
>Thread-1016::INFO::2012-04-06 14:56:41,297::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1016::INFO::2012-04-06 14:56:41,297::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00707197189331', 'lastCheck': 1333716992.292856, 'code': 0, 'valid': True}}
>Thread-1016::DEBUG::2012-04-06 14:56:41,297::task::1172::TaskManager.Task::(prepare) Task=`8a8b9ea6-eec4-40a5-9383-f3c038237da7`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00707197189331', 'lastCheck': 1333716992.292856, 'code': 0, 'valid': True}}
>Thread-1016::DEBUG::2012-04-06 14:56:41,298::task::588::TaskManager.Task::(_updateState) Task=`8a8b9ea6-eec4-40a5-9383-f3c038237da7`::moving from state preparing -> state finished
>Thread-1016::DEBUG::2012-04-06 14:56:41,298::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1016::DEBUG::2012-04-06 14:56:41,298::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1016::DEBUG::2012-04-06 14:56:41,298::task::978::TaskManager.Task::(_decref) Task=`8a8b9ea6-eec4-40a5-9383-f3c038237da7`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:41,620::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:41,690::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0362607 s, 28.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:43,698::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:43,767::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0347959 s, 29.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:45,775::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:45,850::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.040709 s, 25.2 MB/s\n'; <rc> = 0
>Thread-1020::DEBUG::2012-04-06 14:56:47,137::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1020::DEBUG::2012-04-06 14:56:47,138::task::588::TaskManager.Task::(_updateState) Task=`68e057c7-9b3c-49c3-beb3-f7d5c5556b32`::moving from state init -> state preparing
>Thread-1020::INFO::2012-04-06 14:56:47,138::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1020::INFO::2012-04-06 14:56:47,139::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1020::DEBUG::2012-04-06 14:56:47,139::task::1172::TaskManager.Task::(prepare) Task=`68e057c7-9b3c-49c3-beb3-f7d5c5556b32`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1020::DEBUG::2012-04-06 14:56:47,139::task::588::TaskManager.Task::(_updateState) Task=`68e057c7-9b3c-49c3-beb3-f7d5c5556b32`::moving from state preparing -> state finished
>Thread-1020::DEBUG::2012-04-06 14:56:47,139::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1020::DEBUG::2012-04-06 14:56:47,140::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1020::DEBUG::2012-04-06 14:56:47,140::task::978::TaskManager.Task::(_decref) Task=`68e057c7-9b3c-49c3-beb3-f7d5c5556b32`::ref 0 aborting False
>Thread-1021::DEBUG::2012-04-06 14:56:47,144::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1021::DEBUG::2012-04-06 14:56:47,144::task::588::TaskManager.Task::(_updateState) Task=`17bf4deb-cc77-432d-8f62-363a67027ee5`::moving from state init -> state preparing
>Thread-1021::INFO::2012-04-06 14:56:47,144::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1021::DEBUG::2012-04-06 14:56:47,145::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`3fc23819-4505-4911-934b-c70097bc8e19`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1021::DEBUG::2012-04-06 14:56:47,145::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1021::DEBUG::2012-04-06 14:56:47,145::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1021::DEBUG::2012-04-06 14:56:47,146::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`3fc23819-4505-4911-934b-c70097bc8e19`::Granted request
>Thread-1021::DEBUG::2012-04-06 14:56:47,146::task::817::TaskManager.Task::(resourceAcquired) Task=`17bf4deb-cc77-432d-8f62-363a67027ee5`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1021::DEBUG::2012-04-06 14:56:47,146::task::978::TaskManager.Task::(_decref) Task=`17bf4deb-cc77-432d-8f62-363a67027ee5`::ref 1 aborting False
>Thread-1021::INFO::2012-04-06 14:56:47,147::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1021::DEBUG::2012-04-06 14:56:47,148::task::1172::TaskManager.Task::(prepare) Task=`17bf4deb-cc77-432d-8f62-363a67027ee5`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1021::DEBUG::2012-04-06 14:56:47,148::task::588::TaskManager.Task::(_updateState) Task=`17bf4deb-cc77-432d-8f62-363a67027ee5`::moving from state preparing -> state finished
>Thread-1021::DEBUG::2012-04-06 14:56:47,148::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1021::DEBUG::2012-04-06 14:56:47,148::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1021::DEBUG::2012-04-06 14:56:47,149::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1021::DEBUG::2012-04-06 14:56:47,149::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1021::DEBUG::2012-04-06 14:56:47,149::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1021::DEBUG::2012-04-06 14:56:47,150::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1021::DEBUG::2012-04-06 14:56:47,150::task::978::TaskManager.Task::(_decref) Task=`17bf4deb-cc77-432d-8f62-363a67027ee5`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:47,858::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:47,935::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0431232 s, 23.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:49,943::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:50,018::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.040449 s, 25.3 MB/s\n'; <rc> = 0
>Thread-1024::DEBUG::2012-04-06 14:56:51,400::task::588::TaskManager.Task::(_updateState) Task=`4a389eed-570a-4525-a72a-98f112904b0c`::moving from state init -> state preparing
>Thread-1024::INFO::2012-04-06 14:56:51,400::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1024::INFO::2012-04-06 14:56:51,401::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00528717041016', 'lastCheck': 1333717002.2996809, 'code': 0, 'valid': True}}
>Thread-1024::DEBUG::2012-04-06 14:56:51,401::task::1172::TaskManager.Task::(prepare) Task=`4a389eed-570a-4525-a72a-98f112904b0c`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00528717041016', 'lastCheck': 1333717002.2996809, 'code': 0, 'valid': True}}
>Thread-1024::DEBUG::2012-04-06 14:56:51,401::task::588::TaskManager.Task::(_updateState) Task=`4a389eed-570a-4525-a72a-98f112904b0c`::moving from state preparing -> state finished
>Thread-1024::DEBUG::2012-04-06 14:56:51,402::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1024::DEBUG::2012-04-06 14:56:51,402::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1024::DEBUG::2012-04-06 14:56:51,402::task::978::TaskManager.Task::(_decref) Task=`4a389eed-570a-4525-a72a-98f112904b0c`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:52,026::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:52,096::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0363252 s, 28.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:56:54,104::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:54,185::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.04806 s, 21.3 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2012-04-06 14:56:54,285::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 319.
>Thread-393::DEBUG::2012-04-06 14:56:55,861::task::588::TaskManager.Task::(_updateState) Task=`b9fbb2b6-be38-4dd9-a797-3a21a14200ac`::moving from state init -> state preparing
>Thread-393::INFO::2012-04-06 14:56:55,861::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5a526aab-7488-4e8d-a05a-73a3c27db31c', spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', imgUUID='0cdee4ac-5c14-4c63-8d5e-c16b540b3ce7', volUUID='a8fd1587-9932-4cb8-ac78-b2f709a749af', options=None)
>Thread-393::DEBUG::2012-04-06 14:56:55,862::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`51a97362-6eae-4b91-8602-84eb347b78c9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2496' at 'getVolumeSize'
>Thread-393::DEBUG::2012-04-06 14:56:55,862::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' for lock type 'shared'
>Thread-393::DEBUG::2012-04-06 14:56:55,862::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free. Now locking as 'shared' (1 active user)
>Thread-393::DEBUG::2012-04-06 14:56:55,863::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`51a97362-6eae-4b91-8602-84eb347b78c9`::Granted request
>Thread-393::DEBUG::2012-04-06 14:56:55,863::task::817::TaskManager.Task::(resourceAcquired) Task=`b9fbb2b6-be38-4dd9-a797-3a21a14200ac`::_resourcesAcquired: Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c (shared)
>Thread-393::DEBUG::2012-04-06 14:56:55,863::task::978::TaskManager.Task::(_decref) Task=`b9fbb2b6-be38-4dd9-a797-3a21a14200ac`::ref 1 aborting False
>Thread-393::INFO::2012-04-06 14:56:55,864::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '4294967296', 'apparentsize': '4294967296'}
>Thread-393::DEBUG::2012-04-06 14:56:55,864::task::1172::TaskManager.Task::(prepare) Task=`b9fbb2b6-be38-4dd9-a797-3a21a14200ac`::finished: {'truesize': '4294967296', 'apparentsize': '4294967296'}
>Thread-393::DEBUG::2012-04-06 14:56:55,864::task::588::TaskManager.Task::(_updateState) Task=`b9fbb2b6-be38-4dd9-a797-3a21a14200ac`::moving from state preparing -> state finished
>Thread-393::DEBUG::2012-04-06 14:56:55,865::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c': < ResourceRef 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', isValid: 'True' obj: 'None'>}
>Thread-393::DEBUG::2012-04-06 14:56:55,865::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-393::DEBUG::2012-04-06 14:56:55,865::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c'
>Thread-393::DEBUG::2012-04-06 14:56:55,866::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' (0 active users)
>Thread-393::DEBUG::2012-04-06 14:56:55,866::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free, finding out if anyone is waiting for it.
>Thread-393::DEBUG::2012-04-06 14:56:55,866::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', Clearing records.
>Thread-393::DEBUG::2012-04-06 14:56:55,866::task::978::TaskManager.Task::(_decref) Task=`b9fbb2b6-be38-4dd9-a797-3a21a14200ac`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:56,193::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:56,268::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0412652 s, 24.8 MB/s\n'; <rc> = 0
>Thread-1028::DEBUG::2012-04-06 14:56:57,172::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1028::DEBUG::2012-04-06 14:56:57,173::task::588::TaskManager.Task::(_updateState) Task=`febaa78f-950d-475e-800e-d277bac62487`::moving from state init -> state preparing
>Thread-1028::INFO::2012-04-06 14:56:57,173::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1028::INFO::2012-04-06 14:56:57,174::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1028::DEBUG::2012-04-06 14:56:57,174::task::1172::TaskManager.Task::(prepare) Task=`febaa78f-950d-475e-800e-d277bac62487`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1028::DEBUG::2012-04-06 14:56:57,174::task::588::TaskManager.Task::(_updateState) Task=`febaa78f-950d-475e-800e-d277bac62487`::moving from state preparing -> state finished
>Thread-1028::DEBUG::2012-04-06 14:56:57,174::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1028::DEBUG::2012-04-06 14:56:57,175::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1028::DEBUG::2012-04-06 14:56:57,175::task::978::TaskManager.Task::(_decref) Task=`febaa78f-950d-475e-800e-d277bac62487`::ref 0 aborting False
>Thread-1029::DEBUG::2012-04-06 14:56:57,179::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1029::DEBUG::2012-04-06 14:56:57,180::task::588::TaskManager.Task::(_updateState) Task=`9385694b-da52-4fab-a2ac-bb43490eb64b`::moving from state init -> state preparing
>Thread-1029::INFO::2012-04-06 14:56:57,180::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1029::DEBUG::2012-04-06 14:56:57,180::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`94a2178a-fb63-49fb-95f9-72b1ad1a2848`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1029::DEBUG::2012-04-06 14:56:57,181::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1029::DEBUG::2012-04-06 14:56:57,181::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1029::DEBUG::2012-04-06 14:56:57,181::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`94a2178a-fb63-49fb-95f9-72b1ad1a2848`::Granted request
>Thread-1029::DEBUG::2012-04-06 14:56:57,182::task::817::TaskManager.Task::(resourceAcquired) Task=`9385694b-da52-4fab-a2ac-bb43490eb64b`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1029::DEBUG::2012-04-06 14:56:57,182::task::978::TaskManager.Task::(_decref) Task=`9385694b-da52-4fab-a2ac-bb43490eb64b`::ref 1 aborting False
>Thread-1029::INFO::2012-04-06 14:56:57,183::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1029::DEBUG::2012-04-06 14:56:57,183::task::1172::TaskManager.Task::(prepare) Task=`9385694b-da52-4fab-a2ac-bb43490eb64b`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1029::DEBUG::2012-04-06 14:56:57,183::task::588::TaskManager.Task::(_updateState) Task=`9385694b-da52-4fab-a2ac-bb43490eb64b`::moving from state preparing -> state finished
>Thread-1029::DEBUG::2012-04-06 14:56:57,184::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1029::DEBUG::2012-04-06 14:56:57,184::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1029::DEBUG::2012-04-06 14:56:57,184::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1029::DEBUG::2012-04-06 14:56:57,185::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1029::DEBUG::2012-04-06 14:56:57,185::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1029::DEBUG::2012-04-06 14:56:57,185::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1029::DEBUG::2012-04-06 14:56:57,185::task::978::TaskManager.Task::(_decref) Task=`9385694b-da52-4fab-a2ac-bb43490eb64b`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:56:58,276::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:56:58,348::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0382918 s, 26.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:00,357::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:00,431::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0409522 s, 25.0 MB/s\n'; <rc> = 0
>Thread-1032::DEBUG::2012-04-06 14:57:01,506::task::588::TaskManager.Task::(_updateState) Task=`7c058b9e-8b45-4713-a8e1-297245ac098e`::moving from state init -> state preparing
>Thread-1032::INFO::2012-04-06 14:57:01,507::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1032::INFO::2012-04-06 14:57:01,507::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0143749713898', 'lastCheck': 1333717012.3155661, 'code': 0, 'valid': True}}
>Thread-1032::DEBUG::2012-04-06 14:57:01,507::task::1172::TaskManager.Task::(prepare) Task=`7c058b9e-8b45-4713-a8e1-297245ac098e`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0143749713898', 'lastCheck': 1333717012.3155661, 'code': 0, 'valid': True}}
>Thread-1032::DEBUG::2012-04-06 14:57:01,508::task::588::TaskManager.Task::(_updateState) Task=`7c058b9e-8b45-4713-a8e1-297245ac098e`::moving from state preparing -> state finished
>Thread-1032::DEBUG::2012-04-06 14:57:01,508::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1032::DEBUG::2012-04-06 14:57:01,508::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1032::DEBUG::2012-04-06 14:57:01,508::task::978::TaskManager.Task::(_decref) Task=`7c058b9e-8b45-4713-a8e1-297245ac098e`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:02,440::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:02,510::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0361838 s, 28.3 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:04,518::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:04,589::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0362147 s, 28.3 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:06,597::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:06,667::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0362658 s, 28.2 MB/s\n'; <rc> = 0
>Thread-1036::DEBUG::2012-04-06 14:57:07,212::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1036::DEBUG::2012-04-06 14:57:07,213::task::588::TaskManager.Task::(_updateState) Task=`4bf6bbf1-1b97-4672-94e9-4adf4959c33b`::moving from state init -> state preparing
>Thread-1036::INFO::2012-04-06 14:57:07,213::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1036::INFO::2012-04-06 14:57:07,213::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1036::DEBUG::2012-04-06 14:57:07,214::task::1172::TaskManager.Task::(prepare) Task=`4bf6bbf1-1b97-4672-94e9-4adf4959c33b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1036::DEBUG::2012-04-06 14:57:07,214::task::588::TaskManager.Task::(_updateState) Task=`4bf6bbf1-1b97-4672-94e9-4adf4959c33b`::moving from state preparing -> state finished
>Thread-1036::DEBUG::2012-04-06 14:57:07,214::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1036::DEBUG::2012-04-06 14:57:07,215::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1036::DEBUG::2012-04-06 14:57:07,215::task::978::TaskManager.Task::(_decref) Task=`4bf6bbf1-1b97-4672-94e9-4adf4959c33b`::ref 0 aborting False
>Thread-1037::DEBUG::2012-04-06 14:57:07,219::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1037::DEBUG::2012-04-06 14:57:07,219::task::588::TaskManager.Task::(_updateState) Task=`098e15af-4247-46a8-b02b-37c2948e2940`::moving from state init -> state preparing
>Thread-1037::INFO::2012-04-06 14:57:07,220::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1037::DEBUG::2012-04-06 14:57:07,220::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`c552334a-d3d0-4732-a6ac-de09eb01e15b`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1037::DEBUG::2012-04-06 14:57:07,220::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1037::DEBUG::2012-04-06 14:57:07,221::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1037::DEBUG::2012-04-06 14:57:07,221::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`c552334a-d3d0-4732-a6ac-de09eb01e15b`::Granted request
>Thread-1037::DEBUG::2012-04-06 14:57:07,221::task::817::TaskManager.Task::(resourceAcquired) Task=`098e15af-4247-46a8-b02b-37c2948e2940`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1037::DEBUG::2012-04-06 14:57:07,222::task::978::TaskManager.Task::(_decref) Task=`098e15af-4247-46a8-b02b-37c2948e2940`::ref 1 aborting False
>Thread-1037::INFO::2012-04-06 14:57:07,223::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1037::DEBUG::2012-04-06 14:57:07,223::task::1172::TaskManager.Task::(prepare) Task=`098e15af-4247-46a8-b02b-37c2948e2940`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1037::DEBUG::2012-04-06 14:57:07,223::task::588::TaskManager.Task::(_updateState) Task=`098e15af-4247-46a8-b02b-37c2948e2940`::moving from state preparing -> state finished
>Thread-1037::DEBUG::2012-04-06 14:57:07,223::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1037::DEBUG::2012-04-06 14:57:07,224::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1037::DEBUG::2012-04-06 14:57:07,224::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1037::DEBUG::2012-04-06 14:57:07,224::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1037::DEBUG::2012-04-06 14:57:07,225::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1037::DEBUG::2012-04-06 14:57:07,225::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1037::DEBUG::2012-04-06 14:57:07,225::task::978::TaskManager.Task::(_decref) Task=`098e15af-4247-46a8-b02b-37c2948e2940`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:08,675::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:08,745::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360573 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:10,754::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:10,826::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0361397 s, 28.3 MB/s\n'; <rc> = 0
>Thread-1040::DEBUG::2012-04-06 14:57:11,603::task::588::TaskManager.Task::(_updateState) Task=`cdbc9d26-e418-452a-8c35-b0ca36a3f382`::moving from state init -> state preparing
>Thread-1040::INFO::2012-04-06 14:57:11,603::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1040::INFO::2012-04-06 14:57:11,604::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0077428817749', 'lastCheck': 1333717022.32476, 'code': 0, 'valid': True}}
>Thread-1040::DEBUG::2012-04-06 14:57:11,604::task::1172::TaskManager.Task::(prepare) Task=`cdbc9d26-e418-452a-8c35-b0ca36a3f382`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0077428817749', 'lastCheck': 1333717022.32476, 'code': 0, 'valid': True}}
>Thread-1040::DEBUG::2012-04-06 14:57:11,604::task::588::TaskManager.Task::(_updateState) Task=`cdbc9d26-e418-452a-8c35-b0ca36a3f382`::moving from state preparing -> state finished
>Thread-1040::DEBUG::2012-04-06 14:57:11,605::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1040::DEBUG::2012-04-06 14:57:11,605::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1040::DEBUG::2012-04-06 14:57:11,605::task::978::TaskManager.Task::(_decref) Task=`cdbc9d26-e418-452a-8c35-b0ca36a3f382`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:12,834::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:12,907::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0382518 s, 26.8 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:14,915::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:14,987::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036907 s, 27.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:16,995::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:17,067::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036609 s, 28.0 MB/s\n'; <rc> = 0
>Thread-1044::DEBUG::2012-04-06 14:57:17,245::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1044::DEBUG::2012-04-06 14:57:17,246::task::588::TaskManager.Task::(_updateState) Task=`056e0912-71db-45be-8e0b-4b13466f6800`::moving from state init -> state preparing
>Thread-1044::INFO::2012-04-06 14:57:17,246::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1044::INFO::2012-04-06 14:57:17,246::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1044::DEBUG::2012-04-06 14:57:17,247::task::1172::TaskManager.Task::(prepare) Task=`056e0912-71db-45be-8e0b-4b13466f6800`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1044::DEBUG::2012-04-06 14:57:17,247::task::588::TaskManager.Task::(_updateState) Task=`056e0912-71db-45be-8e0b-4b13466f6800`::moving from state preparing -> state finished
>Thread-1044::DEBUG::2012-04-06 14:57:17,247::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1044::DEBUG::2012-04-06 14:57:17,247::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1044::DEBUG::2012-04-06 14:57:17,248::task::978::TaskManager.Task::(_decref) Task=`056e0912-71db-45be-8e0b-4b13466f6800`::ref 0 aborting False
>Thread-1045::DEBUG::2012-04-06 14:57:17,251::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1045::DEBUG::2012-04-06 14:57:17,252::task::588::TaskManager.Task::(_updateState) Task=`c10f2fc3-266f-4823-b2bb-6e4338aa9cd6`::moving from state init -> state preparing
>Thread-1045::INFO::2012-04-06 14:57:17,252::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1045::DEBUG::2012-04-06 14:57:17,253::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`b8231514-e00a-4080-ae77-6b50826fb25e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1045::DEBUG::2012-04-06 14:57:17,253::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1045::DEBUG::2012-04-06 14:57:17,253::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1045::DEBUG::2012-04-06 14:57:17,253::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`b8231514-e00a-4080-ae77-6b50826fb25e`::Granted request
>Thread-1045::DEBUG::2012-04-06 14:57:17,254::task::817::TaskManager.Task::(resourceAcquired) Task=`c10f2fc3-266f-4823-b2bb-6e4338aa9cd6`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1045::DEBUG::2012-04-06 14:57:17,254::task::978::TaskManager.Task::(_decref) Task=`c10f2fc3-266f-4823-b2bb-6e4338aa9cd6`::ref 1 aborting False
>Thread-1045::INFO::2012-04-06 14:57:17,255::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1045::DEBUG::2012-04-06 14:57:17,255::task::1172::TaskManager.Task::(prepare) Task=`c10f2fc3-266f-4823-b2bb-6e4338aa9cd6`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1045::DEBUG::2012-04-06 14:57:17,256::task::588::TaskManager.Task::(_updateState) Task=`c10f2fc3-266f-4823-b2bb-6e4338aa9cd6`::moving from state preparing -> state finished
>Thread-1045::DEBUG::2012-04-06 14:57:17,256::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1045::DEBUG::2012-04-06 14:57:17,256::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1045::DEBUG::2012-04-06 14:57:17,257::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1045::DEBUG::2012-04-06 14:57:17,257::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1045::DEBUG::2012-04-06 14:57:17,257::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1045::DEBUG::2012-04-06 14:57:17,257::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1045::DEBUG::2012-04-06 14:57:17,258::task::978::TaskManager.Task::(_decref) Task=`c10f2fc3-266f-4823-b2bb-6e4338aa9cd6`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:19,075::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:19,149::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0387393 s, 26.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:21,156::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:21,237::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0430957 s, 23.8 MB/s\n'; <rc> = 0
>Thread-1048::DEBUG::2012-04-06 14:57:21,705::task::588::TaskManager.Task::(_updateState) Task=`44d50618-53b0-4633-b7fc-0cc00484484b`::moving from state init -> state preparing
>Thread-1048::INFO::2012-04-06 14:57:21,706::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1048::INFO::2012-04-06 14:57:21,706::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00417804718018', 'lastCheck': 1333717032.3309381, 'code': 0, 'valid': True}}
>Thread-1048::DEBUG::2012-04-06 14:57:21,706::task::1172::TaskManager.Task::(prepare) Task=`44d50618-53b0-4633-b7fc-0cc00484484b`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00417804718018', 'lastCheck': 1333717032.3309381, 'code': 0, 'valid': True}}
>Thread-1048::DEBUG::2012-04-06 14:57:21,706::task::588::TaskManager.Task::(_updateState) Task=`44d50618-53b0-4633-b7fc-0cc00484484b`::moving from state preparing -> state finished
>Thread-1048::DEBUG::2012-04-06 14:57:21,707::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1048::DEBUG::2012-04-06 14:57:21,707::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1048::DEBUG::2012-04-06 14:57:21,707::task::978::TaskManager.Task::(_decref) Task=`44d50618-53b0-4633-b7fc-0cc00484484b`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:23,245::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:23,316::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0364354 s, 28.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2012-04-06 14:57:24,294::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 319.
>Thread-642::DEBUG::2012-04-06 14:57:24,528::task::588::TaskManager.Task::(_updateState) Task=`057ab279-7835-4683-84c4-39b39467362d`::moving from state init -> state preparing
>Thread-642::INFO::2012-04-06 14:57:24,529::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5a526aab-7488-4e8d-a05a-73a3c27db31c', spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', imgUUID='816042f6-b056-42fd-8154-e766aec76bfd', volUUID='8718328b-f49c-4f3d-b7d8-a51702424f1c', options=None)
>Thread-642::DEBUG::2012-04-06 14:57:24,529::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`c1488391-7cfc-4a90-9a60-377e10be5726`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2496' at 'getVolumeSize'
>Thread-642::DEBUG::2012-04-06 14:57:24,530::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' for lock type 'shared'
>Thread-642::DEBUG::2012-04-06 14:57:24,530::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free. Now locking as 'shared' (1 active user)
>Thread-642::DEBUG::2012-04-06 14:57:24,530::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`c1488391-7cfc-4a90-9a60-377e10be5726`::Granted request
>Thread-642::DEBUG::2012-04-06 14:57:24,531::task::817::TaskManager.Task::(resourceAcquired) Task=`057ab279-7835-4683-84c4-39b39467362d`::_resourcesAcquired: Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c (shared)
>Thread-642::DEBUG::2012-04-06 14:57:24,531::task::978::TaskManager.Task::(_decref) Task=`057ab279-7835-4683-84c4-39b39467362d`::ref 1 aborting False
>Thread-642::INFO::2012-04-06 14:57:24,531::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '10737418240', 'apparentsize': '10737418240'}
>Thread-642::DEBUG::2012-04-06 14:57:24,532::task::1172::TaskManager.Task::(prepare) Task=`057ab279-7835-4683-84c4-39b39467362d`::finished: {'truesize': '10737418240', 'apparentsize': '10737418240'}
>Thread-642::DEBUG::2012-04-06 14:57:24,532::task::588::TaskManager.Task::(_updateState) Task=`057ab279-7835-4683-84c4-39b39467362d`::moving from state preparing -> state finished
>Thread-642::DEBUG::2012-04-06 14:57:24,532::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c': < ResourceRef 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', isValid: 'True' obj: 'None'>}
>Thread-642::DEBUG::2012-04-06 14:57:24,532::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-642::DEBUG::2012-04-06 14:57:24,533::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c'
>Thread-642::DEBUG::2012-04-06 14:57:24,533::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' (0 active users)
>Thread-642::DEBUG::2012-04-06 14:57:24,533::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free, finding out if anyone is waiting for it.
>Thread-642::DEBUG::2012-04-06 14:57:24,534::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', Clearing records.
>Thread-642::DEBUG::2012-04-06 14:57:24,534::task::978::TaskManager.Task::(_decref) Task=`057ab279-7835-4683-84c4-39b39467362d`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:25,324::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:25,394::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.036202 s, 28.3 MB/s\n'; <rc> = 0
>Thread-1052::DEBUG::2012-04-06 14:57:27,278::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1052::DEBUG::2012-04-06 14:57:27,278::task::588::TaskManager.Task::(_updateState) Task=`5c225799-c947-4a55-9944-ca42fa5cc9ff`::moving from state init -> state preparing
>Thread-1052::INFO::2012-04-06 14:57:27,278::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1052::INFO::2012-04-06 14:57:27,279::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1052::DEBUG::2012-04-06 14:57:27,279::task::1172::TaskManager.Task::(prepare) Task=`5c225799-c947-4a55-9944-ca42fa5cc9ff`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1052::DEBUG::2012-04-06 14:57:27,279::task::588::TaskManager.Task::(_updateState) Task=`5c225799-c947-4a55-9944-ca42fa5cc9ff`::moving from state preparing -> state finished
>Thread-1052::DEBUG::2012-04-06 14:57:27,280::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1052::DEBUG::2012-04-06 14:57:27,280::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1052::DEBUG::2012-04-06 14:57:27,280::task::978::TaskManager.Task::(_decref) Task=`5c225799-c947-4a55-9944-ca42fa5cc9ff`::ref 0 aborting False
>Thread-1053::DEBUG::2012-04-06 14:57:27,284::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1053::DEBUG::2012-04-06 14:57:27,284::task::588::TaskManager.Task::(_updateState) Task=`0922feba-e631-45df-997f-5e93b30a41c0`::moving from state init -> state preparing
>Thread-1053::INFO::2012-04-06 14:57:27,284::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1053::DEBUG::2012-04-06 14:57:27,285::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`8971880a-70a8-42dc-a9ad-048716dc3b49`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1053::DEBUG::2012-04-06 14:57:27,285::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1053::DEBUG::2012-04-06 14:57:27,286::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1053::DEBUG::2012-04-06 14:57:27,286::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`8971880a-70a8-42dc-a9ad-048716dc3b49`::Granted request
>Thread-1053::DEBUG::2012-04-06 14:57:27,286::task::817::TaskManager.Task::(resourceAcquired) Task=`0922feba-e631-45df-997f-5e93b30a41c0`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1053::DEBUG::2012-04-06 14:57:27,286::task::978::TaskManager.Task::(_decref) Task=`0922feba-e631-45df-997f-5e93b30a41c0`::ref 1 aborting False
>Thread-1053::INFO::2012-04-06 14:57:27,287::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1053::DEBUG::2012-04-06 14:57:27,288::task::1172::TaskManager.Task::(prepare) Task=`0922feba-e631-45df-997f-5e93b30a41c0`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1053::DEBUG::2012-04-06 14:57:27,288::task::588::TaskManager.Task::(_updateState) Task=`0922feba-e631-45df-997f-5e93b30a41c0`::moving from state preparing -> state finished
>Thread-1053::DEBUG::2012-04-06 14:57:27,288::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1053::DEBUG::2012-04-06 14:57:27,288::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1053::DEBUG::2012-04-06 14:57:27,289::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1053::DEBUG::2012-04-06 14:57:27,289::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1053::DEBUG::2012-04-06 14:57:27,289::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1053::DEBUG::2012-04-06 14:57:27,290::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1053::DEBUG::2012-04-06 14:57:27,290::task::978::TaskManager.Task::(_decref) Task=`0922feba-e631-45df-997f-5e93b30a41c0`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:27,400::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:27,480::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0442932 s, 23.1 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:29,489::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:29,567::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0398018 s, 25.7 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:31,575::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:31,655::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0459042 s, 22.3 MB/s\n'; <rc> = 0
>Thread-1056::DEBUG::2012-04-06 14:57:31,801::task::588::TaskManager.Task::(_updateState) Task=`d5e25d63-dd6a-4841-8646-16070734ceff`::moving from state init -> state preparing
>Thread-1056::INFO::2012-04-06 14:57:31,802::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1056::INFO::2012-04-06 14:57:31,802::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0063591003418', 'lastCheck': 1333717042.338748, 'code': 0, 'valid': True}}
>Thread-1056::DEBUG::2012-04-06 14:57:31,802::task::1172::TaskManager.Task::(prepare) Task=`d5e25d63-dd6a-4841-8646-16070734ceff`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.0063591003418', 'lastCheck': 1333717042.338748, 'code': 0, 'valid': True}}
>Thread-1056::DEBUG::2012-04-06 14:57:31,803::task::588::TaskManager.Task::(_updateState) Task=`d5e25d63-dd6a-4841-8646-16070734ceff`::moving from state preparing -> state finished
>Thread-1056::DEBUG::2012-04-06 14:57:31,803::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1056::DEBUG::2012-04-06 14:57:31,803::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1056::DEBUG::2012-04-06 14:57:31,803::task::978::TaskManager.Task::(_decref) Task=`d5e25d63-dd6a-4841-8646-16070734ceff`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:33,663::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:33,733::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0359109 s, 28.5 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:35,741::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:35,810::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0348824 s, 29.4 MB/s\n'; <rc> = 0
>Thread-1060::DEBUG::2012-04-06 14:57:37,310::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1060::DEBUG::2012-04-06 14:57:37,311::task::588::TaskManager.Task::(_updateState) Task=`70493c90-c359-405d-8ccc-271da71db4f5`::moving from state init -> state preparing
>Thread-1060::INFO::2012-04-06 14:57:37,311::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1060::INFO::2012-04-06 14:57:37,312::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1060::DEBUG::2012-04-06 14:57:37,312::task::1172::TaskManager.Task::(prepare) Task=`70493c90-c359-405d-8ccc-271da71db4f5`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1060::DEBUG::2012-04-06 14:57:37,312::task::588::TaskManager.Task::(_updateState) Task=`70493c90-c359-405d-8ccc-271da71db4f5`::moving from state preparing -> state finished
>Thread-1060::DEBUG::2012-04-06 14:57:37,313::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1060::DEBUG::2012-04-06 14:57:37,313::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1060::DEBUG::2012-04-06 14:57:37,313::task::978::TaskManager.Task::(_decref) Task=`70493c90-c359-405d-8ccc-271da71db4f5`::ref 0 aborting False
>Thread-1061::DEBUG::2012-04-06 14:57:37,320::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1061::DEBUG::2012-04-06 14:57:37,320::task::588::TaskManager.Task::(_updateState) Task=`610a8185-9960-46a6-97ad-4dec7a9be668`::moving from state init -> state preparing
>Thread-1061::INFO::2012-04-06 14:57:37,320::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1061::DEBUG::2012-04-06 14:57:37,321::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`38e91af6-9eed-474b-8092-aa27c73f665f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1061::DEBUG::2012-04-06 14:57:37,321::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1061::DEBUG::2012-04-06 14:57:37,322::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1061::DEBUG::2012-04-06 14:57:37,322::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`38e91af6-9eed-474b-8092-aa27c73f665f`::Granted request
>Thread-1061::DEBUG::2012-04-06 14:57:37,322::task::817::TaskManager.Task::(resourceAcquired) Task=`610a8185-9960-46a6-97ad-4dec7a9be668`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1061::DEBUG::2012-04-06 14:57:37,323::task::978::TaskManager.Task::(_decref) Task=`610a8185-9960-46a6-97ad-4dec7a9be668`::ref 1 aborting False
>Thread-1061::INFO::2012-04-06 14:57:37,323::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1061::DEBUG::2012-04-06 14:57:37,324::task::1172::TaskManager.Task::(prepare) Task=`610a8185-9960-46a6-97ad-4dec7a9be668`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1061::DEBUG::2012-04-06 14:57:37,324::task::588::TaskManager.Task::(_updateState) Task=`610a8185-9960-46a6-97ad-4dec7a9be668`::moving from state preparing -> state finished
>Thread-1061::DEBUG::2012-04-06 14:57:37,324::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1061::DEBUG::2012-04-06 14:57:37,324::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1061::DEBUG::2012-04-06 14:57:37,325::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1061::DEBUG::2012-04-06 14:57:37,325::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1061::DEBUG::2012-04-06 14:57:37,325::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1061::DEBUG::2012-04-06 14:57:37,326::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1061::DEBUG::2012-04-06 14:57:37,326::task::978::TaskManager.Task::(_decref) Task=`610a8185-9960-46a6-97ad-4dec7a9be668`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:37,817::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:37,890::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0363276 s, 28.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:39,897::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:39,967::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0361737 s, 28.3 MB/s\n'; <rc> = 0
>Thread-1064::DEBUG::2012-04-06 14:57:41,895::task::588::TaskManager.Task::(_updateState) Task=`765e3798-bf4d-49ea-9a2e-111f414ed9d1`::moving from state init -> state preparing
>Thread-1064::INFO::2012-04-06 14:57:41,895::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1064::INFO::2012-04-06 14:57:41,896::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00556397438049', 'lastCheck': 1333717052.3457849, 'code': 0, 'valid': True}}
>Thread-1064::DEBUG::2012-04-06 14:57:41,896::task::1172::TaskManager.Task::(prepare) Task=`765e3798-bf4d-49ea-9a2e-111f414ed9d1`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00556397438049', 'lastCheck': 1333717052.3457849, 'code': 0, 'valid': True}}
>Thread-1064::DEBUG::2012-04-06 14:57:41,896::task::588::TaskManager.Task::(_updateState) Task=`765e3798-bf4d-49ea-9a2e-111f414ed9d1`::moving from state preparing -> state finished
>Thread-1064::DEBUG::2012-04-06 14:57:41,896::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1064::DEBUG::2012-04-06 14:57:41,897::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1064::DEBUG::2012-04-06 14:57:41,897::task::978::TaskManager.Task::(_decref) Task=`765e3798-bf4d-49ea-9a2e-111f414ed9d1`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:41,976::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:42,046::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0360901 s, 28.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:44,055::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:44,125::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0351185 s, 29.2 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:46,133::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:46,210::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0359969 s, 28.4 MB/s\n'; <rc> = 0
>Thread-1068::DEBUG::2012-04-06 14:57:47,358::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1068::DEBUG::2012-04-06 14:57:47,358::task::588::TaskManager.Task::(_updateState) Task=`0f053bd7-5858-402b-a637-bf877677e59f`::moving from state init -> state preparing
>Thread-1068::INFO::2012-04-06 14:57:47,359::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1068::INFO::2012-04-06 14:57:47,359::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1068::DEBUG::2012-04-06 14:57:47,359::task::1172::TaskManager.Task::(prepare) Task=`0f053bd7-5858-402b-a637-bf877677e59f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1068::DEBUG::2012-04-06 14:57:47,359::task::588::TaskManager.Task::(_updateState) Task=`0f053bd7-5858-402b-a637-bf877677e59f`::moving from state preparing -> state finished
>Thread-1068::DEBUG::2012-04-06 14:57:47,360::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1068::DEBUG::2012-04-06 14:57:47,360::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1068::DEBUG::2012-04-06 14:57:47,360::task::978::TaskManager.Task::(_decref) Task=`0f053bd7-5858-402b-a637-bf877677e59f`::ref 0 aborting False
>Thread-1069::DEBUG::2012-04-06 14:57:47,364::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1069::DEBUG::2012-04-06 14:57:47,364::task::588::TaskManager.Task::(_updateState) Task=`50343564-d1a1-4750-a69f-3ead9e104663`::moving from state init -> state preparing
>Thread-1069::INFO::2012-04-06 14:57:47,365::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1069::DEBUG::2012-04-06 14:57:47,365::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`221d0b90-372e-4154-b419-61b69918435a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1069::DEBUG::2012-04-06 14:57:47,366::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1069::DEBUG::2012-04-06 14:57:47,366::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1069::DEBUG::2012-04-06 14:57:47,366::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`221d0b90-372e-4154-b419-61b69918435a`::Granted request
>Thread-1069::DEBUG::2012-04-06 14:57:47,367::task::817::TaskManager.Task::(resourceAcquired) Task=`50343564-d1a1-4750-a69f-3ead9e104663`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1069::DEBUG::2012-04-06 14:57:47,367::task::978::TaskManager.Task::(_decref) Task=`50343564-d1a1-4750-a69f-3ead9e104663`::ref 1 aborting False
>Thread-1069::INFO::2012-04-06 14:57:47,368::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1069::DEBUG::2012-04-06 14:57:47,368::task::1172::TaskManager.Task::(prepare) Task=`50343564-d1a1-4750-a69f-3ead9e104663`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1069::DEBUG::2012-04-06 14:57:47,368::task::588::TaskManager.Task::(_updateState) Task=`50343564-d1a1-4750-a69f-3ead9e104663`::moving from state preparing -> state finished
>Thread-1069::DEBUG::2012-04-06 14:57:47,369::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1069::DEBUG::2012-04-06 14:57:47,369::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1069::DEBUG::2012-04-06 14:57:47,369::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1069::DEBUG::2012-04-06 14:57:47,369::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1069::DEBUG::2012-04-06 14:57:47,370::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1069::DEBUG::2012-04-06 14:57:47,370::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1069::DEBUG::2012-04-06 14:57:47,370::task::978::TaskManager.Task::(_decref) Task=`50343564-d1a1-4750-a69f-3ead9e104663`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:48,222::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:48,289::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0336533 s, 30.4 MB/s\n'; <rc> = 0
>Dummy-321::DEBUG::2012-04-06 14:57:50,297::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:50,368::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.035709 s, 28.7 MB/s\n'; <rc> = 0
>Thread-1072::DEBUG::2012-04-06 14:57:51,986::task::588::TaskManager.Task::(_updateState) Task=`0e6c36a4-bf40-4e2b-a3d1-51d13c1d5327`::moving from state init -> state preparing
>Thread-1072::INFO::2012-04-06 14:57:51,987::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1072::INFO::2012-04-06 14:57:51,987::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00068187713623', 'lastCheck': 1333717062.3480749, 'code': 0, 'valid': True}}
>Thread-1072::DEBUG::2012-04-06 14:57:51,987::task::1172::TaskManager.Task::(prepare) Task=`0e6c36a4-bf40-4e2b-a3d1-51d13c1d5327`::finished: {'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'delay': '0.00068187713623', 'lastCheck': 1333717062.3480749, 'code': 0, 'valid': True}}
>Thread-1072::DEBUG::2012-04-06 14:57:51,988::task::588::TaskManager.Task::(_updateState) Task=`0e6c36a4-bf40-4e2b-a3d1-51d13c1d5327`::moving from state preparing -> state finished
>Thread-1072::DEBUG::2012-04-06 14:57:51,988::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1072::DEBUG::2012-04-06 14:57:51,988::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1072::DEBUG::2012-04-06 14:57:51,989::task::978::TaskManager.Task::(_decref) Task=`0e6c36a4-bf40-4e2b-a3d1-51d13c1d5327`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:52,377::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:52,444::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0340447 s, 30.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2012-04-06 14:57:54,305::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 319.
>Dummy-321::DEBUG::2012-04-06 14:57:54,452::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:54,523::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0363933 s, 28.1 MB/s\n'; <rc> = 0
>Thread-393::DEBUG::2012-04-06 14:57:56,102::task::588::TaskManager.Task::(_updateState) Task=`60043004-326b-42bc-9648-a39e6242cbcd`::moving from state init -> state preparing
>Thread-393::INFO::2012-04-06 14:57:56,102::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5a526aab-7488-4e8d-a05a-73a3c27db31c', spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', imgUUID='0cdee4ac-5c14-4c63-8d5e-c16b540b3ce7', volUUID='a8fd1587-9932-4cb8-ac78-b2f709a749af', options=None)
>Thread-393::DEBUG::2012-04-06 14:57:56,103::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`c10a2836-6d0a-4bf8-861c-01edaae83bac`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2496' at 'getVolumeSize'
>Thread-393::DEBUG::2012-04-06 14:57:56,103::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' for lock type 'shared'
>Thread-393::DEBUG::2012-04-06 14:57:56,103::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free. Now locking as 'shared' (1 active user)
>Thread-393::DEBUG::2012-04-06 14:57:56,103::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c`ReqID=`c10a2836-6d0a-4bf8-861c-01edaae83bac`::Granted request
>Thread-393::DEBUG::2012-04-06 14:57:56,104::task::817::TaskManager.Task::(resourceAcquired) Task=`60043004-326b-42bc-9648-a39e6242cbcd`::_resourcesAcquired: Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c (shared)
>Thread-393::DEBUG::2012-04-06 14:57:56,104::task::978::TaskManager.Task::(_decref) Task=`60043004-326b-42bc-9648-a39e6242cbcd`::ref 1 aborting False
>Thread-393::INFO::2012-04-06 14:57:56,105::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '4294967296', 'apparentsize': '4294967296'}
>Thread-393::DEBUG::2012-04-06 14:57:56,105::task::1172::TaskManager.Task::(prepare) Task=`60043004-326b-42bc-9648-a39e6242cbcd`::finished: {'truesize': '4294967296', 'apparentsize': '4294967296'}
>Thread-393::DEBUG::2012-04-06 14:57:56,105::task::588::TaskManager.Task::(_updateState) Task=`60043004-326b-42bc-9648-a39e6242cbcd`::moving from state preparing -> state finished
>Thread-393::DEBUG::2012-04-06 14:57:56,105::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c': < ResourceRef 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', isValid: 'True' obj: 'None'>}
>Thread-393::DEBUG::2012-04-06 14:57:56,106::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-393::DEBUG::2012-04-06 14:57:56,106::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c'
>Thread-393::DEBUG::2012-04-06 14:57:56,106::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' (0 active users)
>Thread-393::DEBUG::2012-04-06 14:57:56,107::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c' is free, finding out if anyone is waiting for it.
>Thread-393::DEBUG::2012-04-06 14:57:56,107::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5a526aab-7488-4e8d-a05a-73a3c27db31c', Clearing records.
>Thread-393::DEBUG::2012-04-06 14:57:56,107::task::978::TaskManager.Task::(_decref) Task=`60043004-326b-42bc-9648-a39e6242cbcd`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:57:56,530::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:56,598::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.033965 s, 30.1 MB/s\n'; <rc> = 0
>Thread-1076::DEBUG::2012-04-06 14:57:57,390::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1076::DEBUG::2012-04-06 14:57:57,390::task::588::TaskManager.Task::(_updateState) Task=`540873c7-ea88-452d-8a49-c1e4f7e5f1a1`::moving from state init -> state preparing
>Thread-1076::INFO::2012-04-06 14:57:57,391::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1076::INFO::2012-04-06 14:57:57,391::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1076::DEBUG::2012-04-06 14:57:57,391::task::1172::TaskManager.Task::(prepare) Task=`540873c7-ea88-452d-8a49-c1e4f7e5f1a1`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 5}}
>Thread-1076::DEBUG::2012-04-06 14:57:57,392::task::588::TaskManager.Task::(_updateState) Task=`540873c7-ea88-452d-8a49-c1e4f7e5f1a1`::moving from state preparing -> state finished
>Thread-1076::DEBUG::2012-04-06 14:57:57,392::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1076::DEBUG::2012-04-06 14:57:57,392::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1076::DEBUG::2012-04-06 14:57:57,393::task::978::TaskManager.Task::(_decref) Task=`540873c7-ea88-452d-8a49-c1e4f7e5f1a1`::ref 0 aborting False
>Thread-1077::DEBUG::2012-04-06 14:57:57,397::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1077::DEBUG::2012-04-06 14:57:57,397::task::588::TaskManager.Task::(_updateState) Task=`fb174ec1-7880-4c6a-bc76-45b34449d639`::moving from state init -> state preparing
>Thread-1077::INFO::2012-04-06 14:57:57,397::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', options=None)
>Thread-1077::DEBUG::2012-04-06 14:57:57,398::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`9d4fa284-4edc-4ac5-9ae8-390e041fa3b2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2038' at 'getStoragePoolInfo'
>Thread-1077::DEBUG::2012-04-06 14:57:57,398::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' for lock type 'shared'
>Thread-1077::DEBUG::2012-04-06 14:57:57,398::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free. Now locking as 'shared' (1 active user)
>Thread-1077::DEBUG::2012-04-06 14:57:57,399::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf`ReqID=`9d4fa284-4edc-4ac5-9ae8-390e041fa3b2`::Granted request
>Thread-1077::DEBUG::2012-04-06 14:57:57,399::task::817::TaskManager.Task::(resourceAcquired) Task=`fb174ec1-7880-4c6a-bc76-45b34449d639`::_resourcesAcquired: Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf (shared)
>Thread-1077::DEBUG::2012-04-06 14:57:57,399::task::978::TaskManager.Task::(_decref) Task=`fb174ec1-7880-4c6a-bc76-45b34449d639`::ref 1 aborting False
>Thread-1077::INFO::2012-04-06 14:57:57,400::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1077::DEBUG::2012-04-06 14:57:57,401::task::1172::TaskManager.Task::(prepare) Task=`fb174ec1-7880-4c6a-bc76-45b34449d639`::finished: {'info': {'spm_id': 1, 'master_uuid': '5a526aab-7488-4e8d-a05a-73a3c27db31c', 'name': 'iSCSI', 'version': '2', 'domains': u'5a526aab-7488-4e8d-a05a-73a3c27db31c:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 5}, 'dominfo': {u'5a526aab-7488-4e8d-a05a-73a3c27db31c': {'status': u'Active', 'diskfree': '217701154816', 'alerts': [], 'disktotal': '268032802816'}}}
>Thread-1077::DEBUG::2012-04-06 14:57:57,401::task::588::TaskManager.Task::(_updateState) Task=`fb174ec1-7880-4c6a-bc76-45b34449d639`::moving from state preparing -> state finished
>Thread-1077::DEBUG::2012-04-06 14:57:57,401::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf': < ResourceRef 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', isValid: 'True' obj: 'None'>}
>Thread-1077::DEBUG::2012-04-06 14:57:57,401::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1077::DEBUG::2012-04-06 14:57:57,402::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf'
>Thread-1077::DEBUG::2012-04-06 14:57:57,402::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' (0 active users)
>Thread-1077::DEBUG::2012-04-06 14:57:57,402::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf' is free, finding out if anyone is waiting for it.
>Thread-1077::DEBUG::2012-04-06 14:57:57,403::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf', Clearing records.
>Thread-1077::DEBUG::2012-04-06 14:57:57,403::task::978::TaskManager.Task::(_decref) Task=`fb174ec1-7880-4c6a-bc76-45b34449d639`::ref 0 aborting False
>Thread-1079::DEBUG::2012-04-06 14:57:58,362::BindingXMLRPC::167::vds::(wrapper) [10.34.63.27]
>Thread-1079::DEBUG::2012-04-06 14:57:58,362::task::588::TaskManager.Task::(_updateState) Task=`74088ef4-8280-46dc-bfcf-0dacd9d0cad1`::moving from state init -> state preparing
>Thread-1079::INFO::2012-04-06 14:57:58,363::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'example.com:/export/1234', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
>Thread-1079::DEBUG::2012-04-06 14:57:58,363::mount::124::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/example.com:_export_1234' (cwd None)
>Thread-1079::ERROR::2012-04-06 14:57:58,380::hsm::1958::Storage.HSM::(disconnectStorageServer) Could not disconnect from storageServer
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/hsm.py", line 1955, in disconnectStorageServer
>    conObj.disconnect()
>  File "/usr/share/vdsm/storage/storageServer.py", line 255, in disconnect
>    return self._mountCon.disconnect()
>  File "/usr/share/vdsm/storage/storageServer.py", line 178, in disconnect
>    self._mount.umount(True, True)
>  File "/usr/share/vdsm/storage/mount.py", line 147, in umount
>    return self._runcmd(cmd, timeout)
>  File "/usr/share/vdsm/storage/mount.py", line 135, in _runcmd
>    raise MountError(rc, ";".join((out, err)))
>MountError: (1, ';umount: /rhev/data-center/mnt/example.com:_export_1234: not mounted\n')
>Thread-1079::DEBUG::2012-04-06 14:57:58,380::misc::1022::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-1079::DEBUG::2012-04-06 14:57:58,381::misc::1024::SamplingMethod::(__call__) Got in to sampling method
>Thread-1079::DEBUG::2012-04-06 14:57:58,381::misc::1022::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-1079::DEBUG::2012-04-06 14:57:58,381::misc::1024::SamplingMethod::(__call__) Got in to sampling method
>Thread-1079::DEBUG::2012-04-06 14:57:58,382::iscsiadm::48::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1079::DEBUG::2012-04-06 14:57:58,407::iscsiadm::48::Storage.Misc.excCmd::(_runCmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-1079::DEBUG::2012-04-06 14:57:58,407::misc::1032::SamplingMethod::(__call__) Returning last result
>Dummy-321::DEBUG::2012-04-06 14:57:58,605::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:57:58,675::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0345576 s, 29.6 MB/s\n'; <rc> = 0
>Thread-1079::DEBUG::2012-04-06 14:58:00,305::multipath::71::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-1079::DEBUG::2012-04-06 14:58:00,395::multipath::71::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-1079::DEBUG::2012-04-06 14:58:00,396::lvm::474::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1079::DEBUG::2012-04-06 14:58:00,400::lvm::476::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1079::DEBUG::2012-04-06 14:58:00,400::lvm::486::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1079::DEBUG::2012-04-06 14:58:00,400::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1079::DEBUG::2012-04-06 14:58:00,401::lvm::507::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1079::DEBUG::2012-04-06 14:58:00,401::lvm::509::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1079::DEBUG::2012-04-06 14:58:00,401::misc::1032::SamplingMethod::(__call__) Returning last result
>Thread-1079::INFO::2012-04-06 14:58:00,402::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 477, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-1079::DEBUG::2012-04-06 14:58:00,402::task::1172::TaskManager.Task::(prepare) Task=`74088ef4-8280-46dc-bfcf-0dacd9d0cad1`::finished: {'statuslist': [{'status': 477, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-1079::DEBUG::2012-04-06 14:58:00,402::task::588::TaskManager.Task::(_updateState) Task=`74088ef4-8280-46dc-bfcf-0dacd9d0cad1`::moving from state preparing -> state finished
>Thread-1079::DEBUG::2012-04-06 14:58:00,403::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1079::DEBUG::2012-04-06 14:58:00,403::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1079::DEBUG::2012-04-06 14:58:00,403::task::978::TaskManager.Task::(_decref) Task=`74088ef4-8280-46dc-bfcf-0dacd9d0cad1`::ref 0 aborting False
>Dummy-321::DEBUG::2012-04-06 14:58:00,683::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) 'dd if=/rhev/data-center/387d2723-ffe7-4a4b-b28f-4f34a7c1ceaf/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-321::DEBUG::2012-04-06 14:58:00,752::storage_mailbox::640::Storage.Misc.excCmd::(_checkForMail) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0358246 s, 28.6 MB/s\n'; <rc> = 0

Actions: View

Attachments on bug 810499: 575738