Attachment 935464 Details for Bug 1139401 – vdsm log during failure

vdsm log during failure

vdsm.log (text/plain), 7.65 KB, created by Adam Litke on 2014-09-08 20:52:24 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Adam Litke

Created: 2014-09-08 20:52:24 UTC

Size: 7.65 KB

patch

obsolete

>Thread-17::DEBUG::2014-09-08 16:47:29,946::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_data/d5621b87-f2a4-4e1b-8155-1e51ae144295/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-17::DEBUG::2014-09-08 16:47:29,952::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n504 bytes (504 B) copied, 0.00116705 s, 432 kB/s\n'; <rc> = 0
>Thread-16::DEBUG::2014-09-08 16:47:30,009::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-16::DEBUG::2014-09-08 16:47:30,014::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1086 bytes (1.1 kB) copied, 0.00130036 s, 835 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-09-08 16:47:36,500::task::595::Storage.TaskManager.Task::(_updateState) Task=`67b30a66-9cf8-415a-b203-d6fb1d389cca`::moving from state init -> state preparing
>Thread-13::INFO::2014-09-08 16:47:36,500::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-09-08 16:47:36,500::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00130036', 'lastCheck': '6.5', 'valid': True}, 'd5621b87-f2a4-4e1b-8155-1e51ae144295': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00116705', 'lastCheck': '6.5', 'valid': True}}
>Thread-13::DEBUG::2014-09-08 16:47:36,500::task::1191::Storage.TaskManager.Task::(prepare) Task=`67b30a66-9cf8-415a-b203-d6fb1d389cca`::finished: {'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00130036', 'lastCheck': '6.5', 'valid': True}, 'd5621b87-f2a4-4e1b-8155-1e51ae144295': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00116705', 'lastCheck': '6.5', 'valid': True}}
>Thread-13::DEBUG::2014-09-08 16:47:36,500::task::595::Storage.TaskManager.Task::(_updateState) Task=`67b30a66-9cf8-415a-b203-d6fb1d389cca`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-09-08 16:47:36,500::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-09-08 16:47:36,501::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-09-08 16:47:36,501::task::993::Storage.TaskManager.Task::(_decref) Task=`67b30a66-9cf8-415a-b203-d6fb1d389cca`::ref 0 aborting False
>Thread-13::DEBUG::2014-09-08 16:47:39,535::BindingXMLRPC::318::vds::(wrapper) client [192.168.2.1] flowID [288c4913]
>Thread-13::DEBUG::2014-09-08 16:47:39,536::task::595::Storage.TaskManager.Task::(_updateState) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::moving from state init -> state preparing
>Thread-13::INFO::2014-09-08 16:47:39,536::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25a09b8a-177c-40af-865d-22436da5cc66', options=None)
>Thread-13::ERROR::2014-09-08 16:47:39,536::task::866::Storage.TaskManager.Task::(_setError) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::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 611, in getSpmStatus
>    status = self._getSpmStatusInfo(pool)
>  File "/usr/share/vdsm/storage/hsm.py", line 605, in _getSpmStatusInfo
>    (pool.spmRole,) + pool.getSpmStatus()))
>  File "/usr/share/vdsm/storage/sp.py", line 126, in getSpmStatus
>    return self._backend.getSpmStatus()
>  File "/usr/share/vdsm/storage/spbackends.py", line 416, in getSpmStatus
>    lVer, spmId = self.masterDomain.inquireClusterLock()
>  File "/usr/share/vdsm/storage/sd.py", line 515, in inquireClusterLock
>    return self._clusterLock.inquire()
>  File "/usr/share/vdsm/storage/clusterlock.py", line 149, in inquire
>    raise InquireNotSupportedError()
>InquireNotSupportedError
>Thread-13::DEBUG::2014-09-08 16:47:39,537::task::885::Storage.TaskManager.Task::(_run) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::Task._run: ed54e7ed-96b6-41c7-89e2-1a144c6a703d ('25a09b8a-177c-40af-865d-22436da5cc66',) {} failed - stopping task
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::1217::Storage.TaskManager.Task::(stop) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::stopping in state preparing (force False)
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::993::Storage.TaskManager.Task::(_decref) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::ref 1 aborting True
>Thread-13::INFO::2014-09-08 16:47:39,538::task::1171::Storage.TaskManager.Task::(prepare) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::aborting: Task is aborted: u'' - code 100
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::1176::Storage.TaskManager.Task::(prepare) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::Prepare: aborted: 
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::993::Storage.TaskManager.Task::(_decref) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::ref 0 aborting True
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::928::Storage.TaskManager.Task::(_doAbort) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::Task._doAbort: force False
>Thread-13::DEBUG::2014-09-08 16:47:39,538::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::595::Storage.TaskManager.Task::(_updateState) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::moving from state preparing -> state aborting
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::550::Storage.TaskManager.Task::(__state_aborting) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::_aborting: recover policy none
>Thread-13::DEBUG::2014-09-08 16:47:39,538::task::595::Storage.TaskManager.Task::(_updateState) Task=`ed54e7ed-96b6-41c7-89e2-1a144c6a703d`::moving from state aborting -> state failed
>Thread-13::DEBUG::2014-09-08 16:47:39,538::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-09-08 16:47:39,538::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::ERROR::2014-09-08 16:47:39,539::dispatcher::79::Storage.Dispatcher::(wrapper) 
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/dispatcher.py", line 71, in wrapper
>    result = ctask.prepare(func, *args, **kwargs)
>  File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
>    return m(self, *a, **kw)
>  File "/usr/share/vdsm/storage/task.py", line 1179, in prepare
>    raise self.error
>InquireNotSupportedError
>Thread-17::DEBUG::2014-09-08 16:47:39,956::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_data/d5621b87-f2a4-4e1b-8155-1e51ae144295/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-17::DEBUG::2014-09-08 16:47:39,963::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n505 bytes (505 B) copied, 0.00109707 s, 460 kB/s\n'; <rc> = 0
>Thread-16::DEBUG::2014-09-08 16:47:40,017::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
>Thread-16::DEBUG::2014-09-08 16:47:40,022::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n1086 bytes (1.1 kB) copied, 0.00114226 s, 951 kB/s\n'; <rc> = 0

Actions: View

Attachments on bug 1139401: 935464 | 935730 | 935878 | 935879 | 935880 | 935881 | 935882 | 935883