Attachment 640114 Details for Bug 874120 – vdsm.log

vdsm.log

vdsm.log (text/x-log), 17.64 KB, created by Valentin Bajrami on 2012-11-07 14:56:13 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Valentin Bajrami

Created: 2012-11-07 14:56:13 UTC

Size: 17.64 KB

patch

obsolete

>clientIFinit::INFO::2012-11-07 07:50:49,860::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:50:49,861::task::1172::TaskManager.Task::(prepare) Task=`8d84b004-3691-425c-9440-d4138ec5c479`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:50:49,861::task::588::TaskManager.Task::(_updateState) Task=`8d84b004-3691-425c-9440-d4138ec5c479`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:50:49,861::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:50:49,861::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:50:49,861::task::978::TaskManager.Task::(_decref) Task=`8d84b004-3691-425c-9440-d4138ec5c479`::ref 0 aborting False
>clientIFinit::DEBUG::2012-11-07 07:50:54,867::task::588::TaskManager.Task::(_updateState) Task=`73d8fcd0-58d0-4028-b8d9-2943fa09c87f`::moving from state init -> state preparing
>clientIFinit::INFO::2012-11-07 07:50:54,867::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>clientIFinit::INFO::2012-11-07 07:50:54,867::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:50:54,868::task::1172::TaskManager.Task::(prepare) Task=`73d8fcd0-58d0-4028-b8d9-2943fa09c87f`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:50:54,868::task::588::TaskManager.Task::(_updateState) Task=`73d8fcd0-58d0-4028-b8d9-2943fa09c87f`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:50:54,868::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:50:54,868::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:50:54,868::task::978::TaskManager.Task::(_decref) Task=`73d8fcd0-58d0-4028-b8d9-2943fa09c87f`::ref 0 aborting False
>Thread-377::DEBUG::2012-11-07 07:50:55,203::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-377::DEBUG::2012-11-07 07:50:55,204::task::588::TaskManager.Task::(_updateState) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::moving from state init -> state preparing
>Thread-377::INFO::2012-11-07 07:50:55,204::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c02503a4-274e-11e2-b33c-002590730631', options=None)
>Thread-377::ERROR::2012-11-07 07:50:55,204::task::853::TaskManager.Task::(_setError) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 528, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 265, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)
>Thread-377::DEBUG::2012-11-07 07:50:55,204::task::872::TaskManager.Task::(_run) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::Task._run: c2aad506-d09d-464c-acc7-6828f33b2013 ('c02503a4-274e-11e2-b33c-002590730631',) {} failed - stopping task
>Thread-377::DEBUG::2012-11-07 07:50:55,205::task::1199::TaskManager.Task::(stop) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::stopping in state preparing (force False)
>Thread-377::DEBUG::2012-11-07 07:50:55,205::task::978::TaskManager.Task::(_decref) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::ref 1 aborting True
>Thread-377::INFO::2012-11-07 07:50:55,205::task::1157::TaskManager.Task::(prepare) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-377::DEBUG::2012-11-07 07:50:55,205::task::1162::TaskManager.Task::(prepare) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-377::DEBUG::2012-11-07 07:50:55,205::task::978::TaskManager.Task::(_decref) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::ref 0 aborting True
>Thread-377::DEBUG::2012-11-07 07:50:55,205::task::913::TaskManager.Task::(_doAbort) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::Task._doAbort: force False
>Thread-377::DEBUG::2012-11-07 07:50:55,206::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-377::DEBUG::2012-11-07 07:50:55,206::task::588::TaskManager.Task::(_updateState) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::moving from state preparing -> state aborting
>Thread-377::DEBUG::2012-11-07 07:50:55,206::task::537::TaskManager.Task::(__state_aborting) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::_aborting: recover policy none
>Thread-377::DEBUG::2012-11-07 07:50:55,206::task::588::TaskManager.Task::(_updateState) Task=`c2aad506-d09d-464c-acc7-6828f33b2013`::moving from state aborting -> state failed
>Thread-377::DEBUG::2012-11-07 07:50:55,206::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-377::DEBUG::2012-11-07 07:50:55,206::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-377::ERROR::2012-11-07 07:50:55,207::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)", 'code': 309}}
>Thread-378::DEBUG::2012-11-07 07:50:55,243::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-378::DEBUG::2012-11-07 07:50:55,243::task::588::TaskManager.Task::(_updateState) Task=`5e807f73-5c08-487b-9afe-570dd92f99e5`::moving from state init -> state preparing
>Thread-378::INFO::2012-11-07 07:50:55,243::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='c02503a4-274e-11e2-b33c-002590730631', hostID=1, scsiKey='c02503a4-274e-11e2-b33c-002590730631', msdUUID='b1658676-2dc3-4357-b112-3852a056c663', masterVersion=1, options=None)
>Thread-378::DEBUG::2012-11-07 07:50:55,244::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`975e8250-1860-4ebf-bbd0-2350a882f80d`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-378::DEBUG::2012-11-07 07:50:55,244::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' for lock type 'exclusive'
>Thread-378::DEBUG::2012-11-07 07:50:55,244::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free. Now locking as 'exclusive' (1 active user)
>Thread-378::DEBUG::2012-11-07 07:50:55,245::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`975e8250-1860-4ebf-bbd0-2350a882f80d`::Granted request
>Thread-378::INFO::2012-11-07 07:50:55,245::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool c02503a4-274e-11e2-b33c-002590730631 with master domain: b1658676-2dc3-4357-b112-3852a056c663 (ver = 1)
>Thread-378::DEBUG::2012-11-07 07:50:55,245::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:55,246::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:55,246::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:55,246::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:55,246::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:55,247::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:55,247::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-378::DEBUG::2012-11-07 07:50:55,247::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-378::DEBUG::2012-11-07 07:50:55,247::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-378::DEBUG::2012-11-07 07:50:55,247::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-378::DEBUG::2012-11-07 07:50:55,248::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-378::DEBUG::2012-11-07 07:50:55,259::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-378::DEBUG::2012-11-07 07:50:55,259::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-378::DEBUG::2012-11-07 07:50:55,939::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-378::DEBUG::2012-11-07 07:50:56,006::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-378::DEBUG::2012-11-07 07:50:56,006::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,007::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,007::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,007::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,007::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,008::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,008::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-378::DEBUG::2012-11-07 07:50:56,008::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-378::DEBUG::2012-11-07 07:50:56,009::__init__::1249::Storage.Misc.excCmd::(_log) '/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 = [ \\"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 b1658676-2dc3-4357-b112-3852a056c663' (cwd None)
>Thread-378::DEBUG::2012-11-07 07:50:56,058::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found\n'; <rc> = 5
>Thread-378::WARNING::2012-11-07 07:50:56,060::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found']
>Thread-378::DEBUG::2012-11-07 07:50:56,060::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>clientIFinit::DEBUG::2012-11-07 07:50:59,874::task::588::TaskManager.Task::(_updateState) Task=`c34a42b3-e76f-46c6-b421-f54ff8675a08`::moving from state init -> state preparing
>clientIFinit::INFO::2012-11-07 07:50:59,875::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>clientIFinit::INFO::2012-11-07 07:50:59,875::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:50:59,875::task::1172::TaskManager.Task::(prepare) Task=`c34a42b3-e76f-46c6-b421-f54ff8675a08`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:50:59,875::task::588::TaskManager.Task::(_updateState) Task=`c34a42b3-e76f-46c6-b421-f54ff8675a08`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:50:59,876::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:50:59,876::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:50:59,876::task::978::TaskManager.Task::(_decref) Task=`c34a42b3-e76f-46c6-b421-f54ff8675a08`::ref 0 aborting False
>clientIFinit::DEBUG::2012-11-07 07:51:04,882::task::588::TaskManager.Task::(_updateState) Task=`ac9f147c-2346-4280-8217-820969dee9a4`::moving from state init -> state preparing
>clientIFinit::INFO::2012-11-07 07:51:04,882::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>clientIFinit::INFO::2012-11-07 07:51:04,882::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:04,882::task::1172::TaskManager.Task::(prepare) Task=`ac9f147c-2346-4280-8217-820969dee9a4`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:04,882::task::588::TaskManager.Task::(_updateState) Task=`ac9f147c-2346-4280-8217-820969dee9a4`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:51:04,883::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:51:04,883::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:51:04,883::task::978::TaskManager.Task::(_decref) Task=`ac9f147c-2346-4280-8217-820969dee9a4`::ref 0 aborting False
>clientIFinit::DEBUG::2012-11-07 07:51:09,889::task::588::TaskManager.Task::(_updateState) Task=`65ed0bb2-72d5-4ce8-b3fe-eaeba2013d0e`::moving from state init -> state preparing
>clientIFinit::INFO::2012-11-07 07:51:09,889::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>clientIFinit::INFO::2012-11-07 07:51:09,889::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:09,889::task::1172::TaskManager.Task::(prepare) Task=`65ed0bb2-72d5-4ce8-b3fe-eaeba2013d0e`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:09,889::task::588::TaskManager.Task::(_updateState) Task=`65ed0bb2-72d5-4ce8-b3fe-eaeba2013d0e`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:51:09,890::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:51:09,890::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:51:09,890::task::978::TaskManager.Task::(_decref) Task=`65ed0bb2-72d5-4ce8-b3fe-eaeba2013d0e`::ref 0 aborting False
>VM Channels Listener::DEBUG::2012-11-07 07:51:14,207::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 24.
>clientIFinit::DEBUG::2012-11-07 07:51:14,896::task::588::TaskManager.Task::(_updateState) Task=`866c27ad-6c0a-4fea-bdc0-74425d7d44d9`::moving from state init -> state preparing
>clientIFinit::INFO::2012-11-07 07:51:14,896::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>clientIFinit::INFO::2012-11-07 07:51:14,896::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:14,896::task::1172::TaskManager.Task::(prepare) Task=`866c27ad-6c0a-4fea-bdc0-74425d7d44d9`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:14,897::task::588::TaskManager.Task::(_updateState) Task=`866c27ad-6c0a-4fea-bdc0-74425d7d44d9`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:51:14,897::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:51:14,897::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:51:14,897::task::978::TaskManager.Task::(_decref) Task=`866c27ad-6c0a-4fea-bdc0-74425d7d44d9`::ref 0 aborting False
>clientIFinit::DEBUG::2012-11-07 07:51:19,903::task::588::TaskManager.Task::(_updateState) Task=`6a6e0a0e-0490-4208-8b4d-4ea5f5bf4e0e`::moving from state init -> state preparing
>clientIFinit::INFO::2012-11-07 07:51:19,903::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>clientIFinit::INFO::2012-11-07 07:51:19,903::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:19,903::task::1172::TaskManager.Task::(prepare) Task=`6a6e0a0e-0490-4208-8b4d-4ea5f5bf4e0e`::finished: {'poollist': []}
>clientIFinit::DEBUG::2012-11-07 07:51:19,904::task::588::TaskManager.Task::(_updateState) Task=`6a6e0a0e-0490-4208-8b4d-4ea5f5bf4e0e`::moving from state preparing -> state finished
>clientIFinit::DEBUG::2012-11-07 07:51:19,904::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>clientIFinit::DEBUG::2012-11-07 07:51:19,904::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>clientIFinit::DEBUG::2012-11-07 07:51:19,904::task::978::TaskManager.Task::(_decref) Task=`6a6e0a0e-0490-4208-8b4d-4ea5f5bf4e0e`::ref 0 aborting False
>

Actions: View

Attachments on bug 874120: 640114 | 641526 | 641527