Attachment 680207 Details for Bug 869956 – vdsm log

vdsm log

vdsm.log (text/plain), 25.65 KB, created by Mike Burns on 2013-01-17 13:44:41 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Mike Burns

Created: 2013-01-17 13:44:41 UTC

Size: 25.65 KB

patch

obsolete

>Dummy-236::DEBUG::2013-01-17 13:38:51,218::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0566919 s, 18.1 MB/s\n'; <rc> = 0
>Thread-585::DEBUG::2013-01-17 13:38:52,720::BindingXMLRPC::161::vds::(wrapper) [172.31.12.191]
>Thread-585::DEBUG::2013-01-17 13:38:52,776::task::568::TaskManager.Task::(_updateState) Task=`6b27c505-ddba-483a-a8ed-59e93dfff84f`::moving from state init -> state preparing
>Thread-585::INFO::2013-01-17 13:38:52,777::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'beelzebub.mburnsfire.net:/export/engine_iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd3b44aef-12ac-4672-b648-78a74dfb0ac7', 'port': ''}], options=None)
>Thread-585::INFO::2013-01-17 13:38:52,778::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': 'd3b44aef-12ac-4672-b648-78a74dfb0ac7'}]}
>Thread-585::DEBUG::2013-01-17 13:38:52,778::task::1151::TaskManager.Task::(prepare) Task=`6b27c505-ddba-483a-a8ed-59e93dfff84f`::finished: {'statuslist': [{'status': 0, 'id': 'd3b44aef-12ac-4672-b648-78a74dfb0ac7'}]}
>Thread-585::DEBUG::2013-01-17 13:38:52,778::task::568::TaskManager.Task::(_updateState) Task=`6b27c505-ddba-483a-a8ed-59e93dfff84f`::moving from state preparing -> state finished
>Thread-585::DEBUG::2013-01-17 13:38:52,779::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-585::DEBUG::2013-01-17 13:38:52,779::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-585::DEBUG::2013-01-17 13:38:52,779::task::957::TaskManager.Task::(_decref) Task=`6b27c505-ddba-483a-a8ed-59e93dfff84f`::ref 0 aborting False
>Thread-586::DEBUG::2013-01-17 13:38:52,810::BindingXMLRPC::161::vds::(wrapper) [172.31.12.191]
>Thread-586::DEBUG::2013-01-17 13:38:52,811::task::568::TaskManager.Task::(_updateState) Task=`0495e671-fe4b-4f9d-a99e-f3d063d53c4e`::moving from state init -> state preparing
>Thread-586::INFO::2013-01-17 13:38:52,811::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'beelzebub.mburnsfire.net:/export/engine_iso', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'd3b44aef-12ac-4672-b648-78a74dfb0ac7', 'port': ''}], options=None)
>Thread-586::DEBUG::2013-01-17 13:38:52,822::misc::83::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 beelzebub.mburnsfire.net:/export/engine_iso /rhev/data-center/mnt/beelzebub.mburnsfire.net:_export_engine__iso' (cwd None)
>Thread-586::ERROR::2013-01-17 13:38:52,924::hsm::2207::Storage.HSM::(connectStorageServer) Could not connect to storageServer
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/hsm.py", line 2203, in connectStorageServer
>  File "/usr/share/vdsm/storage/storageServer.py", line 302, in connect
>  File "/usr/share/vdsm/storage/storageServer.py", line 208, in connect
>  File "/usr/share/vdsm/storage/mount.py", line 236, in getRecord
>OSError: [Errno 2] Mount of `beelzebub.mburnsfire.net:/export/engine_iso` at `/rhev/data-center/mnt/beelzebub.mburnsfire.net:_export_engine__iso` does not exist
>Thread-586::INFO::2013-01-17 13:38:52,927::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 100, 'id': 'd3b44aef-12ac-4672-b648-78a74dfb0ac7'}]}
>Thread-586::DEBUG::2013-01-17 13:38:52,927::task::1151::TaskManager.Task::(prepare) Task=`0495e671-fe4b-4f9d-a99e-f3d063d53c4e`::finished: {'statuslist': [{'status': 100, 'id': 'd3b44aef-12ac-4672-b648-78a74dfb0ac7'}]}
>Thread-586::DEBUG::2013-01-17 13:38:52,928::task::568::TaskManager.Task::(_updateState) Task=`0495e671-fe4b-4f9d-a99e-f3d063d53c4e`::moving from state preparing -> state finished
>Thread-586::DEBUG::2013-01-17 13:38:52,928::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-586::DEBUG::2013-01-17 13:38:52,928::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-586::DEBUG::2013-01-17 13:38:52,928::task::957::TaskManager.Task::(_decref) Task=`0495e671-fe4b-4f9d-a99e-f3d063d53c4e`::ref 0 aborting False
>Thread-587::DEBUG::2013-01-17 13:38:52,971::BindingXMLRPC::161::vds::(wrapper) [172.31.12.191]
>Thread-587::DEBUG::2013-01-17 13:38:52,972::task::568::TaskManager.Task::(_updateState) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::moving from state init -> state preparing
>Thread-587::INFO::2013-01-17 13:38:52,972::logUtils::37::dispatcher::(wrapper) Run and protect: attachStorageDomain(sdUUID='42586010-e21c-431b-8ce9-67f3137797be', spUUID='7f88fb78-f33d-4092-854e-913da8763e1b', options=None)
>Thread-587::DEBUG::2013-01-17 13:38:52,972::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.7f88fb78-f33d-4092-854e-913da8763e1b`ReqID=`f898e6d2-cd9a-4b16-9ed5-759e9966e4e7`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
>Thread-587::DEBUG::2013-01-17 13:38:52,973::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' for lock type 'exclusive'
>Thread-587::DEBUG::2013-01-17 13:38:52,973::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' is free. Now locking as 'exclusive' (1 active user)
>Thread-587::DEBUG::2013-01-17 13:38:52,973::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.7f88fb78-f33d-4092-854e-913da8763e1b`ReqID=`f898e6d2-cd9a-4b16-9ed5-759e9966e4e7`::Granted request
>Thread-587::DEBUG::2013-01-17 13:38:52,974::task::794::TaskManager.Task::(resourceAcquired) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::_resourcesAcquired: Storage.7f88fb78-f33d-4092-854e-913da8763e1b (exclusive)
>Thread-587::DEBUG::2013-01-17 13:38:52,974::task::957::TaskManager.Task::(_decref) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::ref 1 aborting False
>Thread-587::DEBUG::2013-01-17 13:38:52,974::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.42586010-e21c-431b-8ce9-67f3137797be`ReqID=`294d41f5-456a-4a30-9223-17ae14549de1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
>Thread-587::DEBUG::2013-01-17 13:38:52,974::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.42586010-e21c-431b-8ce9-67f3137797be' for lock type 'exclusive'
>Thread-587::DEBUG::2013-01-17 13:38:52,975::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.42586010-e21c-431b-8ce9-67f3137797be' is free. Now locking as 'exclusive' (1 active user)
>Thread-587::DEBUG::2013-01-17 13:38:52,975::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.42586010-e21c-431b-8ce9-67f3137797be`ReqID=`294d41f5-456a-4a30-9223-17ae14549de1`::Granted request
>Thread-587::DEBUG::2013-01-17 13:38:52,975::task::794::TaskManager.Task::(resourceAcquired) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::_resourcesAcquired: Storage.42586010-e21c-431b-8ce9-67f3137797be (exclusive)
>Thread-587::DEBUG::2013-01-17 13:38:52,975::task::957::TaskManager.Task::(_decref) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::ref 1 aborting False
>Thread-587::INFO::2013-01-17 13:38:52,976::sp::918::Storage.StoragePool::(attachSD) sdUUID=42586010-e21c-431b-8ce9-67f3137797be spUUID=7f88fb78-f33d-4092-854e-913da8763e1b
>Thread-587::DEBUG::2013-01-17 13:38:52,976::misc::1025::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-587::DEBUG::2013-01-17 13:38:52,976::misc::1027::SamplingMethod::(__call__) Got in to sampling method
>Thread-587::DEBUG::2013-01-17 13:38:52,977::misc::1025::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-587::DEBUG::2013-01-17 13:38:52,977::misc::1027::SamplingMethod::(__call__) Got in to sampling method
>Thread-587::DEBUG::2013-01-17 13:38:52,977::misc::83::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-587::DEBUG::2013-01-17 13:38:53,013::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
>Thread-587::DEBUG::2013-01-17 13:38:53,015::misc::1035::SamplingMethod::(__call__) Returning last result
>MainProcess|Thread-587::DEBUG::2013-01-17 13:38:53,020::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
>MainProcess|Thread-587::DEBUG::2013-01-17 13:38:53,022::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
>MainProcess|Thread-587::DEBUG::2013-01-17 13:38:53,027::misc::83::Storage.Misc.excCmd::(<lambda>) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
>MainProcess|Thread-587::DEBUG::2013-01-17 13:38:53,030::iscsi::388::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
>Dummy-236::DEBUG::2013-01-17 13:38:53,230::misc::83::Storage.Misc.excCmd::(<lambda>) 'dd if=/rhev/data-center/7f88fb78-f33d-4092-854e-913da8763e1b/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-236::DEBUG::2013-01-17 13:38:53,329::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0566088 s, 18.1 MB/s\n'; <rc> = 0
>Thread-587::DEBUG::2013-01-17 13:38:55,034::misc::83::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-587::DEBUG::2013-01-17 13:38:55,075::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
>Thread-587::DEBUG::2013-01-17 13:38:55,078::lvm::477::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,078::lvm::479::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,079::lvm::488::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,079::lvm::490::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,079::lvm::508::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,079::lvm::510::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,080::misc::1035::SamplingMethod::(__call__) Returning last result
>Thread-587::DEBUG::2013-01-17 13:38:55,080::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-587::DEBUG::2013-01-17 13:38:55,082::misc::83::Storage.Misc.excCmd::(<lambda>) '/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 filter = [ \\"a%1IET_00010001|1IET_00010002%\\", \\"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 42586010-e21c-431b-8ce9-67f3137797be' (cwd None)
>Dummy-236::DEBUG::2013-01-17 13:38:55,343::misc::83::Storage.Misc.excCmd::(<lambda>) 'dd if=/rhev/data-center/7f88fb78-f33d-4092-854e-913da8763e1b/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Thread-587::DEBUG::2013-01-17 13:38:55,446::misc::83::Storage.Misc.excCmd::(<lambda>) FAILED: <err> = '  Volume group "42586010-e21c-431b-8ce9-67f3137797be" not found\n'; <rc> = 5
>Thread-587::WARNING::2013-01-17 13:38:55,448::lvm::373::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "42586010-e21c-431b-8ce9-67f3137797be" not found']
>Thread-587::DEBUG::2013-01-17 13:38:55,448::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-587::ERROR::2013-01-17 13:38:55,449::task::833::TaskManager.Task::(_setError) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 840, in _run
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>  File "/usr/share/vdsm/storage/hsm.py", line 1076, in attachStorageDomain
>  File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper
>  File "/usr/share/vdsm/storage/sp.py", line 927, in attachSD
>  File "/usr/share/vdsm/storage/sdc.py", line 97, in produce
>  File "/usr/share/vdsm/storage/sdc.py", line 52, in getRealDomain
>  File "/usr/share/vdsm/storage/sdc.py", line 121, in _realProduce
>  File "/usr/share/vdsm/storage/sdc.py", line 152, in _findDomain
>StorageDomainDoesNotExist: Storage domain does not exist: ('42586010-e21c-431b-8ce9-67f3137797be',)
>Thread-587::DEBUG::2013-01-17 13:38:55,450::task::852::TaskManager.Task::(_run) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::Task._run: 1040cf69-d208-4d6a-ad8e-6d29f09b438e ('42586010-e21c-431b-8ce9-67f3137797be', '7f88fb78-f33d-4092-854e-913da8763e1b') {} failed - stopping task
>Thread-587::DEBUG::2013-01-17 13:38:55,450::task::1177::TaskManager.Task::(stop) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::stopping in state preparing (force False)
>Thread-587::DEBUG::2013-01-17 13:38:55,450::task::957::TaskManager.Task::(_decref) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::ref 1 aborting True
>Thread-587::INFO::2013-01-17 13:38:55,450::task::1134::TaskManager.Task::(prepare) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::aborting: Task is aborted: 'Storage domain does not exist' - code 358
>Thread-587::DEBUG::2013-01-17 13:38:55,451::task::1139::TaskManager.Task::(prepare) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::Prepare: aborted: Storage domain does not exist
>Thread-587::DEBUG::2013-01-17 13:38:55,451::task::957::TaskManager.Task::(_decref) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::ref 0 aborting True
>Thread-587::DEBUG::2013-01-17 13:38:55,451::task::892::TaskManager.Task::(_doAbort) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::Task._doAbort: force False
>Thread-587::DEBUG::2013-01-17 13:38:55,451::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-587::DEBUG::2013-01-17 13:38:55,451::task::568::TaskManager.Task::(_updateState) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::moving from state preparing -> state aborting
>Thread-587::DEBUG::2013-01-17 13:38:55,452::task::523::TaskManager.Task::(__state_aborting) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::_aborting: recover policy none
>Thread-587::DEBUG::2013-01-17 13:38:55,452::task::568::TaskManager.Task::(_updateState) Task=`1040cf69-d208-4d6a-ad8e-6d29f09b438e`::moving from state aborting -> state failed
>Thread-587::DEBUG::2013-01-17 13:38:55,452::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.42586010-e21c-431b-8ce9-67f3137797be': < ResourceRef 'Storage.42586010-e21c-431b-8ce9-67f3137797be', isValid: 'True' obj: 'None'>, 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b': < ResourceRef 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b', isValid: 'True' obj: 'None'>}
>Thread-587::DEBUG::2013-01-17 13:38:55,452::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-587::DEBUG::2013-01-17 13:38:55,452::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.42586010-e21c-431b-8ce9-67f3137797be'
>Thread-587::DEBUG::2013-01-17 13:38:55,453::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.42586010-e21c-431b-8ce9-67f3137797be' (0 active users)
>Thread-587::DEBUG::2013-01-17 13:38:55,453::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.42586010-e21c-431b-8ce9-67f3137797be' is free, finding out if anyone is waiting for it.
>Thread-587::DEBUG::2013-01-17 13:38:55,453::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.42586010-e21c-431b-8ce9-67f3137797be', Clearing records.
>Thread-587::DEBUG::2013-01-17 13:38:55,453::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b'
>Thread-587::DEBUG::2013-01-17 13:38:55,454::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' (0 active users)
>Thread-587::DEBUG::2013-01-17 13:38:55,454::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' is free, finding out if anyone is waiting for it.
>Thread-587::DEBUG::2013-01-17 13:38:55,457::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b', Clearing records.
>Thread-587::ERROR::2013-01-17 13:38:55,457::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Storage domain does not exist: ('42586010-e21c-431b-8ce9-67f3137797be',)", 'code': 358}}
>Thread-589::DEBUG::2013-01-17 13:38:55,486::BindingXMLRPC::161::vds::(wrapper) [172.31.12.191]
>Thread-589::DEBUG::2013-01-17 13:38:55,487::task::568::TaskManager.Task::(_updateState) Task=`9955aceb-c465-4579-842f-dadb8c003f39`::moving from state init -> state preparing
>Thread-589::INFO::2013-01-17 13:38:55,487::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='7f88fb78-f33d-4092-854e-913da8763e1b', options=None)
>Thread-589::INFO::2013-01-17 13:38:55,487::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-589::DEBUG::2013-01-17 13:38:55,487::task::1151::TaskManager.Task::(prepare) Task=`9955aceb-c465-4579-842f-dadb8c003f39`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-589::DEBUG::2013-01-17 13:38:55,488::task::568::TaskManager.Task::(_updateState) Task=`9955aceb-c465-4579-842f-dadb8c003f39`::moving from state preparing -> state finished
>Thread-589::DEBUG::2013-01-17 13:38:55,488::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-589::DEBUG::2013-01-17 13:38:55,488::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-589::DEBUG::2013-01-17 13:38:55,492::task::957::TaskManager.Task::(_decref) Task=`9955aceb-c465-4579-842f-dadb8c003f39`::ref 0 aborting False
>Dummy-236::DEBUG::2013-01-17 13:38:55,503::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0648303 s, 15.8 MB/s\n'; <rc> = 0
>Thread-590::DEBUG::2013-01-17 13:38:55,521::BindingXMLRPC::161::vds::(wrapper) [172.31.12.191]
>Thread-590::DEBUG::2013-01-17 13:38:55,521::task::568::TaskManager.Task::(_updateState) Task=`d72ab033-a9fa-46a4-8813-d97d4ea07f6b`::moving from state init -> state preparing
>Thread-590::INFO::2013-01-17 13:38:55,522::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='7f88fb78-f33d-4092-854e-913da8763e1b', options=None)
>Thread-590::DEBUG::2013-01-17 13:38:55,522::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.7f88fb78-f33d-4092-854e-913da8763e1b`ReqID=`fa33d3fc-5e54-4016-bbd8-32a31c174b6a`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '174' at '__init__'
>Thread-590::DEBUG::2013-01-17 13:38:55,522::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' for lock type 'shared'
>Thread-590::DEBUG::2013-01-17 13:38:55,522::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' is free. Now locking as 'shared' (1 active user)
>Thread-590::DEBUG::2013-01-17 13:38:55,522::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.7f88fb78-f33d-4092-854e-913da8763e1b`ReqID=`fa33d3fc-5e54-4016-bbd8-32a31c174b6a`::Granted request
>Thread-590::DEBUG::2013-01-17 13:38:55,523::task::794::TaskManager.Task::(resourceAcquired) Task=`d72ab033-a9fa-46a4-8813-d97d4ea07f6b`::_resourcesAcquired: Storage.7f88fb78-f33d-4092-854e-913da8763e1b (shared)
>Thread-590::DEBUG::2013-01-17 13:38:55,523::task::957::TaskManager.Task::(_decref) Task=`d72ab033-a9fa-46a4-8813-d97d4ea07f6b`::ref 1 aborting False
>Thread-590::DEBUG::2013-01-17 13:38:55,523::lvm::368::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-590::DEBUG::2013-01-17 13:38:55,524::misc::83::Storage.Misc.excCmd::(<lambda>) '/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 filter = [ \\"a%1IET_00010001|1IET_00010002%\\", \\"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 552028c9-b84a-4018-8b21-8af0f403ba71' (cwd None)
>Thread-590::DEBUG::2013-01-17 13:38:55,803::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0
>Thread-590::DEBUG::2013-01-17 13:38:55,804::lvm::397::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-590::INFO::2013-01-17 13:38:55,805::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '552028c9-b84a-4018-8b21-8af0f403ba71', 'name': 'test-iscsi', 'version': '3', 'domains': '552028c9-b84a-4018-8b21-8af0f403ba71:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {'552028c9-b84a-4018-8b21-8af0f403ba71': {'status': 'Active', 'diskfree': '48721035264', 'alerts': [], 'disktotal': '63619203072'}}}
>Thread-590::DEBUG::2013-01-17 13:38:55,805::task::1151::TaskManager.Task::(prepare) Task=`d72ab033-a9fa-46a4-8813-d97d4ea07f6b`::finished: {'info': {'spm_id': 1, 'master_uuid': '552028c9-b84a-4018-8b21-8af0f403ba71', 'name': 'test-iscsi', 'version': '3', 'domains': '552028c9-b84a-4018-8b21-8af0f403ba71:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {'552028c9-b84a-4018-8b21-8af0f403ba71': {'status': 'Active', 'diskfree': '48721035264', 'alerts': [], 'disktotal': '63619203072'}}}
>Thread-590::DEBUG::2013-01-17 13:38:55,805::task::568::TaskManager.Task::(_updateState) Task=`d72ab033-a9fa-46a4-8813-d97d4ea07f6b`::moving from state preparing -> state finished
>Thread-590::DEBUG::2013-01-17 13:38:55,805::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.7f88fb78-f33d-4092-854e-913da8763e1b': < ResourceRef 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b', isValid: 'True' obj: 'None'>}
>Thread-590::DEBUG::2013-01-17 13:38:55,805::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-590::DEBUG::2013-01-17 13:38:55,805::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b'
>Thread-590::DEBUG::2013-01-17 13:38:55,806::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' (0 active users)
>Thread-590::DEBUG::2013-01-17 13:38:55,806::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b' is free, finding out if anyone is waiting for it.
>Thread-590::DEBUG::2013-01-17 13:38:55,806::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.7f88fb78-f33d-4092-854e-913da8763e1b', Clearing records.
>Thread-590::DEBUG::2013-01-17 13:38:55,806::task::957::TaskManager.Task::(_decref) Task=`d72ab033-a9fa-46a4-8813-d97d4ea07f6b`::ref 0 aborting False
>Dummy-236::DEBUG::2013-01-17 13:38:57,518::misc::83::Storage.Misc.excCmd::(<lambda>) 'dd if=/rhev/data-center/7f88fb78-f33d-4092-854e-913da8763e1b/mastersd/dom_md/inbox iflag=direct,fullblock count=1 bs=1024000' (cwd None)
>Dummy-236::DEBUG::2013-01-17 13:38:57,604::misc::83::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0501314 s, 20.4 MB/s\n'; <rc> = 0
>Thread-592::DEBUG::2013-01-17 13:38:58,561::task::568::TaskManager.Task::(_updateState) Task=`45849a15-fda0-4b2e-a4bf-ce2de3419e7e`::moving from state init -> state preparing
>Thread-592::INFO::2013-01-17 13:38:58,561::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-592::INFO::2013-01-17 13:38:58,561::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'552028c9-b84a-4018-8b21-8af0f403ba71': {'delay': '0.0218119621277', 'lastCheck': '7.4', 'code': 0, 'valid': True}}
>Thread-592::DEBUG::2013-01-17 13:38:58,562::task::1151::TaskManager.Task::(prepare) Task=`45849a15-fda0-4b2e-a4bf-ce2de3419e7e`::finished: {'552028c9-b84a-4018-8b21-8af0f403ba71': {'delay': '0.0218119621277', 'lastCheck': '7.4', 'code': 0, 'valid': True}}
>Thread-592::DEBUG::2013-01-17 13:38:58,562::task::568::TaskManager.Task::(_updateState) Task=`45849a15-fda0-4b2e-a4bf-ce2de3419e7e`::moving from state preparing -> state finished
>Thread-592::DEBUG::2013-01-17 13:38:58,562::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-592::DEBUG::2013-01-17 13:38:58,562::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-592::DEBUG::2013-01-17 13:38:58,562::task::957::TaskManager.Task::(_decref) Task=`45849a15-fda0-4b2e-a4bf-ce2de3419e7e`::ref 0 aborting False
>

Actions: View

Attachments on bug 869956: 633227 | 633228 | 639763 | 639764 | 680207