Attachment 911366 Details for Bug 1112171 – VDSM log file

VDSM log file

vdsm.log (text/x-log), 185.99 KB, created by Idan Shaby on 2014-06-23 09:30:14 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Idan Shaby

Created: 2014-06-23 09:30:14 UTC

Size: 185.99 KB

patch

obsolete

>Thread-13::DEBUG::2014-06-23 12:15:59,949::task::595::TaskManager.Task::(_updateState) Task=`b1c0391e-4787-449d-a267-e914b94eac1c`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:15:59,951::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:15:59,951::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000200247', 'lastCheck': '5.0', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000208594', 'lastCheck': '5.0', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00027819', 'lastCheck': '5.2', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000274998', 'lastCheck': '5.1', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:15:59,951::task::1185::TaskManager.Task::(prepare) Task=`b1c0391e-4787-449d-a267-e914b94eac1c`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000200247', 'lastCheck': '5.0', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000208594', 'lastCheck': '5.0', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00027819', 'lastCheck': '5.2', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000274998', 'lastCheck': '5.1', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:15:59,951::task::595::TaskManager.Task::(_updateState) Task=`b1c0391e-4787-449d-a267-e914b94eac1c`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:15:59,951::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:15:59,951::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:15:59,951::task::990::TaskManager.Task::(_decref) Task=`b1c0391e-4787-449d-a267-e914b94eac1c`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:04,283::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:04,283::task::595::TaskManager.Task::(_updateState) Task=`626deb43-4dfc-4538-aa29-747a31991d70`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:04,283::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:16:04,284::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:04,284::task::1185::TaskManager.Task::(prepare) Task=`626deb43-4dfc-4538-aa29-747a31991d70`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:04,284::task::595::TaskManager.Task::(_updateState) Task=`626deb43-4dfc-4538-aa29-747a31991d70`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:04,284::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:04,284::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:04,284::task::990::TaskManager.Task::(_decref) Task=`626deb43-4dfc-4538-aa29-747a31991d70`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:04,292::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:16:04,292::task::595::TaskManager.Task::(_updateState) Task=`5c704905-8d74-404c-b1cd-aed3572bf022`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:04,292::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:04,292::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`30cd1fc4-3a7d-4828-b328-50c534cfea21`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:16:04,292::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:16:04,292::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:04,293::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`30cd1fc4-3a7d-4828-b328-50c534cfea21`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:04,293::task::827::TaskManager.Task::(resourceAcquired) Task=`5c704905-8d74-404c-b1cd-aed3572bf022`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:16:04,293::task::990::TaskManager.Task::(_decref) Task=`5c704905-8d74-404c-b1cd-aed3572bf022`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:04,294::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17234882560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17234882560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17234886656', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17234886656', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:04,294::task::1185::TaskManager.Task::(prepare) Task=`5c704905-8d74-404c-b1cd-aed3572bf022`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17234882560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17234882560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17234886656', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17234886656', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:04,294::task::595::TaskManager.Task::(_updateState) Task=`5c704905-8d74-404c-b1cd-aed3572bf022`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:04,294::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:04,294::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:04,294::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:04,294::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:04,294::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:04,294::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:04,294::task::990::TaskManager.Task::(_decref) Task=`5c704905-8d74-404c-b1cd-aed3572bf022`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:16:04,743::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:16:04,747::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n587 bytes (587 B) copied, 0.000271662 s, 2.2 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:16:04,869::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:16:04,873::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000238837 s, 1.4 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-23 12:16:04,981::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:16:04,981::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:05,018::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.0298859 s, 11.2 kB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:05,018::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.0266172 s, 12.9 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:14,368::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:14,368::task::595::TaskManager.Task::(_updateState) Task=`7b90a48a-73ca-43da-a9aa-11ad0f8ce8dd`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:14,368::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:16:14,368::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:14,368::task::1185::TaskManager.Task::(prepare) Task=`7b90a48a-73ca-43da-a9aa-11ad0f8ce8dd`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:14,368::task::595::TaskManager.Task::(_updateState) Task=`7b90a48a-73ca-43da-a9aa-11ad0f8ce8dd`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:14,368::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:14,369::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:14,369::task::990::TaskManager.Task::(_decref) Task=`7b90a48a-73ca-43da-a9aa-11ad0f8ce8dd`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:14,376::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:16:14,377::task::595::TaskManager.Task::(_updateState) Task=`c3fc7fc0-7f36-47c0-8a5a-e72950b60001`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:14,377::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:14,378::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`16912454-15c8-460e-ad5d-7b1fba536326`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:16:14,378::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:16:14,378::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:14,378::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`16912454-15c8-460e-ad5d-7b1fba536326`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:14,378::task::827::TaskManager.Task::(resourceAcquired) Task=`c3fc7fc0-7f36-47c0-8a5a-e72950b60001`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:16:14,378::task::990::TaskManager.Task::(_decref) Task=`c3fc7fc0-7f36-47c0-8a5a-e72950b60001`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:14,379::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:14,379::task::1185::TaskManager.Task::(prepare) Task=`c3fc7fc0-7f36-47c0-8a5a-e72950b60001`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:14,379::task::595::TaskManager.Task::(_updateState) Task=`c3fc7fc0-7f36-47c0-8a5a-e72950b60001`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:14,379::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:14,379::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:14,379::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:14,379::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:14,379::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:14,379::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:14,379::task::990::TaskManager.Task::(_decref) Task=`c3fc7fc0-7f36-47c0-8a5a-e72950b60001`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:16:14,751::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:16:14,756::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n587 bytes (587 B) copied, 0.000277654 s, 2.1 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:16:14,876::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:16:14,881::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000238983 s, 1.4 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-23 12:16:15,030::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:16:15,034::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:15,043::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000187427 s, 1.8 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:15,044::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000198064 s, 1.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:15,140::task::595::TaskManager.Task::(_updateState) Task=`11a0e774-c562-49eb-ae81-654a2cb2f879`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:15,140::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:16:15,141::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000198064', 'lastCheck': '0.1', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000187427', 'lastCheck': '0.1', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000277654', 'lastCheck': '0.4', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000238983', 'lastCheck': '0.3', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:16:15,141::task::1185::TaskManager.Task::(prepare) Task=`11a0e774-c562-49eb-ae81-654a2cb2f879`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000198064', 'lastCheck': '0.1', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000187427', 'lastCheck': '0.1', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000277654', 'lastCheck': '0.4', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000238983', 'lastCheck': '0.3', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:16:15,141::task::595::TaskManager.Task::(_updateState) Task=`11a0e774-c562-49eb-ae81-654a2cb2f879`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:15,141::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:15,141::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:15,141::task::990::TaskManager.Task::(_decref) Task=`11a0e774-c562-49eb-ae81-654a2cb2f879`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:24,450::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:24,451::task::595::TaskManager.Task::(_updateState) Task=`9a32c2f5-26dd-49ad-a928-660502c5df93`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:24,451::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:16:24,451::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:24,451::task::1185::TaskManager.Task::(prepare) Task=`9a32c2f5-26dd-49ad-a928-660502c5df93`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:24,451::task::595::TaskManager.Task::(_updateState) Task=`9a32c2f5-26dd-49ad-a928-660502c5df93`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:24,451::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:24,451::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:24,451::task::990::TaskManager.Task::(_decref) Task=`9a32c2f5-26dd-49ad-a928-660502c5df93`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:24,463::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:16:24,463::task::595::TaskManager.Task::(_updateState) Task=`0ab91ac5-4adb-4e7e-a224-ad6f15b9a180`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:24,464::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:24,464::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`93d36416-ba3c-4905-be18-30696351223e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:16:24,464::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:16:24,464::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:24,464::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`93d36416-ba3c-4905-be18-30696351223e`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:24,464::task::827::TaskManager.Task::(resourceAcquired) Task=`0ab91ac5-4adb-4e7e-a224-ad6f15b9a180`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:16:24,464::task::990::TaskManager.Task::(_decref) Task=`0ab91ac5-4adb-4e7e-a224-ad6f15b9a180`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:24,465::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:24,465::task::1185::TaskManager.Task::(prepare) Task=`0ab91ac5-4adb-4e7e-a224-ad6f15b9a180`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244839936', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:24,465::task::595::TaskManager.Task::(_updateState) Task=`0ab91ac5-4adb-4e7e-a224-ad6f15b9a180`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:24,465::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:24,465::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:24,465::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:24,465::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:24,465::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:24,465::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:24,466::task::990::TaskManager.Task::(_decref) Task=`0ab91ac5-4adb-4e7e-a224-ad6f15b9a180`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:16:24,759::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:16:24,763::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n587 bytes (587 B) copied, 0.000301143 s, 1.9 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:16:24,884::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:16:24,888::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000240629 s, 1.4 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-23 12:16:25,058::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:16:25,068::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:25,075::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000224621 s, 1.5 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:25,079::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000185855 s, 1.8 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:30,290::task::595::TaskManager.Task::(_updateState) Task=`0c518226-4cae-4907-90e0-69fc3a07c1d2`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:30,290::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:16:30,290::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000185855', 'lastCheck': '5.2', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000224621', 'lastCheck': '5.2', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000301143', 'lastCheck': '5.5', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000240629', 'lastCheck': '5.4', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:16:30,290::task::1185::TaskManager.Task::(prepare) Task=`0c518226-4cae-4907-90e0-69fc3a07c1d2`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000185855', 'lastCheck': '5.2', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000224621', 'lastCheck': '5.2', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000301143', 'lastCheck': '5.5', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000240629', 'lastCheck': '5.4', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:16:30,291::task::595::TaskManager.Task::(_updateState) Task=`0c518226-4cae-4907-90e0-69fc3a07c1d2`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:30,291::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:30,291::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:30,291::task::990::TaskManager.Task::(_decref) Task=`0c518226-4cae-4907-90e0-69fc3a07c1d2`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:34,542::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:34,543::task::595::TaskManager.Task::(_updateState) Task=`fb1fb2e3-72de-41a6-b2e1-e2a5edcafc9b`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:34,543::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:16:34,543::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:34,543::task::1185::TaskManager.Task::(prepare) Task=`fb1fb2e3-72de-41a6-b2e1-e2a5edcafc9b`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:34,543::task::595::TaskManager.Task::(_updateState) Task=`fb1fb2e3-72de-41a6-b2e1-e2a5edcafc9b`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:34,543::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:34,543::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:34,544::task::990::TaskManager.Task::(_decref) Task=`fb1fb2e3-72de-41a6-b2e1-e2a5edcafc9b`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:34,551::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:16:34,551::task::595::TaskManager.Task::(_updateState) Task=`cfcd5b58-3731-48ac-8e14-51d50d328c3d`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:34,551::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:34,551::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`04ca6d53-9376-40fa-bf3c-57f82afea818`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:16:34,551::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:16:34,551::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:34,551::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`04ca6d53-9376-40fa-bf3c-57f82afea818`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:34,552::task::827::TaskManager.Task::(resourceAcquired) Task=`cfcd5b58-3731-48ac-8e14-51d50d328c3d`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:16:34,552::task::990::TaskManager.Task::(_decref) Task=`cfcd5b58-3731-48ac-8e14-51d50d328c3d`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:34,552::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:34,552::task::1185::TaskManager.Task::(prepare) Task=`cfcd5b58-3731-48ac-8e14-51d50d328c3d`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244827648', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:34,552::task::595::TaskManager.Task::(_updateState) Task=`cfcd5b58-3731-48ac-8e14-51d50d328c3d`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:34,552::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:34,552::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:34,553::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:34,553::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:34,553::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:34,553::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:34,553::task::990::TaskManager.Task::(_decref) Task=`cfcd5b58-3731-48ac-8e14-51d50d328c3d`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:16:34,766::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:16:34,771::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n587 bytes (587 B) copied, 0.000299783 s, 2.0 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:16:34,891::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:16:34,895::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000236457 s, 1.4 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-23 12:16:35,095::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:16:35,101::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:35,108::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000214957 s, 1.6 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:35,110::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000201305 s, 1.7 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:44,602::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:44,602::task::595::TaskManager.Task::(_updateState) Task=`2ce79e56-6b13-48e2-b913-9c3d6e4dbcbd`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:44,602::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:16:44,603::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:44,603::task::1185::TaskManager.Task::(prepare) Task=`2ce79e56-6b13-48e2-b913-9c3d6e4dbcbd`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:44,603::task::595::TaskManager.Task::(_updateState) Task=`2ce79e56-6b13-48e2-b913-9c3d6e4dbcbd`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:44,603::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:44,603::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:44,603::task::990::TaskManager.Task::(_decref) Task=`2ce79e56-6b13-48e2-b913-9c3d6e4dbcbd`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:44,612::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:16:44,612::task::595::TaskManager.Task::(_updateState) Task=`c9151243-c029-4616-bbae-b4563ae9539b`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:44,612::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:44,612::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`1b3d8670-5bb5-4a03-8407-08c7c79bfe09`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:16:44,612::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:16:44,612::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:44,613::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`1b3d8670-5bb5-4a03-8407-08c7c79bfe09`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:44,613::task::827::TaskManager.Task::(resourceAcquired) Task=`c9151243-c029-4616-bbae-b4563ae9539b`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:16:44,613::task::990::TaskManager.Task::(_decref) Task=`c9151243-c029-4616-bbae-b4563ae9539b`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:44,613::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244815360', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244815360', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244819456', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244815360', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:44,613::task::1185::TaskManager.Task::(prepare) Task=`c9151243-c029-4616-bbae-b4563ae9539b`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244815360', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244815360', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244819456', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244815360', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:44,613::task::595::TaskManager.Task::(_updateState) Task=`c9151243-c029-4616-bbae-b4563ae9539b`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:44,613::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:44,614::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:44,614::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:44,614::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:44,614::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:44,614::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:44,614::task::990::TaskManager.Task::(_decref) Task=`c9151243-c029-4616-bbae-b4563ae9539b`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:16:44,774::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:16:44,778::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n587 bytes (587 B) copied, 0.000276511 s, 2.1 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:16:44,898::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:16:44,903::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000233704 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:45,104::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [7896c94a]
>Thread-13::DEBUG::2014-06-23 12:16:45,105::task::595::TaskManager.Task::(_updateState) Task=`9260d104-97b6-40b6-8e3d-093bf687124b`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:45,105::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '/storage/sd_owned_by_root', 'iqn': '', 'user': '', 'tpgt': '1', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
>Thread-13::ERROR::2014-06-23 12:16:45,108::hsm::2378::Storage.HSM::(connectStorageServer) Could not connect to storageServer
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/hsm.py", line 2375, in connectStorageServer
>    conObj.connect()
>  File "/usr/share/vdsm/storage/storageServer.py", line 489, in connect
>    os.chmod(lnPath, 0o775)
>OSError: [Errno 1] Operation not permitted: '/rhev/data-center/mnt/_storage_sd__owned__by__root'
>Thread-13::DEBUG::2014-06-23 12:16:45,109::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {26ac6b95-0f85-4453-b46b-dc94074490af: storage.localFsSD.findDomain, cfd4f121-48d7-45b9-ab47-f57464b377f1: storage.localFsSD.findDomain, 9ab3ca6f-c18b-4635-a004-670ecc93431b: storage.localFsSD.findDomain, b071beb4-4aed-4eed-9d4c-98b424976dc6: storage.localFsSD.findDomain}
>Thread-13::INFO::2014-06-23 12:16:45,109::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 100, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-13::DEBUG::2014-06-23 12:16:45,109::task::1185::TaskManager.Task::(prepare) Task=`9260d104-97b6-40b6-8e3d-093bf687124b`::finished: {'statuslist': [{'status': 100, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-13::DEBUG::2014-06-23 12:16:45,109::task::595::TaskManager.Task::(_updateState) Task=`9260d104-97b6-40b6-8e3d-093bf687124b`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:45,109::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:45,109::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:45,109::task::990::TaskManager.Task::(_decref) Task=`9260d104-97b6-40b6-8e3d-093bf687124b`::ref 0 aborting False
>Thread-33::DEBUG::2014-06-23 12:16:45,123::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:16:45,128::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:45,136::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.00021582 s, 1.5 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:45,137::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000189467 s, 1.8 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:45,648::task::595::TaskManager.Task::(_updateState) Task=`5715e02b-0040-4a8e-b4ee-cc7841dec1af`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:45,648::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:16:45,648::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000189467', 'lastCheck': '0.5', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00021582', 'lastCheck': '0.5', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000276511', 'lastCheck': '0.9', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000233704', 'lastCheck': '0.7', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:16:45,648::task::1185::TaskManager.Task::(prepare) Task=`5715e02b-0040-4a8e-b4ee-cc7841dec1af`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000189467', 'lastCheck': '0.5', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00021582', 'lastCheck': '0.5', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000276511', 'lastCheck': '0.9', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000233704', 'lastCheck': '0.7', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:16:45,648::task::595::TaskManager.Task::(_updateState) Task=`5715e02b-0040-4a8e-b4ee-cc7841dec1af`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:45,648::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:45,648::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:45,648::task::990::TaskManager.Task::(_decref) Task=`5715e02b-0040-4a8e-b4ee-cc7841dec1af`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:51,429::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [5aee09ab]
>Thread-13::DEBUG::2014-06-23 12:16:51,430::task::595::TaskManager.Task::(_updateState) Task=`ce949f19-5907-4c95-ad1d-0b20d4b2d19f`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:51,430::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '/storage/sd_owned_by_root', 'iqn': '', 'user': '', 'tpgt': '1', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
>Thread-13::DEBUG::2014-06-23 12:16:51,433::hsm::2334::Storage.HSM::(__prefetchDomains) local _path: /storage/sd_owned_by_root
>Thread-13::DEBUG::2014-06-23 12:16:51,433::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-13::DEBUG::2014-06-23 12:16:51,433::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {26ac6b95-0f85-4453-b46b-dc94074490af: storage.localFsSD.findDomain, cfd4f121-48d7-45b9-ab47-f57464b377f1: storage.localFsSD.findDomain, 9ab3ca6f-c18b-4635-a004-670ecc93431b: storage.localFsSD.findDomain, b071beb4-4aed-4eed-9d4c-98b424976dc6: storage.localFsSD.findDomain}
>Thread-13::INFO::2014-06-23 12:16:51,433::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-13::DEBUG::2014-06-23 12:16:51,433::task::1185::TaskManager.Task::(prepare) Task=`ce949f19-5907-4c95-ad1d-0b20d4b2d19f`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-13::DEBUG::2014-06-23 12:16:51,433::task::595::TaskManager.Task::(_updateState) Task=`ce949f19-5907-4c95-ad1d-0b20d4b2d19f`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:51,433::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:51,433::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:51,434::task::990::TaskManager.Task::(_decref) Task=`ce949f19-5907-4c95-ad1d-0b20d4b2d19f`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:51,581::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [21c1b376]
>Thread-13::DEBUG::2014-06-23 12:16:51,581::task::595::TaskManager.Task::(_updateState) Task=`8ce3d824-2f38-4e9f-a6cc-ac9cd169f023`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:51,582::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '/storage/sd_owned_by_root', 'iqn': '', 'user': '', 'tpgt': '1', 'password': '******', 'id': '33a5aab0-8772-4281-a071-c74e4268c70a', 'port': ''}], options=None)
>Thread-13::DEBUG::2014-06-23 12:16:51,584::hsm::2334::Storage.HSM::(__prefetchDomains) local _path: /storage/sd_owned_by_root
>Thread-13::DEBUG::2014-06-23 12:16:51,585::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
>Thread-13::DEBUG::2014-06-23 12:16:51,585::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {26ac6b95-0f85-4453-b46b-dc94074490af: storage.localFsSD.findDomain, cfd4f121-48d7-45b9-ab47-f57464b377f1: storage.localFsSD.findDomain, 9ab3ca6f-c18b-4635-a004-670ecc93431b: storage.localFsSD.findDomain, b071beb4-4aed-4eed-9d4c-98b424976dc6: storage.localFsSD.findDomain}
>Thread-13::INFO::2014-06-23 12:16:51,585::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '33a5aab0-8772-4281-a071-c74e4268c70a'}]}
>Thread-13::DEBUG::2014-06-23 12:16:51,585::task::1185::TaskManager.Task::(prepare) Task=`8ce3d824-2f38-4e9f-a6cc-ac9cd169f023`::finished: {'statuslist': [{'status': 0, 'id': '33a5aab0-8772-4281-a071-c74e4268c70a'}]}
>Thread-13::DEBUG::2014-06-23 12:16:51,585::task::595::TaskManager.Task::(_updateState) Task=`8ce3d824-2f38-4e9f-a6cc-ac9cd169f023`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:51,585::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:51,585::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:51,585::task::990::TaskManager.Task::(_decref) Task=`8ce3d824-2f38-4e9f-a6cc-ac9cd169f023`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:51,593::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [21c1b376]
>Thread-13::DEBUG::2014-06-23 12:16:51,593::task::595::TaskManager.Task::(_updateState) Task=`743052b7-2214-413d-b6c4-234216081b1a`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:51,594::logUtils::44::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=4, sdUUID='65e38dfb-5d35-41d9-835c-1483386b4077', domainName='sd_owned_by_root', typeSpecificArg='/storage/sd_owned_by_root', domClass=1, domVersion='3', options=None)
>Thread-13::DEBUG::2014-06-23 12:16:51,594::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-13::DEBUG::2014-06-23 12:16:51,594::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-13::DEBUG::2014-06-23 12:16:51,594::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-13::DEBUG::2014-06-23 12:16:51,594::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-13::DEBUG::2014-06-23 12:16:51,594::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-13::DEBUG::2014-06-23 12:16:51,594::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-13::DEBUG::2014-06-23 12:16:51,627::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-13::DEBUG::2014-06-23 12:16:51,627::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-13::DEBUG::2014-06-23 12:16:52,008::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:16:52,008::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,009::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,009::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,009::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,009::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,009::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,010::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-13::ERROR::2014-06-23 12:16:52,010::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-13::ERROR::2014-06-23 12:16:52,010::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-13::DEBUG::2014-06-23 12:16:52,010::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-13::DEBUG::2014-06-23 12:16:52,014::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600144f09dbd050000004ddbe77f0011|/dev/mapper/3600144f09dbd050000004ddbe78f0012|/dev/mapper/3600144f09dbd050000004ddbe7a00013|/dev/mapper/3600144f09dbd050000004ddbe7ad0014|/dev/mapper/3600144f09dbd050000004ddbe7bb0015|/dev/mapper/3600144f09dbd050000004ddbe8770016|/dev/mapper/3600144f09dbd050000004ddbe8830017|/dev/mapper/3600144f09dbd050000004ddbe8910018|/dev/mapper/3600144f09dbd050000004ddbe89f0019|/dev/mapper/3600144f09dbd050000004ddbe8ad001a|/dev/mapper/3600144f09dbd050000004ddbeaa50020|/dev/mapper/3600144f09dbd050000004ddbeab50021|/dev/mapper/3600144f09dbd050000004ddbeac50022|/dev/mapper/3600144f09dbd050000004ddbead60023|/dev/mapper/3600144f09dbd050000004ddbeae90024|/dev/mapper/3600144f09dbd050000004e1994980004|/dev/mapper/3600144f09dbd050000004e1994c60005|/dev/mapper/3600144f09dbd050000004e1994f10006|/dev/mapper/3600144f09dbd050000004e19953d0007|/dev/mapper/3600144f09dbd050000004e19956b0008|/dev/mapper/3600144f09dbd05000000501651410004|/dev/mapper/3600144f09dbd05000000501654860005|/dev/mapper/3600144f09dbd05000000501654960006|/dev/mapper/3600144f09dbd050000005016549f0007|/dev/mapper/3600144f09dbd05000000501654ac0008|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free,lv_count,pv_count,pv_name 65e38dfb-5d35-41d9-835c-1483386b4077' (cwd None)
>Thread-13::DEBUG::2014-06-23 12:16:52,305::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  Volume group "65e38dfb-5d35-41d9-835c-1483386b4077" not found\n  Skipping volume group 65e38dfb-5d35-41d9-835c-1483386b4077\n'; <rc> = 5
>Thread-13::WARNING::2014-06-23 12:16:52,307::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "65e38dfb-5d35-41d9-835c-1483386b4077" not found', '  Skipping volume group 65e38dfb-5d35-41d9-835c-1483386b4077']
>Thread-13::DEBUG::2014-06-23 12:16:52,307::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-13::ERROR::2014-06-23 12:16:52,393::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 65e38dfb-5d35-41d9-835c-1483386b4077 not found
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
>    dom = findMethod(sdUUID)
>  File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
>    raise se.StorageDomainDoesNotExist(sdUUID)
>StorageDomainDoesNotExist: Storage domain does not exist: ('65e38dfb-5d35-41d9-835c-1483386b4077',)
>Thread-13::INFO::2014-06-23 12:16:52,393::localFsSD::69::Storage.StorageDomain::(create) sdUUID=65e38dfb-5d35-41d9-835c-1483386b4077 domainName=sd_owned_by_root remotePath=/storage/sd_owned_by_root domClass=1
>Thread-13::DEBUG::2014-06-23 12:16:52,470::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-13::DEBUG::2014-06-23 12:16:52,472::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
>Thread-13::WARNING::2014-06-23 12:16:52,472::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-13::DEBUG::2014-06-23 12:16:52,472::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-13::DEBUG::2014-06-23 12:16:52,472::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-13::DEBUG::2014-06-23 12:16:52,472::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=705ddc21ed028cffb4e3139cc8e996f7e1a7cb23']
>Thread-13::DEBUG::2014-06-23 12:16:52,473::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-13::DEBUG::2014-06-23 12:16:52,473::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-13::DEBUG::2014-06-23 12:16:52,473::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-13::DEBUG::2014-06-23 12:16:52,475::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=705ddc21ed028cffb4e3139cc8e996f7e1a7cb23']
>Thread-13::DEBUG::2014-06-23 12:16:52,476::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-13::DEBUG::2014-06-23 12:16:52,476::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '65e38dfb-5d35-41d9-835c-1483386b4077_imageNS'
>Thread-13::DEBUG::2014-06-23 12:16:52,476::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace '65e38dfb-5d35-41d9-835c-1483386b4077_volumeNS'
>Thread-13::DEBUG::2014-06-23 12:16:52,476::clusterlock::144::initSANLock::(initSANLock) Initializing SANLock for domain 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-13::DEBUG::2014-06-23 12:16:52,793::sd::424::Storage.StorageDomain::(initSPMlease) lease initialized successfully
>Thread-13::DEBUG::2014-06-23 12:16:52,793::hsm::2636::Storage.HSM::(createStorageDomain) knownSDs: {26ac6b95-0f85-4453-b46b-dc94074490af: storage.localFsSD.findDomain, 65e38dfb-5d35-41d9-835c-1483386b4077: storage.localFsSD.findDomain, cfd4f121-48d7-45b9-ab47-f57464b377f1: storage.localFsSD.findDomain, 9ab3ca6f-c18b-4635-a004-670ecc93431b: storage.localFsSD.findDomain, b071beb4-4aed-4eed-9d4c-98b424976dc6: storage.localFsSD.findDomain}
>Thread-13::INFO::2014-06-23 12:16:52,793::logUtils::47::dispatcher::(wrapper) Run and protect: createStorageDomain, Return response: None
>Thread-13::DEBUG::2014-06-23 12:16:52,793::task::1185::TaskManager.Task::(prepare) Task=`743052b7-2214-413d-b6c4-234216081b1a`::finished: None
>Thread-13::DEBUG::2014-06-23 12:16:52,793::task::595::TaskManager.Task::(_updateState) Task=`743052b7-2214-413d-b6c4-234216081b1a`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:52,793::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:52,793::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:52,793::task::990::TaskManager.Task::(_decref) Task=`743052b7-2214-413d-b6c4-234216081b1a`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:52,846::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [21c1b376]
>Thread-13::DEBUG::2014-06-23 12:16:52,846::task::595::TaskManager.Task::(_updateState) Task=`e860832d-6a42-4f9c-b96e-d1aa95b37dc9`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:52,846::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainStats(sdUUID='65e38dfb-5d35-41d9-835c-1483386b4077', options=None)
>Thread-13::DEBUG::2014-06-23 12:16:52,846::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.65e38dfb-5d35-41d9-835c-1483386b4077`ReqID=`9e82f27b-971c-4f8a-9d07-a47d5834c018`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2775' at 'getStorageDomainStats'
>Thread-13::DEBUG::2014-06-23 12:16:52,846::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' for lock type 'shared'
>Thread-13::DEBUG::2014-06-23 12:16:52,846::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' is free. Now locking as 'shared' (1 active user)
>Thread-13::DEBUG::2014-06-23 12:16:52,846::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.65e38dfb-5d35-41d9-835c-1483386b4077`ReqID=`9e82f27b-971c-4f8a-9d07-a47d5834c018`::Granted request
>Thread-13::DEBUG::2014-06-23 12:16:52,847::task::827::TaskManager.Task::(resourceAcquired) Task=`e860832d-6a42-4f9c-b96e-d1aa95b37dc9`::_resourcesAcquired: Storage.65e38dfb-5d35-41d9-835c-1483386b4077 (shared)
>Thread-13::DEBUG::2014-06-23 12:16:52,847::task::990::TaskManager.Task::(_decref) Task=`e860832d-6a42-4f9c-b96e-d1aa95b37dc9`::ref 1 aborting False
>Thread-13::INFO::2014-06-23 12:16:52,847::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainStats, Return response: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '17242656768', 'disktotal': '20642131968', 'mdafree': 0}}
>Thread-13::DEBUG::2014-06-23 12:16:52,847::task::1185::TaskManager.Task::(prepare) Task=`e860832d-6a42-4f9c-b96e-d1aa95b37dc9`::finished: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '17242656768', 'disktotal': '20642131968', 'mdafree': 0}}
>Thread-13::DEBUG::2014-06-23 12:16:52,847::task::595::TaskManager.Task::(_updateState) Task=`e860832d-6a42-4f9c-b96e-d1aa95b37dc9`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:52,847::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.65e38dfb-5d35-41d9-835c-1483386b4077': < ResourceRef 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077', isValid: 'True' obj: 'None'>}
>Thread-13::DEBUG::2014-06-23 12:16:52,848::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:52,848::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077'
>Thread-13::DEBUG::2014-06-23 12:16:52,848::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' (0 active users)
>Thread-13::DEBUG::2014-06-23 12:16:52,848::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' is free, finding out if anyone is waiting for it.
>Thread-13::DEBUG::2014-06-23 12:16:52,848::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077', Clearing records.
>Thread-13::DEBUG::2014-06-23 12:16:52,848::task::990::TaskManager.Task::(_decref) Task=`e860832d-6a42-4f9c-b96e-d1aa95b37dc9`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:52,992::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [18750aee]
>Thread-13::DEBUG::2014-06-23 12:16:52,992::task::595::TaskManager.Task::(_updateState) Task=`7fe65f20-c31b-4b03-9a31-ea4c39e52a4c`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:52,992::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '/storage/sd_owned_by_root', 'iqn': '', 'user': '', 'tpgt': '1', 'password': '******', 'id': '33a5aab0-8772-4281-a071-c74e4268c70a', 'port': ''}], options=None)
>Thread-13::DEBUG::2014-06-23 12:16:52,995::hsm::2334::Storage.HSM::(__prefetchDomains) local _path: /storage/sd_owned_by_root
>Thread-13::DEBUG::2014-06-23 12:16:52,995::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('65e38dfb-5d35-41d9-835c-1483386b4077',)
>Thread-13::DEBUG::2014-06-23 12:16:52,995::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {26ac6b95-0f85-4453-b46b-dc94074490af: storage.localFsSD.findDomain, 65e38dfb-5d35-41d9-835c-1483386b4077: storage.localFsSD.findDomain, 9ab3ca6f-c18b-4635-a004-670ecc93431b: storage.localFsSD.findDomain, cfd4f121-48d7-45b9-ab47-f57464b377f1: storage.localFsSD.findDomain, b071beb4-4aed-4eed-9d4c-98b424976dc6: storage.localFsSD.findDomain}
>Thread-13::INFO::2014-06-23 12:16:52,995::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '33a5aab0-8772-4281-a071-c74e4268c70a'}]}
>Thread-13::DEBUG::2014-06-23 12:16:52,996::task::1185::TaskManager.Task::(prepare) Task=`7fe65f20-c31b-4b03-9a31-ea4c39e52a4c`::finished: {'statuslist': [{'status': 0, 'id': '33a5aab0-8772-4281-a071-c74e4268c70a'}]}
>Thread-13::DEBUG::2014-06-23 12:16:52,996::task::595::TaskManager.Task::(_updateState) Task=`7fe65f20-c31b-4b03-9a31-ea4c39e52a4c`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:52,996::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:52,996::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:52,996::task::990::TaskManager.Task::(_decref) Task=`7fe65f20-c31b-4b03-9a31-ea4c39e52a4c`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:53,002::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [77267c28]
>Thread-68::DEBUG::2014-06-23 12:16:53,002::task::595::TaskManager.Task::(_updateState) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:53,002::logUtils::44::dispatcher::(wrapper) Run and protect: attachStorageDomain(sdUUID='65e38dfb-5d35-41d9-835c-1483386b4077', spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:53,002::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`3a66558a-cdfa-44fd-b5a4-9f684e366b2d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1186' at 'attachStorageDomain'
>Thread-68::DEBUG::2014-06-23 12:16:53,002::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'exclusive'
>Thread-68::DEBUG::2014-06-23 12:16:53,002::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'exclusive' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:53,002::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`3a66558a-cdfa-44fd-b5a4-9f684e366b2d`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:53,003::task::827::TaskManager.Task::(resourceAcquired) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (exclusive)
>Thread-68::DEBUG::2014-06-23 12:16:53,003::task::990::TaskManager.Task::(_decref) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::ref 1 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:53,003::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.65e38dfb-5d35-41d9-835c-1483386b4077`ReqID=`e5d2d4d9-5472-4bbb-b21a-6012dd04f7fb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1187' at 'attachStorageDomain'
>Thread-68::DEBUG::2014-06-23 12:16:53,003::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' for lock type 'exclusive'
>Thread-68::DEBUG::2014-06-23 12:16:53,003::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' is free. Now locking as 'exclusive' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:53,003::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.65e38dfb-5d35-41d9-835c-1483386b4077`ReqID=`e5d2d4d9-5472-4bbb-b21a-6012dd04f7fb`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:53,003::task::827::TaskManager.Task::(resourceAcquired) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::_resourcesAcquired: Storage.65e38dfb-5d35-41d9-835c-1483386b4077 (exclusive)
>Thread-68::DEBUG::2014-06-23 12:16:53,003::task::990::TaskManager.Task::(_decref) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:53,004::sp::860::Storage.StoragePool::(attachSD) sdUUID=65e38dfb-5d35-41d9-835c-1483386b4077 spUUID=d4274bab-7607-4239-9618-2f1ea702508c
>Thread-68::DEBUG::2014-06-23 12:16:53,004::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-68::DEBUG::2014-06-23 12:16:53,004::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-68::DEBUG::2014-06-23 12:16:53,004::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-68::DEBUG::2014-06-23 12:16:53,004::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-68::DEBUG::2014-06-23 12:16:53,004::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-68::DEBUG::2014-06-23 12:16:53,004::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-68::DEBUG::2014-06-23 12:16:53,044::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-68::DEBUG::2014-06-23 12:16:53,044::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-68::DEBUG::2014-06-23 12:16:53,501::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-68::DEBUG::2014-06-23 12:16:53,501::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:53,502::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:53,502::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:53,502::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:53,503::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:53,503::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:53,503::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-68::DEBUG::2014-06-23 12:16:53,510::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::DEBUG::2014-06-23 12:16:53,513::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-68::DEBUG::2014-06-23 12:16:53,517::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=705ddc21ed028cffb4e3139cc8e996f7e1a7cb23']
>Thread-68::DEBUG::2014-06-23 12:16:53,518::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-68::INFO::2014-06-23 12:16:53,519::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 65e38dfb-5d35-41d9-835c-1483386b4077_imageNS already registered
>Thread-68::INFO::2014-06-23 12:16:53,519::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 65e38dfb-5d35-41d9-835c-1483386b4077_volumeNS already registered
>Thread-68::DEBUG::2014-06-23 12:16:53,519::clusterlock::337::LocalLock::(acquireHostId) Host id for domain 65e38dfb-5d35-41d9-835c-1483386b4077 successfully acquired (id: 1)
>Thread-68::INFO::2014-06-23 12:16:53,519::clusterlock::365::LocalLock::(acquire) Acquiring local lock for domain 65e38dfb-5d35-41d9-835c-1483386b4077 (id: 1)
>Thread-68::DEBUG::2014-06-23 12:16:53,520::clusterlock::400::LocalLock::(acquire) Local lock for domain 65e38dfb-5d35-41d9-835c-1483386b4077 successfully acquired (id: 1)
>Thread-68::DEBUG::2014-06-23 12:16:53,523::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=705ddc21ed028cffb4e3139cc8e996f7e1a7cb23']
>Thread-68::DEBUG::2014-06-23 12:16:53,523::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-68::DEBUG::2014-06-23 12:16:53,524::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-68::DEBUG::2014-06-23 12:16:53,524::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=d4274bab-7607-4239-9618-2f1ea702508c', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=cdfdae4c878c9f470c16bedf645d859d33810d08']
>Thread-68::DEBUG::2014-06-23 12:16:53,525::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-68::DEBUG::2014-06-23 12:16:53,526::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-68::DEBUG::2014-06-23 12:16:53,526::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-68::DEBUG::2014-06-23 12:16:53,526::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vdshost2_sd1', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=local_dc', 'POOL_DOMAINS=26ac6b95-0f85-4453-b46b-dc94074490af:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Attached,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=d4274bab-7607-4239-9618-2f1ea702508c', 'REMOTE_PATH=/storage/sd1', 'ROLE=Master', 'SDUUID=b071beb4-4aed-4eed-9d4c-98b424976dc6', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=b62a70a0ca6caed23ea66edb377f423fbc6a34e5']
>Thread-68::DEBUG::2014-06-23 12:16:53,528::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-68::INFO::2014-06-23 12:16:53,528::sp::1104::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077 to /rhev/data-center/d4274bab-7607-4239-9618-2f1ea702508c/65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::INFO::2014-06-23 12:16:53,529::clusterlock::409::LocalLock::(release) Releasing local lock for domain 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::DEBUG::2014-06-23 12:16:53,529::clusterlock::422::LocalLock::(release) Local lock for domain 65e38dfb-5d35-41d9-835c-1483386b4077 successfully released
>Thread-68::DEBUG::2014-06-23 12:16:53,529::clusterlock::355::LocalLock::(releaseHostId) Host id for domain 65e38dfb-5d35-41d9-835c-1483386b4077 released successfully (id: 1)
>Thread-68::DEBUG::2014-06-23 12:16:53,529::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-68::DEBUG::2014-06-23 12:16:53,529::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-68::DEBUG::2014-06-23 12:16:53,529::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-68::INFO::2014-06-23 12:16:53,530::logUtils::47::dispatcher::(wrapper) Run and protect: attachStorageDomain, Return response: None
>Thread-68::DEBUG::2014-06-23 12:16:53,530::task::1185::TaskManager.Task::(prepare) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::finished: None
>Thread-68::DEBUG::2014-06-23 12:16:53,530::task::595::TaskManager.Task::(_updateState) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:53,530::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>, 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077': < ResourceRef 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:53,530::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:53,531::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:53,531::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:53,531::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:53,531::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:53,531::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077'
>Thread-68::DEBUG::2014-06-23 12:16:53,532::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:53,532::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:53,532::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:53,532::task::990::TaskManager.Task::(_decref) Task=`70587098-d899-40ec-b737-c62b2ecade5d`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-23 12:16:53,644::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [132e8fb0]
>Thread-13::DEBUG::2014-06-23 12:16:53,644::task::595::TaskManager.Task::(_updateState) Task=`0476899b-2587-496e-bf0d-5955ece386bf`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:53,644::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '/storage/sd_owned_by_root', 'iqn': '', 'user': '', 'tpgt': '1', 'password': '******', 'id': '33a5aab0-8772-4281-a071-c74e4268c70a', 'port': ''}], options=None)
>Thread-13::DEBUG::2014-06-23 12:16:53,651::hsm::2334::Storage.HSM::(__prefetchDomains) local _path: /storage/sd_owned_by_root
>Thread-13::DEBUG::2014-06-23 12:16:53,651::hsm::2341::Storage.HSM::(__prefetchDomains) Found SD uuids: ('65e38dfb-5d35-41d9-835c-1483386b4077',)
>Thread-13::DEBUG::2014-06-23 12:16:53,651::hsm::2397::Storage.HSM::(connectStorageServer) knownSDs: {26ac6b95-0f85-4453-b46b-dc94074490af: storage.localFsSD.findDomain, 65e38dfb-5d35-41d9-835c-1483386b4077: storage.localFsSD.findDomain, 9ab3ca6f-c18b-4635-a004-670ecc93431b: storage.localFsSD.findDomain, cfd4f121-48d7-45b9-ab47-f57464b377f1: storage.localFsSD.findDomain, b071beb4-4aed-4eed-9d4c-98b424976dc6: storage.localFsSD.findDomain}
>Thread-13::INFO::2014-06-23 12:16:53,651::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '33a5aab0-8772-4281-a071-c74e4268c70a'}]}
>Thread-13::DEBUG::2014-06-23 12:16:53,651::task::1185::TaskManager.Task::(prepare) Task=`0476899b-2587-496e-bf0d-5955ece386bf`::finished: {'statuslist': [{'status': 0, 'id': '33a5aab0-8772-4281-a071-c74e4268c70a'}]}
>Thread-13::DEBUG::2014-06-23 12:16:53,652::task::595::TaskManager.Task::(_updateState) Task=`0476899b-2587-496e-bf0d-5955ece386bf`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:53,652::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:53,652::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:53,652::task::990::TaskManager.Task::(_decref) Task=`0476899b-2587-496e-bf0d-5955ece386bf`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:53,659::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123] flowID [2e80bd4b]
>Thread-68::DEBUG::2014-06-23 12:16:53,659::task::595::TaskManager.Task::(_updateState) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:53,659::logUtils::44::dispatcher::(wrapper) Run and protect: activateStorageDomain(sdUUID='65e38dfb-5d35-41d9-835c-1483386b4077', spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`8602c22a-59c1-4a92-9a5d-bd2046bf43b7`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1245' at 'activateStorageDomain'
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'exclusive'
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'exclusive' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`8602c22a-59c1-4a92-9a5d-bd2046bf43b7`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:53,660::task::827::TaskManager.Task::(resourceAcquired) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (exclusive)
>Thread-68::DEBUG::2014-06-23 12:16:53,660::task::990::TaskManager.Task::(_decref) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::ref 1 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.65e38dfb-5d35-41d9-835c-1483386b4077`ReqID=`22f4cb2e-b80d-4d4d-9052-776c52a3c28a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1246' at 'activateStorageDomain'
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' for lock type 'exclusive'
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' is free. Now locking as 'exclusive' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:53,660::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.65e38dfb-5d35-41d9-835c-1483386b4077`ReqID=`22f4cb2e-b80d-4d4d-9052-776c52a3c28a`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:53,661::task::827::TaskManager.Task::(resourceAcquired) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::_resourcesAcquired: Storage.65e38dfb-5d35-41d9-835c-1483386b4077 (exclusive)
>Thread-68::DEBUG::2014-06-23 12:16:53,661::task::990::TaskManager.Task::(_decref) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:53,661::sp::1015::Storage.StoragePool::(activateSD) sdUUID=65e38dfb-5d35-41d9-835c-1483386b4077 spUUID=d4274bab-7607-4239-9618-2f1ea702508c
>Thread-68::DEBUG::2014-06-23 12:16:53,661::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-68::DEBUG::2014-06-23 12:16:53,661::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-68::DEBUG::2014-06-23 12:16:53,661::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-68::DEBUG::2014-06-23 12:16:53,661::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-68::DEBUG::2014-06-23 12:16:53,661::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-68::DEBUG::2014-06-23 12:16:53,661::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-68::DEBUG::2014-06-23 12:16:53,688::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-68::DEBUG::2014-06-23 12:16:53,688::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-68::DEBUG::2014-06-23 12:16:54,024::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-68::DEBUG::2014-06-23 12:16:54,025::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:54,025::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:54,025::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:54,026::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:54,026::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:54,026::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-68::DEBUG::2014-06-23 12:16:54,026::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-68::DEBUG::2014-06-23 12:16:54,041::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::DEBUG::2014-06-23 12:16:54,043::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-68::DEBUG::2014-06-23 12:16:54,069::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=d4274bab-7607-4239-9618-2f1ea702508c', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=cdfdae4c878c9f470c16bedf645d859d33810d08']
>Thread-68::DEBUG::2014-06-23 12:16:54,070::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-68::INFO::2014-06-23 12:16:54,070::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 65e38dfb-5d35-41d9-835c-1483386b4077_imageNS already registered
>Thread-68::INFO::2014-06-23 12:16:54,070::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 65e38dfb-5d35-41d9-835c-1483386b4077_volumeNS already registered
>Thread-68::INFO::2014-06-23 12:16:54,071::sp::1104::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077 to /rhev/data-center/d4274bab-7607-4239-9618-2f1ea702508c/65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::DEBUG::2014-06-23 12:16:54,071::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-68::DEBUG::2014-06-23 12:16:54,072::persistentDict::160::Storage.PersistentDict::(transaction) Reusing active transaction
>Thread-68::DEBUG::2014-06-23 12:16:54,072::persistentDict::160::Storage.PersistentDict::(transaction) Reusing active transaction
>Thread-68::DEBUG::2014-06-23 12:16:54,072::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-68::DEBUG::2014-06-23 12:16:54,072::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=d4274bab-7607-4239-9618-2f1ea702508c', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=3a83a3bdd576ddb45f8e5a1486e3d9639940debf']
>Thread-68::DEBUG::2014-06-23 12:16:54,073::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-68::DEBUG::2014-06-23 12:16:54,088::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::DEBUG::2014-06-23 12:16:54,090::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-68::DEBUG::2014-06-23 12:16:54,094::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=sd_owned_by_root', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_UUID=d4274bab-7607-4239-9618-2f1ea702508c', 'REMOTE_PATH=/storage/sd_owned_by_root', 'ROLE=Regular', 'SDUUID=65e38dfb-5d35-41d9-835c-1483386b4077', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=3a83a3bdd576ddb45f8e5a1486e3d9639940debf']
>Thread-68::DEBUG::2014-06-23 12:16:54,095::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-68::INFO::2014-06-23 12:16:54,095::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 65e38dfb-5d35-41d9-835c-1483386b4077_imageNS already registered
>Thread-68::INFO::2014-06-23 12:16:54,095::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 65e38dfb-5d35-41d9-835c-1483386b4077_volumeNS already registered
>Thread-68::DEBUG::2014-06-23 12:16:54,096::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
>Thread-68::DEBUG::2014-06-23 12:16:54,096::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
>Thread-68::DEBUG::2014-06-23 12:16:54,096::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vdshost2_sd1', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=local_dc', 'POOL_DOMAINS=26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=d4274bab-7607-4239-9618-2f1ea702508c', 'REMOTE_PATH=/storage/sd1', 'ROLE=Master', 'SDUUID=b071beb4-4aed-4eed-9d4c-98b424976dc6', 'TYPE=LOCALFS', 'VERSION=3', '_SHA_CKSUM=3fc47d88672e8ab29069713dcb446ba8b2ea43fb']
>Thread-68::DEBUG::2014-06-23 12:16:54,097::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
>Thread-68::DEBUG::2014-06-23 12:16:54,098::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-68::DEBUG::2014-06-23 12:16:54,098::misc::764::SamplingMethod::(__call__) Got in to sampling method
>Thread-68::INFO::2014-06-23 12:16:54,098::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-108::DEBUG::2014-06-23 12:16:54,099::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-68::DEBUG::2014-06-23 12:16:54,099::sp::1395::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `d4274bab-7607-4239-9618-2f1ea702508c` started monitoring domain `65e38dfb-5d35-41d9-835c-1483386b4077`
>Thread-68::DEBUG::2014-06-23 12:16:54,101::misc::772::SamplingMethod::(__call__) Returning last result
>Thread-68::INFO::2014-06-23 12:16:54,101::logUtils::47::dispatcher::(wrapper) Run and protect: activateStorageDomain, Return response: None
>Thread-68::DEBUG::2014-06-23 12:16:54,103::task::1185::TaskManager.Task::(prepare) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::finished: None
>Thread-68::DEBUG::2014-06-23 12:16:54,104::task::595::TaskManager.Task::(_updateState) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:54,105::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>, 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077': < ResourceRef 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:54,106::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:54,108::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:54,109::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:54,110::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:54,111::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:54,112::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077'
>Thread-68::DEBUG::2014-06-23 12:16:54,112::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:54,113::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:54,113::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.65e38dfb-5d35-41d9-835c-1483386b4077', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:54,113::task::990::TaskManager.Task::(_decref) Task=`bc4e23a1-3040-471f-80fb-f32332982a21`::ref 0 aborting False
>Thread-108::DEBUG::2014-06-23 12:16:54,115::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-108::DEBUG::2014-06-23 12:16:54,154::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000431234 s, 835 kB/s\n'; <rc> = 0
>Thread-108::DEBUG::2014-06-23 12:16:54,155::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain 65e38dfb-5d35-41d9-835c-1483386b4077 changed its status to Valid
>Thread-109::DEBUG::2014-06-23 12:16:54,157::misc::884::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-109::DEBUG::2014-06-23 12:16:54,158::misc::894::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-108::DEBUG::2014-06-23 12:16:54,158::clusterlock::337::LocalLock::(acquireHostId) Host id for domain 65e38dfb-5d35-41d9-835c-1483386b4077 successfully acquired (id: 1)
>Thread-109::DEBUG::2014-06-23 12:16:54,159::misc::904::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-13::DEBUG::2014-06-23 12:16:54,164::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:54,165::task::595::TaskManager.Task::(_updateState) Task=`7a1cdfea-dfef-40e5-a97a-cd7db94c626d`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:54,165::logUtils::44::dispatcher::(wrapper) Run and protect: refreshStoragePool(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', msdUUID='b071beb4-4aed-4eed-9d4c-98b424976dc6', masterVersion=1, options=None)
>Thread-13::DEBUG::2014-06-23 12:16:54,165::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`335ef727-6504-4368-8c28-f8627f0b4182`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '859' at 'refreshStoragePool'
>Thread-13::DEBUG::2014-06-23 12:16:54,166::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-13::DEBUG::2014-06-23 12:16:54,166::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-13::DEBUG::2014-06-23 12:16:54,166::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`335ef727-6504-4368-8c28-f8627f0b4182`::Granted request
>Thread-13::DEBUG::2014-06-23 12:16:54,166::task::827::TaskManager.Task::(resourceAcquired) Task=`7a1cdfea-dfef-40e5-a97a-cd7db94c626d`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-13::DEBUG::2014-06-23 12:16:54,167::task::990::TaskManager.Task::(_decref) Task=`7a1cdfea-dfef-40e5-a97a-cd7db94c626d`::ref 1 aborting False
>Thread-13::INFO::2014-06-23 12:16:54,167::hsm::868::Storage.HSM::(refreshStoragePool) Ignoring the refreshStoragePool request (the host is the SPM)
>Thread-13::INFO::2014-06-23 12:16:54,167::logUtils::47::dispatcher::(wrapper) Run and protect: refreshStoragePool, Return response: None
>Thread-13::DEBUG::2014-06-23 12:16:54,167::task::1185::TaskManager.Task::(prepare) Task=`7a1cdfea-dfef-40e5-a97a-cd7db94c626d`::finished: None
>Thread-13::DEBUG::2014-06-23 12:16:54,167::task::595::TaskManager.Task::(_updateState) Task=`7a1cdfea-dfef-40e5-a97a-cd7db94c626d`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:54,167::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-13::DEBUG::2014-06-23 12:16:54,167::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:54,168::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-13::DEBUG::2014-06-23 12:16:54,168::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-13::DEBUG::2014-06-23 12:16:54,168::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-13::DEBUG::2014-06-23 12:16:54,168::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-13::DEBUG::2014-06-23 12:16:54,168::task::990::TaskManager.Task::(_decref) Task=`7a1cdfea-dfef-40e5-a97a-cd7db94c626d`::ref 0 aborting False
>Thread-110::INFO::2014-06-23 12:16:54,170::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-13::DEBUG::2014-06-23 12:16:54,685::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:16:54,686::task::595::TaskManager.Task::(_updateState) Task=`5d2bda1a-3f07-4fe4-8841-8b8747d3993a`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:16:54,686::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:16:54,686::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:54,686::task::1185::TaskManager.Task::(prepare) Task=`5d2bda1a-3f07-4fe4-8841-8b8747d3993a`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:16:54,686::task::595::TaskManager.Task::(_updateState) Task=`5d2bda1a-3f07-4fe4-8841-8b8747d3993a`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:16:54,686::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:16:54,686::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:16:54,686::task::990::TaskManager.Task::(_decref) Task=`5d2bda1a-3f07-4fe4-8841-8b8747d3993a`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:16:54,694::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:16:54,694::task::595::TaskManager.Task::(_updateState) Task=`78d9cbac-dcea-4e89-84f6-9da1f06cb072`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:16:54,694::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:16:54,694::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`22441af6-5bd2-483d-80f4-349205848cbb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:16:54,695::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:16:54,695::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:16:54,695::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`22441af6-5bd2-483d-80f4-349205848cbb`::Granted request
>Thread-68::DEBUG::2014-06-23 12:16:54,695::task::827::TaskManager.Task::(resourceAcquired) Task=`78d9cbac-dcea-4e89-84f6-9da1f06cb072`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:16:54,695::task::990::TaskManager.Task::(_decref) Task=`78d9cbac-dcea-4e89-84f6-9da1f06cb072`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:16:54,696::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244803072', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242607616', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244807168', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244807168', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244807168', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:54,696::task::1185::TaskManager.Task::(prepare) Task=`78d9cbac-dcea-4e89-84f6-9da1f06cb072`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17244803072', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242607616', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17244807168', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17244807168', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17244807168', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:16:54,696::task::595::TaskManager.Task::(_updateState) Task=`78d9cbac-dcea-4e89-84f6-9da1f06cb072`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:16:54,696::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:16:54,696::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:16:54,696::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:16:54,696::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:16:54,696::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:16:54,696::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:16:54,696::task::990::TaskManager.Task::(_decref) Task=`78d9cbac-dcea-4e89-84f6-9da1f06cb072`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:16:54,781::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:16:54,786::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n631 bytes (631 B) copied, 0.000240561 s, 2.6 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:16:54,906::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:16:54,927::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.0179957 s, 18.6 kB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:55,142::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:55,142::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:16:55,154::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000212381 s, 1.6 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:16:55,154::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.00101333 s, 338 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:01,036::task::595::TaskManager.Task::(_updateState) Task=`7ec2b0f7-4a02-4ac3-9cf0-d266136c19d2`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:01,036::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:17:01,036::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00101333', 'lastCheck': '5.9', 'valid': True}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000431234', 'lastCheck': '6.9', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000212381', 'lastCheck': '5.9', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000240561', 'lastCheck': '6.2', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0179957', 'lastCheck': '6.1', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:17:01,036::task::1185::TaskManager.Task::(prepare) Task=`7ec2b0f7-4a02-4ac3-9cf0-d266136c19d2`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00101333', 'lastCheck': '5.9', 'valid': True}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'code': 0, 'version': 3, 'acquired': False, 'delay': '0.000431234', 'lastCheck': '6.9', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000212381', 'lastCheck': '5.9', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000240561', 'lastCheck': '6.2', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0179957', 'lastCheck': '6.1', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:17:01,036::task::595::TaskManager.Task::(_updateState) Task=`7ec2b0f7-4a02-4ac3-9cf0-d266136c19d2`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:01,036::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:01,036::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:01,037::task::990::TaskManager.Task::(_decref) Task=`7ec2b0f7-4a02-4ac3-9cf0-d266136c19d2`::ref 0 aborting False
>Thread-108::DEBUG::2014-06-23 12:17:04,161::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-108::DEBUG::2014-06-23 12:17:04,166::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000271339 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:04,770::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:17:04,770::task::595::TaskManager.Task::(_updateState) Task=`6b38e4a7-acca-4a75-b522-7094ee7cc6f7`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:04,770::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:17:04,770::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:04,770::task::1185::TaskManager.Task::(prepare) Task=`6b38e4a7-acca-4a75-b522-7094ee7cc6f7`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:04,771::task::595::TaskManager.Task::(_updateState) Task=`6b38e4a7-acca-4a75-b522-7094ee7cc6f7`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:04,771::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:04,771::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:04,771::task::990::TaskManager.Task::(_decref) Task=`6b38e4a7-acca-4a75-b522-7094ee7cc6f7`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:17:04,779::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:17:04,779::task::595::TaskManager.Task::(_updateState) Task=`d7304761-22b5-4ebb-87a5-467beb72d9d2`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:17:04,779::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:17:04,780::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`0b75ed12-f9b0-4c8b-8049-ca45e7d40e0f`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:17:04,780::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:17:04,780::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:17:04,780::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`0b75ed12-f9b0-4c8b-8049-ca45e7d40e0f`::Granted request
>Thread-68::DEBUG::2014-06-23 12:17:04,780::task::827::TaskManager.Task::(resourceAcquired) Task=`d7304761-22b5-4ebb-87a5-467beb72d9d2`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:17:04,780::task::990::TaskManager.Task::(_decref) Task=`d7304761-22b5-4ebb-87a5-467beb72d9d2`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:17:04,781::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242570752', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:04,781::task::1185::TaskManager.Task::(prepare) Task=`d7304761-22b5-4ebb-87a5-467beb72d9d2`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242570752', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242599424', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:04,781::task::595::TaskManager.Task::(_updateState) Task=`d7304761-22b5-4ebb-87a5-467beb72d9d2`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:17:04,781::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:17:04,781::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:17:04,781::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:17:04,781::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:17:04,781::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:17:04,782::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:17:04,782::task::990::TaskManager.Task::(_decref) Task=`d7304761-22b5-4ebb-87a5-467beb72d9d2`::ref 0 aborting False
>Thread-25::DEBUG::2014-06-23 12:17:04,789::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:17:04,794::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n631 bytes (631 B) copied, 0.00028243 s, 2.2 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:17:04,930::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:17:04,935::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000239404 s, 1.4 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-23 12:17:05,167::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:17:05,171::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:17:05,180::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000188567 s, 1.8 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:17:05,181::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000191629 s, 1.8 MB/s\n'; <rc> = 0
>Thread-108::DEBUG::2014-06-23 12:17:14,169::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-108::DEBUG::2014-06-23 12:17:14,173::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000287431 s, 1.3 MB/s\n'; <rc> = 0
>Thread-25::DEBUG::2014-06-23 12:17:14,797::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:17:14,802::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n631 bytes (631 B) copied, 0.000300619 s, 2.1 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:14,862::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:17:14,863::task::595::TaskManager.Task::(_updateState) Task=`e8c94fbf-cc5f-4bd6-9a43-640a82bc777e`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:14,863::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:17:14,863::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:14,863::task::1185::TaskManager.Task::(prepare) Task=`e8c94fbf-cc5f-4bd6-9a43-640a82bc777e`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:14,863::task::595::TaskManager.Task::(_updateState) Task=`e8c94fbf-cc5f-4bd6-9a43-640a82bc777e`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:14,863::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:14,863::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:14,863::task::990::TaskManager.Task::(_decref) Task=`e8c94fbf-cc5f-4bd6-9a43-640a82bc777e`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:17:14,871::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:17:14,872::task::595::TaskManager.Task::(_updateState) Task=`a99b380d-18de-410d-9b32-f3a679a2cd2a`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:17:14,872::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:17:14,872::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`09758283-395c-4c56-beb1-e8175e62453c`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:17:14,872::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:17:14,872::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:17:14,872::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`09758283-395c-4c56-beb1-e8175e62453c`::Granted request
>Thread-68::DEBUG::2014-06-23 12:17:14,873::task::827::TaskManager.Task::(resourceAcquired) Task=`a99b380d-18de-410d-9b32-f3a679a2cd2a`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:17:14,873::task::990::TaskManager.Task::(_decref) Task=`a99b380d-18de-410d-9b32-f3a679a2cd2a`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:17:14,873::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:14,873::task::1185::TaskManager.Task::(prepare) Task=`a99b380d-18de-410d-9b32-f3a679a2cd2a`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242558464', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:14,873::task::595::TaskManager.Task::(_updateState) Task=`a99b380d-18de-410d-9b32-f3a679a2cd2a`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:17:14,874::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:17:14,874::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:17:14,874::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:17:14,874::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:17:14,874::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:17:14,874::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:17:14,874::task::990::TaskManager.Task::(_decref) Task=`a99b380d-18de-410d-9b32-f3a679a2cd2a`::ref 0 aborting False
>Thread-21::DEBUG::2014-06-23 12:17:14,938::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:17:14,942::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000247043 s, 1.4 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:17:15,195::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:17:15,195::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:17:15,204::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000195721 s, 1.7 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:17:15,207::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000215682 s, 1.6 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:16,395::task::595::TaskManager.Task::(_updateState) Task=`c23a62ed-dc31-475f-ac80-c4a31b2c6505`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:16,395::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:17:16,396::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000215682', 'lastCheck': '1.2', 'valid': True}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000287431', 'lastCheck': '2.2', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000195721', 'lastCheck': '1.2', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000300619', 'lastCheck': '1.6', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000247043', 'lastCheck': '1.5', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:17:16,396::task::1185::TaskManager.Task::(prepare) Task=`c23a62ed-dc31-475f-ac80-c4a31b2c6505`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000215682', 'lastCheck': '1.2', 'valid': True}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000287431', 'lastCheck': '2.2', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000195721', 'lastCheck': '1.2', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000300619', 'lastCheck': '1.6', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000247043', 'lastCheck': '1.5', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:17:16,396::task::595::TaskManager.Task::(_updateState) Task=`c23a62ed-dc31-475f-ac80-c4a31b2c6505`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:16,396::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:16,396::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:16,396::task::990::TaskManager.Task::(_decref) Task=`c23a62ed-dc31-475f-ac80-c4a31b2c6505`::ref 0 aborting False
>Thread-108::DEBUG::2014-06-23 12:17:24,176::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-108::DEBUG::2014-06-23 12:17:24,180::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000276703 s, 1.3 MB/s\n'; <rc> = 0
>Thread-25::DEBUG::2014-06-23 12:17:24,805::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:17:24,866::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n631 bytes (631 B) copied, 0.0567445 s, 11.1 kB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:17:24,945::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:17:24,950::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000252008 s, 1.3 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:24,994::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:17:24,995::task::595::TaskManager.Task::(_updateState) Task=`393537f6-e8c9-471d-8d50-cfef13350abe`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:24,995::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:17:24,995::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:24,995::task::1185::TaskManager.Task::(prepare) Task=`393537f6-e8c9-471d-8d50-cfef13350abe`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:24,995::task::595::TaskManager.Task::(_updateState) Task=`393537f6-e8c9-471d-8d50-cfef13350abe`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:24,995::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:24,995::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:24,995::task::990::TaskManager.Task::(_decref) Task=`393537f6-e8c9-471d-8d50-cfef13350abe`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:17:25,004::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:17:25,004::task::595::TaskManager.Task::(_updateState) Task=`9933f296-cc04-4603-bfaf-00d5886c372e`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:17:25,004::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:17:25,005::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`c739034c-554e-4148-9164-a8dbcefeb579`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:17:25,005::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:17:25,005::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:17:25,005::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`c739034c-554e-4148-9164-a8dbcefeb579`::Granted request
>Thread-68::DEBUG::2014-06-23 12:17:25,005::task::827::TaskManager.Task::(resourceAcquired) Task=`9933f296-cc04-4603-bfaf-00d5886c372e`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:17:25,005::task::990::TaskManager.Task::(_decref) Task=`9933f296-cc04-4603-bfaf-00d5886c372e`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:17:25,006::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242550272', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242562560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242550272', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242562560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242562560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:25,006::task::1185::TaskManager.Task::(prepare) Task=`9933f296-cc04-4603-bfaf-00d5886c372e`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242550272', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242562560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242550272', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242562560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242562560', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:25,006::task::595::TaskManager.Task::(_updateState) Task=`9933f296-cc04-4603-bfaf-00d5886c372e`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:17:25,006::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:17:25,006::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:17:25,006::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:17:25,006::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:17:25,006::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:17:25,006::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:17:25,007::task::990::TaskManager.Task::(_decref) Task=`9933f296-cc04-4603-bfaf-00d5886c372e`::ref 0 aborting False
>Thread-33::DEBUG::2014-06-23 12:17:25,209::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:17:25,218::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000253699 s, 1.3 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:17:25,220::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:17:25,225::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.00019488 s, 1.8 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:31,603::task::595::TaskManager.Task::(_updateState) Task=`c8291b01-3c35-4f14-8829-7a1598ea4bae`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:31,603::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-23 12:17:31,603::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00019488', 'lastCheck': '6.4', 'valid': True}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000276703', 'lastCheck': '7.4', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000253699', 'lastCheck': '6.4', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0567445', 'lastCheck': '6.7', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000252008', 'lastCheck': '6.7', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:17:31,604::task::1185::TaskManager.Task::(prepare) Task=`c8291b01-3c35-4f14-8829-7a1598ea4bae`::finished: {'26ac6b95-0f85-4453-b46b-dc94074490af': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00019488', 'lastCheck': '6.4', 'valid': True}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000276703', 'lastCheck': '7.4', 'valid': True}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000253699', 'lastCheck': '6.4', 'valid': True}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0567445', 'lastCheck': '6.7', 'valid': True}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000252008', 'lastCheck': '6.7', 'valid': True}}
>Thread-13::DEBUG::2014-06-23 12:17:31,604::task::595::TaskManager.Task::(_updateState) Task=`c8291b01-3c35-4f14-8829-7a1598ea4bae`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:31,604::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:31,604::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:31,604::task::990::TaskManager.Task::(_decref) Task=`c8291b01-3c35-4f14-8829-7a1598ea4bae`::ref 0 aborting False
>Thread-108::DEBUG::2014-06-23 12:17:34,183::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd__owned__by__root/65e38dfb-5d35-41d9-835c-1483386b4077/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-108::DEBUG::2014-06-23 12:17:34,188::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n360 bytes (360 B) copied, 0.000275909 s, 1.3 MB/s\n'; <rc> = 0
>Thread-25::DEBUG::2014-06-23 12:17:34,869::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd1/b071beb4-4aed-4eed-9d4c-98b424976dc6/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-25::DEBUG::2014-06-23 12:17:34,874::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n631 bytes (631 B) copied, 0.000276535 s, 2.3 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-23 12:17:34,953::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd6/9ab3ca6f-c18b-4635-a004-670ecc93431b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-23 12:17:34,957::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000246283 s, 1.4 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-23 12:17:35,054::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-13::DEBUG::2014-06-23 12:17:35,055::task::595::TaskManager.Task::(_updateState) Task=`6509ddc0-6407-4266-8915-a2f2ae0ead55`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-23 12:17:35,055::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-13::INFO::2014-06-23 12:17:35,055::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:35,055::task::1185::TaskManager.Task::(prepare) Task=`6509ddc0-6407-4266-8915-a2f2ae0ead55`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': -1}}
>Thread-13::DEBUG::2014-06-23 12:17:35,055::task::595::TaskManager.Task::(_updateState) Task=`6509ddc0-6407-4266-8915-a2f2ae0ead55`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-23 12:17:35,055::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-23 12:17:35,055::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-23 12:17:35,056::task::990::TaskManager.Task::(_decref) Task=`6509ddc0-6407-4266-8915-a2f2ae0ead55`::ref 0 aborting False
>Thread-68::DEBUG::2014-06-23 12:17:35,064::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-68::DEBUG::2014-06-23 12:17:35,064::task::595::TaskManager.Task::(_updateState) Task=`5d751b25-fb70-4760-b1d3-6e457df1e90a`::moving from state init -> state preparing
>Thread-68::INFO::2014-06-23 12:17:35,064::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-68::DEBUG::2014-06-23 12:17:35,065::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`38ea28df-3e14-419a-892c-66a8d2eb0a87`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2561' at 'getStoragePoolInfo'
>Thread-68::DEBUG::2014-06-23 12:17:35,065::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' for lock type 'shared'
>Thread-68::DEBUG::2014-06-23 12:17:35,065::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free. Now locking as 'shared' (1 active user)
>Thread-68::DEBUG::2014-06-23 12:17:35,065::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.d4274bab-7607-4239-9618-2f1ea702508c`ReqID=`38ea28df-3e14-419a-892c-66a8d2eb0a87`::Granted request
>Thread-68::DEBUG::2014-06-23 12:17:35,065::task::827::TaskManager.Task::(resourceAcquired) Task=`5d751b25-fb70-4760-b1d3-6e457df1e90a`::_resourcesAcquired: Storage.d4274bab-7607-4239-9618-2f1ea702508c (shared)
>Thread-68::DEBUG::2014-06-23 12:17:35,065::task::990::TaskManager.Task::(_decref) Task=`5d751b25-fb70-4760-b1d3-6e457df1e90a`::ref 1 aborting False
>Thread-68::INFO::2014-06-23 12:17:35,066::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:35,066::task::1185::TaskManager.Task::(prepare) Task=`5d751b25-fb70-4760-b1d3-6e457df1e90a`::finished: {'info': {'name': 'local_dc', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '26ac6b95-0f85-4453-b46b-dc94074490af:Active,65e38dfb-5d35-41d9-835c-1483386b4077:Active,cfd4f121-48d7-45b9-ab47-f57464b377f1:Active,b071beb4-4aed-4eed-9d4c-98b424976dc6:Active,9ab3ca6f-c18b-4635-a004-670ecc93431b:Active', 'master_uuid': 'b071beb4-4aed-4eed-9d4c-98b424976dc6', 'version': '3', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 1}, 'dominfo': {'26ac6b95-0f85-4453-b46b-dc94074490af': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '65e38dfb-5d35-41d9-835c-1483386b4077': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'cfd4f121-48d7-45b9-ab47-f57464b377f1': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, 'b071beb4-4aed-4eed-9d4c-98b424976dc6': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}, '9ab3ca6f-c18b-4635-a004-670ecc93431b': {'status': 'Active', 'diskfree': '17242554368', 'isoprefix': '', 'alerts': [], 'disktotal': '20642131968', 'version': 3}}}
>Thread-68::DEBUG::2014-06-23 12:17:35,066::task::595::TaskManager.Task::(_updateState) Task=`5d751b25-fb70-4760-b1d3-6e457df1e90a`::moving from state preparing -> state finished
>Thread-68::DEBUG::2014-06-23 12:17:35,066::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d4274bab-7607-4239-9618-2f1ea702508c': < ResourceRef 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', isValid: 'True' obj: 'None'>}
>Thread-68::DEBUG::2014-06-23 12:17:35,066::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-68::DEBUG::2014-06-23 12:17:35,066::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c'
>Thread-68::DEBUG::2014-06-23 12:17:35,066::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' (0 active users)
>Thread-68::DEBUG::2014-06-23 12:17:35,066::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c' is free, finding out if anyone is waiting for it.
>Thread-68::DEBUG::2014-06-23 12:17:35,066::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d4274bab-7607-4239-9618-2f1ea702508c', Clearing records.
>Thread-68::DEBUG::2014-06-23 12:17:35,066::task::990::TaskManager.Task::(_decref) Task=`5d751b25-fb70-4760-b1d3-6e457df1e90a`::ref 0 aborting False
>Thread-33::DEBUG::2014-06-23 12:17:35,230::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd3/cfd4f121-48d7-45b9-ab47-f57464b377f1/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-33::DEBUG::2014-06-23 12:17:35,240::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n334 bytes (334 B) copied, 0.000212466 s, 1.6 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-23 12:17:35,242::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/_storage_sd2/26ac6b95-0f85-4453-b46b-dc94074490af/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-23 12:17:35,247::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n343 bytes (343 B) copied, 0.000204298 s, 1.7 MB/s\n'; <rc> = 0
>MainThread::DEBUG::2014-06-23 12:17:38,979::vdsm::55::vds::(sigtermHandler) Received signal 15
>MainThread::INFO::2014-06-23 12:17:39,020::vmChannels::183::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-06-23 12:17:39,020::momIF::84::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-06-23 12:17:39,021::task::595::TaskManager.Task::(_updateState) Task=`f753a9d9-ca34-4e0f-9310-8000b53e2177`::moving from state init -> state preparing
>MainThread::INFO::2014-06-23 12:17:39,021::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2014-06-23 12:17:39,022::storageServer::698::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>VM Channels Listener::INFO::2014-06-23 12:17:39,165::vmChannels::178::vds::(run) VM channels listener thread has ended.
>MainThread::INFO::2014-06-23 12:17:39,343::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::INFO::2014-06-23 12:17:39,343::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring 26ac6b95-0f85-4453-b46b-dc94074490af
>Thread-20::DEBUG::2014-06-23 12:17:39,343::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 26ac6b95-0f85-4453-b46b-dc94074490af
>Thread-20::DEBUG::2014-06-23 12:17:39,343::clusterlock::355::LocalLock::(releaseHostId) Host id for domain 26ac6b95-0f85-4453-b46b-dc94074490af released successfully (id: 1)
>MainThread::INFO::2014-06-23 12:17:39,343::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-108::DEBUG::2014-06-23 12:17:39,344::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 65e38dfb-5d35-41d9-835c-1483386b4077
>Thread-108::DEBUG::2014-06-23 12:17:39,344::clusterlock::355::LocalLock::(releaseHostId) Host id for domain 65e38dfb-5d35-41d9-835c-1483386b4077 released successfully (id: 1)
>MainThread::INFO::2014-06-23 12:17:39,344::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring cfd4f121-48d7-45b9-ab47-f57464b377f1
>Thread-33::DEBUG::2014-06-23 12:17:39,344::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for cfd4f121-48d7-45b9-ab47-f57464b377f1
>Thread-33::DEBUG::2014-06-23 12:17:39,344::clusterlock::355::LocalLock::(releaseHostId) Host id for domain cfd4f121-48d7-45b9-ab47-f57464b377f1 released successfully (id: 1)
>MainThread::INFO::2014-06-23 12:17:39,344::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring b071beb4-4aed-4eed-9d4c-98b424976dc6
>Thread-25::DEBUG::2014-06-23 12:17:39,344::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for b071beb4-4aed-4eed-9d4c-98b424976dc6
>Thread-25::ERROR::2014-06-23 12:17:39,344::clusterlock::349::LocalLock::(releaseHostId) Cannot release host id when lock is acquired
>Thread-25::DEBUG::2014-06-23 12:17:39,347::domainMonitor::184::Storage.DomainMonitorThread::(_monitorLoop) Unable to release the host id 1 for domain b071beb4-4aed-4eed-9d4c-98b424976dc6
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/domainMonitor.py", line 181, in _monitorLoop
>    self.domain.releaseHostId(self.hostId, unused=True)
>  File "/usr/share/vdsm/storage/sd.py", line 461, in releaseHostId
>    self._clusterLock.releaseHostId(hostId, async, unused)
>  File "/usr/share/vdsm/storage/clusterlock.py", line 350, in releaseHostId
>    raise se.ReleaseHostIdFailure(self._sdUUID)
>ReleaseHostIdFailure: Cannot release host id: ('b071beb4-4aed-4eed-9d4c-98b424976dc6',)
>MainThread::INFO::2014-06-23 12:17:39,348::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring 9ab3ca6f-c18b-4635-a004-670ecc93431b
>Thread-21::DEBUG::2014-06-23 12:17:39,348::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for 9ab3ca6f-c18b-4635-a004-670ecc93431b
>Thread-21::DEBUG::2014-06-23 12:17:39,348::clusterlock::355::LocalLock::(releaseHostId) Host id for domain 9ab3ca6f-c18b-4635-a004-670ecc93431b released successfully (id: 1)
>MainThread::DEBUG::2014-06-23 12:17:39,348::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-06-23 12:17:39,348::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-06-23 12:17:39,348::task::1185::TaskManager.Task::(prepare) Task=`f753a9d9-ca34-4e0f-9310-8000b53e2177`::finished: None
>MainThread::DEBUG::2014-06-23 12:17:39,348::task::595::TaskManager.Task::(_updateState) Task=`f753a9d9-ca34-4e0f-9310-8000b53e2177`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-06-23 12:17:39,348::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-06-23 12:17:39,349::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-06-23 12:17:39,349::task::990::TaskManager.Task::(_decref) Task=`f753a9d9-ca34-4e0f-9310-8000b53e2177`::ref 0 aborting False
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::125::vds::(run) VDSM main thread ended. Waiting for 18 other threads...
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <_MainThread(MainThread, started 140277548627712)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <Thread(libvirtEventLoop, started daemon 140277416847104)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-2, started daemon 140277322872576)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140275913586432)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-6, started daemon 140277280913152)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-3, started daemon 140277312382720)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-5, started daemon 140277291403008)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(d7c6596f-41ce-4415-a510-73145e517262, started daemon 140277406357248)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <HostMonitor(HostMonitor, started daemon 140276372858624)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-8, started daemon 140276853110528)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-10, started daemon 140276832130816)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <Thread(Thread-13, started daemon 140275903096576)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <WorkerThread(Thread-4, started daemon 140277301892864)>
>MainThread::INFO::2014-06-23 12:17:39,349::vdsm::129::vds::(run) <GuestManager(GuestManager, started daemon 140276328630016)>
>MainThread::INFO::2014-06-23 12:17:39,349::momIF::84::MOM::(stop) Shutting down MOM
>MainThread::INFO::2014-06-23 12:17:39,350::vdsm::129::vds::(run) <MomThread(MOM, started 140276383348480)>
>MainThread::INFO::2014-06-23 12:17:39,350::vdsm::129::vds::(run) <Thread(Thread-68, started daemon 140276811151104)>
>MainThread::INFO::2014-06-23 12:17:39,350::vdsm::129::vds::(run) <WorkerThread(Thread-7, started daemon 140277270423296)>
>MainThread::INFO::2014-06-23 12:17:39,350::vdsm::129::vds::(run) <WorkerThread(Thread-9, started daemon 140276842620672)>
>MainThread::INFO::2014-06-23 12:17:39,350::vdsm::129::vds::(run) <Thread(Thread-69, started daemon 140275645150976)>
>MainThread::INFO::2014-06-23 12:19:04,674::vdsm::119::vds::(run) (PID: 3578) I am the actual vdsm 4.14.6-0.el6 dhcp-2-166.tlv.redhat.com (2.6.32-431.el6.x86_64)
>MainThread::DEBUG::2014-06-23 12:19:04,674::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-06-23 12:19:04,675::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::WARNING::2014-06-23 12:19:04,676::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-06-23 12:19:05,026::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-06-23 12:19:05,035::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-06-23 12:19:05,035::hsm::423::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-06-23 12:19:05,134::hsm::423::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-06-23 12:19:05,134::hsm::447::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-06-23 12:19:05,136::hsm::479::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-06-23 12:19:05,136::hsm::480::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/10.35.16.25:_volumes_smamit_frontend_ishaby_sd3', '/rhev/data-center/mnt/10.35.16.25:_volumes_smamit_frontend_ishaby_sd4']
>MainThread::DEBUG::2014-06-23 12:19:05,136::hsm::482::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-06-23 12:19:05,138::hsm::525::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-06-23 12:19:05,138::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-06-23 12:19:05,139::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-06-23 12:19:05,139::misc::764::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-06-23 12:19:05,153::misc::762::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-06-23 12:19:05,155::misc::764::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-06-23 12:19:05,155::iscsi::393::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-06-23 12:19:05,155::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>MainThread::DEBUG::2014-06-23 12:19:05,170::task::595::TaskManager.Task::(_updateState) Task=`21125a6e-ae9b-46ff-97f0-7e68dfbbedc9`::moving from state init -> state preparing
>MainThread::INFO::2014-06-23 12:19:05,170::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1afdb48>>)
>MainThread::INFO::2014-06-23 12:19:05,170::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-06-23 12:19:05,170::task::1185::TaskManager.Task::(prepare) Task=`21125a6e-ae9b-46ff-97f0-7e68dfbbedc9`::finished: None
>MainThread::DEBUG::2014-06-23 12:19:05,170::task::595::TaskManager.Task::(_updateState) Task=`21125a6e-ae9b-46ff-97f0-7e68dfbbedc9`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-06-23 12:19:05,170::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-06-23 12:19:05,170::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-06-23 12:19:05,170::task::990::TaskManager.Task::(_decref) Task=`21125a6e-ae9b-46ff-97f0-7e68dfbbedc9`::ref 0 aborting False
>MainThread::INFO::2014-06-23 12:19:05,176::momIF::47::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-06-23 12:19:05,177::vmChannels::187::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-06-23 12:19:05,179::vmChannels::170::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-06-23 12:19:05,188::libvirtconnection::145::root::(get) trying to connect libvirt
>storageRefresh::DEBUG::2014-06-23 12:19:05,188::misc::772::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-06-23 12:19:05,190::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>MainThread::WARNING::2014-06-23 12:19:05,194::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
>Thread-13::DEBUG::2014-06-23 12:19:05,417::BindingXMLRPC::1067::vds::(wrapper) client [10.35.0.123]::call getCapabilities with () {} flowID [63ca1e8]
>Thread-13::DEBUG::2014-06-23 12:19:05,417::BindingXMLRPC::1074::vds::(wrapper) return getCapabilities with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>Thread-14::DEBUG::2014-06-23 12:19:05,427::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-14::DEBUG::2014-06-23 12:19:05,428::task::595::TaskManager.Task::(_updateState) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::moving from state init -> state preparing
>Thread-14::INFO::2014-06-23 12:19:05,428::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='d4274bab-7607-4239-9618-2f1ea702508c', options=None)
>Thread-14::ERROR::2014-06-23 12:19:05,428::task::866::TaskManager.Task::(_setError) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 873, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 618, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 324, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('d4274bab-7607-4239-9618-2f1ea702508c',)
>Thread-14::DEBUG::2014-06-23 12:19:05,430::task::885::TaskManager.Task::(_run) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::Task._run: fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4 ('d4274bab-7607-4239-9618-2f1ea702508c',) {} failed - stopping task
>Thread-14::DEBUG::2014-06-23 12:19:05,430::task::1211::TaskManager.Task::(stop) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::stopping in state preparing (force False)
>Thread-14::DEBUG::2014-06-23 12:19:05,430::task::990::TaskManager.Task::(_decref) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::ref 1 aborting True
>Thread-14::INFO::2014-06-23 12:19:05,430::task::1168::TaskManager.Task::(prepare) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-14::DEBUG::2014-06-23 12:19:05,431::task::1173::TaskManager.Task::(prepare) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-14::DEBUG::2014-06-23 12:19:05,432::task::990::TaskManager.Task::(_decref) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::ref 0 aborting True
>Thread-14::DEBUG::2014-06-23 12:19:05,433::task::925::TaskManager.Task::(_doAbort) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::Task._doAbort: force False
>Thread-14::DEBUG::2014-06-23 12:19:05,433::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-14::DEBUG::2014-06-23 12:19:05,433::task::595::TaskManager.Task::(_updateState) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::moving from state preparing -> state aborting
>Thread-14::DEBUG::2014-06-23 12:19:05,433::task::550::TaskManager.Task::(__state_aborting) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::_aborting: recover policy none
>Thread-14::DEBUG::2014-06-23 12:19:05,433::task::595::TaskManager.Task::(_updateState) Task=`fd8cee81-f857-4c1b-9f17-4ce1a6ba92c4`::moving from state aborting -> state failed
>Thread-14::DEBUG::2014-06-23 12:19:05,433::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-14::DEBUG::2014-06-23 12:19:05,434::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-14::ERROR::2014-06-23 12:19:05,434::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('d4274bab-7607-4239-9618-2f1ea702508c',)", 'code': 309}}
>Thread-14::DEBUG::2014-06-23 12:19:05,479::BindingXMLRPC::251::vds::(wrapper) client [10.35.0.123]
>Thread-14::DEBUG::2014-06-23 12:19:05,480::task::595::TaskManager.Task::(_updateState) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::moving from state init -> state preparing
>Thread-14::INFO::2014-06-23 12:19:05,480::logUtils::44::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-14::ERROR::2014-06-23 12:19:05,480::task::866::TaskManager.Task::(_setError) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 873, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 2113, in getAllTasksStatuses
>    raise se.SpmStatusError()
>SpmStatusError: Not SPM: ()
>Thread-14::DEBUG::2014-06-23 12:19:05,480::task::885::TaskManager.Task::(_run) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::Task._run: 91dbe1d5-5dc6-48ca-b30c-154cf7e23c08 () {} failed - stopping task
>Thread-14::DEBUG::2014-06-23 12:19:05,481::task::1211::TaskManager.Task::(stop) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::stopping in state preparing (force False)
>Thread-14::DEBUG::2014-06-23 12:19:05,481::task::990::TaskManager.Task::(_decref) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::ref 1 aborting True
>Thread-14::INFO::2014-06-23 12:19:05,481::task::1168::TaskManager.Task::(prepare) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::aborting: Task is aborted: 'Not SPM' - code 654
>Thread-14::DEBUG::2014-06-23 12:19:05,481::task::1173::TaskManager.Task::(prepare) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::Prepare: aborted: Not SPM
>Thread-14::DEBUG::2014-06-23 12:19:05,481::task::990::TaskManager.Task::(_decref) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::ref 0 aborting True
>Thread-14::DEBUG::2014-06-23 12:19:05,481::task::925::TaskManager.Task::(_doAbort) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::Task._doAbort: force False
>Thread-14::DEBUG::2014-06-23 12:19:05,481::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-14::DEBUG::2014-06-23 12:19:05,482::task::595::TaskManager.Task::(_updateState) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::moving from state preparing -> state aborting
>Thread-14::DEBUG::2014-06-23 12:19:05,482::task::550::TaskManager.Task::(__state_aborting) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::_aborting: recover policy none
>Thread-14::DEBUG::2014-06-23 12:19:05,482::task::595::TaskManager.Task::(_updateState) Task=`91dbe1d5-5dc6-48ca-b30c-154cf7e23c08`::moving from state aborting -> state failed
>Thread-14::DEBUG::2014-06-23 12:19:05,482::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-14::DEBUG::2014-06-23 12:19:05,482::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-14::ERROR::2014-06-23 12:19:05,482::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}}
>storageRefresh::DEBUG::2014-06-23 12:19:05,655::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-06-23 12:19:05,656::lvm::496::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,656::lvm::498::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,656::lvm::507::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,657::lvm::509::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,657::lvm::527::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,657::lvm::529::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,657::misc::772::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-06-23 12:19:05,658::lvm::324::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-06-23 12:19:05,664::lvm::295::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600144f09dbd050000004ddbe77f0011|/dev/mapper/3600144f09dbd050000004ddbe78f0012|/dev/mapper/3600144f09dbd050000004ddbe7a00013|/dev/mapper/3600144f09dbd050000004ddbe7ad0014|/dev/mapper/3600144f09dbd050000004ddbe7bb0015|/dev/mapper/3600144f09dbd050000004ddbe8770016|/dev/mapper/3600144f09dbd050000004ddbe8830017|/dev/mapper/3600144f09dbd050000004ddbe8910018|/dev/mapper/3600144f09dbd050000004ddbe89f0019|/dev/mapper/3600144f09dbd050000004ddbe8ad001a|/dev/mapper/3600144f09dbd050000004ddbeaa50020|/dev/mapper/3600144f09dbd050000004ddbeab50021|/dev/mapper/3600144f09dbd050000004ddbeac50022|/dev/mapper/3600144f09dbd050000004ddbead60023|/dev/mapper/3600144f09dbd050000004ddbeae90024|/dev/mapper/3600144f09dbd050000004e1994980004|/dev/mapper/3600144f09dbd050000004e1994c60005|/dev/mapper/3600144f09dbd050000004e1994f10006|/dev/mapper/3600144f09dbd050000004e19953d0007|/dev/mapper/3600144f09dbd050000004e19956b0008|/dev/mapper/3600144f09dbd05000000501651410004|/dev/mapper/3600144f09dbd05000000501654860005|/dev/mapper/3600144f09dbd05000000501654960006|/dev/mapper/3600144f09dbd050000005016549f0007|/dev/mapper/3600144f09dbd05000000501654ac0008|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)

Actions: View

Attachments on bug 1112171: 911366