Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 911366 Details for
Bug 1112171
Inconsistent failures when attempting to create a local sd on a directory owned by root
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
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:
VDSM log file
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)
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1112171
: 911366