Attachment 633228 Details for Bug 869956 – VDSM client host /vra/log/vdsm/vdsm.log

VDSM client host /vra/log/vdsm/vdsm.log

vdsm.log (text/plain), 32.09 KB, created by EricLee on 2012-10-25 08:34:54 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: EricLee

Created: 2012-10-25 08:34:54 UTC

Size: 32.09 KB

patch

obsolete

>Thread-3851::DEBUG::2012-10-25 16:02:43,867::task::588::TaskManager.Task::(_updateState) Task=`1561b0ac-29ba-4aae-829f-d8d852ee3d17`::moving from state init -> state preparing
>Thread-3851::INFO::2012-10-25 16:02:43,867::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3851::INFO::2012-10-25 16:02:43,867::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3851::DEBUG::2012-10-25 16:02:43,867::task::1172::TaskManager.Task::(prepare) Task=`1561b0ac-29ba-4aae-829f-d8d852ee3d17`::finished: {}
>Thread-3851::DEBUG::2012-10-25 16:02:43,868::task::588::TaskManager.Task::(_updateState) Task=`1561b0ac-29ba-4aae-829f-d8d852ee3d17`::moving from state preparing -> state finished
>Thread-3851::DEBUG::2012-10-25 16:02:43,868::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3851::DEBUG::2012-10-25 16:02:43,868::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3851::DEBUG::2012-10-25 16:02:43,868::task::978::TaskManager.Task::(_decref) Task=`1561b0ac-29ba-4aae-829f-d8d852ee3d17`::ref 0 aborting False
>Thread-3854::DEBUG::2012-10-25 16:02:46,576::BindingXMLRPC::171::vds::(wrapper) [10.66.5.12]
>Thread-3854::DEBUG::2012-10-25 16:02:46,577::task::588::TaskManager.Task::(_updateState) Task=`f7289034-c297-4364-92c5-b485b866f5d0`::moving from state init -> state preparing
>Thread-3854::INFO::2012-10-25 16:02:46,577::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '10.66.5.12:/mnt/data/rhevm', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
>Thread-3854::INFO::2012-10-25 16:02:46,577::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-3854::DEBUG::2012-10-25 16:02:46,577::task::1172::TaskManager.Task::(prepare) Task=`f7289034-c297-4364-92c5-b485b866f5d0`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-3854::DEBUG::2012-10-25 16:02:46,578::task::588::TaskManager.Task::(_updateState) Task=`f7289034-c297-4364-92c5-b485b866f5d0`::moving from state preparing -> state finished
>Thread-3854::DEBUG::2012-10-25 16:02:46,578::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3854::DEBUG::2012-10-25 16:02:46,578::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3854::DEBUG::2012-10-25 16:02:46,578::task::978::TaskManager.Task::(_decref) Task=`f7289034-c297-4364-92c5-b485b866f5d0`::ref 0 aborting False
>Thread-3855::DEBUG::2012-10-25 16:02:46,604::BindingXMLRPC::171::vds::(wrapper) [10.66.5.12]
>Thread-3855::DEBUG::2012-10-25 16:02:46,605::task::588::TaskManager.Task::(_updateState) Task=`8a50eabe-d35c-43bb-abaf-43d5fcdfd8c5`::moving from state init -> state preparing
>Thread-3855::INFO::2012-10-25 16:02:46,605::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '10.66.5.12:/mnt/data/rhevm', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': 'f47a9bf7-17d6-4c4d-b5de-b2e2afa4f54c', 'port': ''}], options=None)
>Thread-3855::DEBUG::2012-10-25 16:02:46,608::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6 10.66.5.12:/mnt/data/rhevm /rhev/data-center/mnt/10.66.5.12:_mnt_data_rhevm' (cwd None)
>Thread-3855::INFO::2012-10-25 16:02:46,683::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'f47a9bf7-17d6-4c4d-b5de-b2e2afa4f54c'}]}
>Thread-3855::DEBUG::2012-10-25 16:02:46,687::task::1172::TaskManager.Task::(prepare) Task=`8a50eabe-d35c-43bb-abaf-43d5fcdfd8c5`::finished: {'statuslist': [{'status': 0, 'id': 'f47a9bf7-17d6-4c4d-b5de-b2e2afa4f54c'}]}
>Thread-3855::DEBUG::2012-10-25 16:02:46,687::task::588::TaskManager.Task::(_updateState) Task=`8a50eabe-d35c-43bb-abaf-43d5fcdfd8c5`::moving from state preparing -> state finished
>Thread-3855::DEBUG::2012-10-25 16:02:46,687::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3855::DEBUG::2012-10-25 16:02:46,688::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3855::DEBUG::2012-10-25 16:02:46,688::task::978::TaskManager.Task::(_decref) Task=`8a50eabe-d35c-43bb-abaf-43d5fcdfd8c5`::ref 0 aborting False
>Thread-3856::DEBUG::2012-10-25 16:02:46,779::BindingXMLRPC::171::vds::(wrapper) [10.66.5.12]
>Thread-3856::DEBUG::2012-10-25 16:02:46,779::task::588::TaskManager.Task::(_updateState) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::moving from state init -> state preparing
>Thread-3856::INFO::2012-10-25 16:02:46,780::logUtils::37::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=1, sdUUID='9a16b215-78c6-4873-a26b-76e9b8946d73', domainName='512', typeSpecificArg='10.66.5.12:/mnt/data/rhevm', domClass=1, domVersion='3', options=None)
>Thread-3856::DEBUG::2012-10-25 16:02:46,780::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-3856::DEBUG::2012-10-25 16:02:46,780::misc::1045::SamplingMethod::(__call__) Got in to sampling method
>Thread-3856::DEBUG::2012-10-25 16:02:46,780::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-3856::DEBUG::2012-10-25 16:02:46,781::misc::1045::SamplingMethod::(__call__) Got in to sampling method
>Thread-3856::DEBUG::2012-10-25 16:02:46,781::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-3856::DEBUG::2012-10-25 16:02:46,796::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-3856::DEBUG::2012-10-25 16:02:46,797::misc::1053::SamplingMethod::(__call__) Returning last result
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,799::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,801::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,803::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,805::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,807::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,808::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,810::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host6/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,812::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host7/scan' (cwd None)
>MainProcess|Thread-3856::DEBUG::2012-10-25 16:02:46,814::iscsi::376::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
>Thread-3856::DEBUG::2012-10-25 16:02:48,817::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-3856::DEBUG::2012-10-25 16:02:48,880::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-3856::DEBUG::2012-10-25 16:02:48,881::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,884::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,884::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,884::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,885::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,885::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,885::misc::1053::SamplingMethod::(__call__) Returning last result
>Thread-3856::DEBUG::2012-10-25 16:02:48,886::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-3856::DEBUG::2012-10-25 16:02:48,886::__init__::1164::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 9a16b215-78c6-4873-a26b-76e9b8946d73' (cwd None)
>Thread-3856::DEBUG::2012-10-25 16:02:49,026::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "9a16b215-78c6-4873-a26b-76e9b8946d73" not found\n'; <rc> = 5
>Thread-3856::WARNING::2012-10-25 16:02:49,027::lvm::356::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "9a16b215-78c6-4873-a26b-76e9b8946d73" not found']
>Thread-3856::DEBUG::2012-10-25 16:02:49,028::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-3856::INFO::2012-10-25 16:02:49,030::nfsSD::66::Storage.StorageDomain::(create) sdUUID=9a16b215-78c6-4873-a26b-76e9b8946d73 domainName=512 remotePath=10.66.5.12:/mnt/data/rhevm domClass=1
>Thread-3856::DEBUG::2012-10-25 16:02:49,154::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>Thread-3856::DEBUG::2012-10-25 16:02:49,155::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
>Thread-3856::WARNING::2012-10-25 16:02:49,155::persistentDict::248::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>Thread-3856::DEBUG::2012-10-25 16:02:49,155::persistentDict::162::Storage.PersistentDict::(transaction) Starting transaction
>Thread-3856::DEBUG::2012-10-25 16:02:49,155::persistentDict::168::Storage.PersistentDict::(transaction) Flushing changes
>Thread-3856::DEBUG::2012-10-25 16:02:49,156::persistentDict::287::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=512', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=10.66.5.12:/mnt/data/rhevm', 'ROLE=Regular', 'SDUUID=9a16b215-78c6-4873-a26b-76e9b8946d73', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=fd67fa49acb463a04b632e53a4a336164e7a80b0']
>Thread-3856::DEBUG::2012-10-25 16:02:49,158::persistentDict::170::Storage.PersistentDict::(transaction) Finished transaction
>Thread-3856::DEBUG::2012-10-25 16:02:49,159::fileSD::107::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.66.5.12:_mnt_data_rhevm/9a16b215-78c6-4873-a26b-76e9b8946d73
>Thread-3856::DEBUG::2012-10-25 16:02:49,159::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>Thread-3856::WARNING::2012-10-25 16:02:49,169::remoteFileHandler::185::Storage.CrabRPCProxy::(callCrabRPCFunction) Problem with handler, treating as timeout
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 177, in callCrabRPCFunction
>    rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 146, in _recvAll
>    timeLeft):
>  File "/usr/lib64/python2.6/contextlib.py", line 83, in helper
>    return GeneratorContextManager(func(*args, **kwds))
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 133, in _poll
>    raise Timeout()
>Timeout
>Thread-3856::ERROR::2012-10-25 16:02:49,170::task::853::TaskManager.Task::(_setError) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::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 2189, in createStorageDomain
>    typeSpecificArg, storageType, domVersion)
>  File "/usr/share/vdsm/storage/nfsSD.py", line 93, in create
>    fsd = cls(os.path.join(mntPoint, sdUUID))
>  File "/usr/share/vdsm/storage/fileSD.py", line 113, in __init__
>    sdUUID = metadata[sd.DMDK_SDUUID]
>  File "/usr/share/vdsm/storage/persistentDict.py", line 85, in __getitem__
>    return dec(self._dict[key])
>  File "/usr/share/vdsm/storage/persistentDict.py", line 193, in __getitem__
>    with self._accessWrapper():
>  File "/usr/lib64/python2.6/contextlib.py", line 16, in __enter__
>    return self.gen.next()
>  File "/usr/share/vdsm/storage/persistentDict.py", line 147, in _accessWrapper
>    self.refresh()
>  File "/usr/share/vdsm/storage/persistentDict.py", line 224, in refresh
>    lines = self._metaRW.readlines()
>  File "/usr/share/vdsm/storage/fileSD.py", line 82, in readlines
>    return misc.stripNewLines(self._oop.directReadLines(self._metafile))
>  File "/usr/share/vdsm/storage/remoteFileHandler.py", line 282, in callCrabRPCFunction
>    raise Timeout("Operation stuck on remote handler")
>Timeout: Operation stuck on remote handler
>Thread-3856::DEBUG::2012-10-25 16:02:49,171::task::872::TaskManager.Task::(_run) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::Task._run: 5c73ae30-0df5-414d-9bfb-59745167e3e7 (1, '9a16b215-78c6-4873-a26b-76e9b8946d73', '512', '10.66.5.12:/mnt/data/rhevm', 1, '3') {} failed - stopping task
>Thread-3856::DEBUG::2012-10-25 16:02:49,171::task::1199::TaskManager.Task::(stop) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::stopping in state preparing (force False)
>Thread-3856::DEBUG::2012-10-25 16:02:49,171::task::978::TaskManager.Task::(_decref) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::ref 1 aborting True
>Thread-3856::INFO::2012-10-25 16:02:49,172::task::1157::TaskManager.Task::(prepare) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::aborting: Task is aborted: u'Operation stuck on remote handler' - code 100
>Thread-3856::DEBUG::2012-10-25 16:02:49,172::task::1162::TaskManager.Task::(prepare) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::Prepare: aborted: Operation stuck on remote handler
>Thread-3856::DEBUG::2012-10-25 16:02:49,173::task::978::TaskManager.Task::(_decref) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::ref 0 aborting True
>Thread-3856::DEBUG::2012-10-25 16:02:49,173::task::913::TaskManager.Task::(_doAbort) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::Task._doAbort: force False
>Thread-3856::DEBUG::2012-10-25 16:02:49,173::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3856::DEBUG::2012-10-25 16:02:49,173::task::588::TaskManager.Task::(_updateState) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::moving from state preparing -> state aborting
>Thread-3856::DEBUG::2012-10-25 16:02:49,173::task::537::TaskManager.Task::(__state_aborting) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::_aborting: recover policy none
>Thread-3856::DEBUG::2012-10-25 16:02:49,174::task::588::TaskManager.Task::(_updateState) Task=`5c73ae30-0df5-414d-9bfb-59745167e3e7`::moving from state aborting -> state failed
>Thread-3856::DEBUG::2012-10-25 16:02:49,174::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3856::DEBUG::2012-10-25 16:02:49,174::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3856::ERROR::2012-10-25 16:02:49,174::dispatcher::69::Storage.Dispatcher.Protect::(run) Operation stuck on remote handler
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/dispatcher.py", line 61, in run
>    result = ctask.prepare(self.func, *args, **kwargs)
>  File "/usr/share/vdsm/storage/task.py", line 1164, in prepare
>    raise self.error
>Timeout: Operation stuck on remote handler
>Thread-3861::DEBUG::2012-10-25 16:02:49,322::BindingXMLRPC::171::vds::(wrapper) [10.66.5.12]
>Thread-3861::DEBUG::2012-10-25 16:02:49,322::task::588::TaskManager.Task::(_updateState) Task=`3fbc652d-4ca1-41a9-9dcb-05f944eb7a4f`::moving from state init -> state preparing
>Thread-3861::INFO::2012-10-25 16:02:49,323::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': '10.66.5.12:/mnt/data/rhevm', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000', 'port': ''}], options=None)
>Thread-3861::DEBUG::2012-10-25 16:02:49,323::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/10.66.5.12:_mnt_data_rhevm' (cwd None)
>Thread-3861::DEBUG::2012-10-25 16:02:49,356::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-3861::DEBUG::2012-10-25 16:02:49,357::misc::1045::SamplingMethod::(__call__) Got in to sampling method
>Thread-3861::DEBUG::2012-10-25 16:02:49,357::misc::1043::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-3861::DEBUG::2012-10-25 16:02:49,357::misc::1045::SamplingMethod::(__call__) Got in to sampling method
>Thread-3861::DEBUG::2012-10-25 16:02:49,358::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-3861::DEBUG::2012-10-25 16:02:49,369::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-3861::DEBUG::2012-10-25 16:02:49,370::misc::1053::SamplingMethod::(__call__) Returning last result
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,373::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host0/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,376::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host1/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,378::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host2/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,379::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host3/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,381::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host4/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,383::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host5/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,385::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host6/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,387::__init__::1164::Storage.Misc.excCmd::(_log) '/bin/dd of=/sys/class/scsi_host/host7/scan' (cwd None)
>MainProcess|Thread-3861::DEBUG::2012-10-25 16:02:49,388::iscsi::376::Storage.ISCSI::(forceIScsiScan) Performing SCSI scan, this will take up to 30 seconds
>Thread-3861::DEBUG::2012-10-25 16:02:51,392::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-3861::DEBUG::2012-10-25 16:02:51,481::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-3861::DEBUG::2012-10-25 16:02:51,481::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-3861::DEBUG::2012-10-25 16:02:51,481::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-3861::DEBUG::2012-10-25 16:02:51,482::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-3861::DEBUG::2012-10-25 16:02:51,482::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-3861::DEBUG::2012-10-25 16:02:51,482::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-3861::DEBUG::2012-10-25 16:02:51,483::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-3861::DEBUG::2012-10-25 16:02:51,483::misc::1053::SamplingMethod::(__call__) Returning last result
>Thread-3861::INFO::2012-10-25 16:02:51,483::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-3861::DEBUG::2012-10-25 16:02:51,483::task::1172::TaskManager.Task::(prepare) Task=`3fbc652d-4ca1-41a9-9dcb-05f944eb7a4f`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
>Thread-3861::DEBUG::2012-10-25 16:02:51,484::task::588::TaskManager.Task::(_updateState) Task=`3fbc652d-4ca1-41a9-9dcb-05f944eb7a4f`::moving from state preparing -> state finished
>Thread-3861::DEBUG::2012-10-25 16:02:51,484::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3861::DEBUG::2012-10-25 16:02:51,484::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3861::DEBUG::2012-10-25 16:02:51,484::task::978::TaskManager.Task::(_decref) Task=`3fbc652d-4ca1-41a9-9dcb-05f944eb7a4f`::ref 0 aborting False
>Thread-3864::DEBUG::2012-10-25 16:02:53,995::task::588::TaskManager.Task::(_updateState) Task=`fdc9b3f0-2eb4-4f36-8c35-70ec5e7c1ddd`::moving from state init -> state preparing
>Thread-3864::INFO::2012-10-25 16:02:53,995::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3864::INFO::2012-10-25 16:02:53,996::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3864::DEBUG::2012-10-25 16:02:53,996::task::1172::TaskManager.Task::(prepare) Task=`fdc9b3f0-2eb4-4f36-8c35-70ec5e7c1ddd`::finished: {}
>Thread-3864::DEBUG::2012-10-25 16:02:53,996::task::588::TaskManager.Task::(_updateState) Task=`fdc9b3f0-2eb4-4f36-8c35-70ec5e7c1ddd`::moving from state preparing -> state finished
>Thread-3864::DEBUG::2012-10-25 16:02:53,996::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3864::DEBUG::2012-10-25 16:02:53,997::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3864::DEBUG::2012-10-25 16:02:53,997::task::978::TaskManager.Task::(_decref) Task=`fdc9b3f0-2eb4-4f36-8c35-70ec5e7c1ddd`::ref 0 aborting False
>Thread-3870::DEBUG::2012-10-25 16:03:04,104::task::588::TaskManager.Task::(_updateState) Task=`e38379c9-79e5-4d91-8f56-2e689e01f6b7`::moving from state init -> state preparing
>Thread-3870::INFO::2012-10-25 16:03:04,105::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3870::INFO::2012-10-25 16:03:04,105::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3870::DEBUG::2012-10-25 16:03:04,105::task::1172::TaskManager.Task::(prepare) Task=`e38379c9-79e5-4d91-8f56-2e689e01f6b7`::finished: {}
>Thread-3870::DEBUG::2012-10-25 16:03:04,105::task::588::TaskManager.Task::(_updateState) Task=`e38379c9-79e5-4d91-8f56-2e689e01f6b7`::moving from state preparing -> state finished
>Thread-3870::DEBUG::2012-10-25 16:03:04,106::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3870::DEBUG::2012-10-25 16:03:04,106::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3870::DEBUG::2012-10-25 16:03:04,106::task::978::TaskManager.Task::(_decref) Task=`e38379c9-79e5-4d91-8f56-2e689e01f6b7`::ref 0 aborting False
>Thread-3876::DEBUG::2012-10-25 16:03:14,213::task::588::TaskManager.Task::(_updateState) Task=`f6295756-a780-48ef-8be5-c88bc87c90b9`::moving from state init -> state preparing
>Thread-3876::INFO::2012-10-25 16:03:14,214::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3876::INFO::2012-10-25 16:03:14,214::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3876::DEBUG::2012-10-25 16:03:14,214::task::1172::TaskManager.Task::(prepare) Task=`f6295756-a780-48ef-8be5-c88bc87c90b9`::finished: {}
>Thread-3876::DEBUG::2012-10-25 16:03:14,214::task::588::TaskManager.Task::(_updateState) Task=`f6295756-a780-48ef-8be5-c88bc87c90b9`::moving from state preparing -> state finished
>Thread-3876::DEBUG::2012-10-25 16:03:14,215::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3876::DEBUG::2012-10-25 16:03:14,215::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3876::DEBUG::2012-10-25 16:03:14,215::task::978::TaskManager.Task::(_decref) Task=`f6295756-a780-48ef-8be5-c88bc87c90b9`::ref 0 aborting False
>Thread-3882::DEBUG::2012-10-25 16:03:24,319::task::588::TaskManager.Task::(_updateState) Task=`92bb73f3-f185-4aff-9327-7e020622e034`::moving from state init -> state preparing
>Thread-3882::INFO::2012-10-25 16:03:24,319::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3882::INFO::2012-10-25 16:03:24,319::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3882::DEBUG::2012-10-25 16:03:24,320::task::1172::TaskManager.Task::(prepare) Task=`92bb73f3-f185-4aff-9327-7e020622e034`::finished: {}
>Thread-3882::DEBUG::2012-10-25 16:03:24,320::task::588::TaskManager.Task::(_updateState) Task=`92bb73f3-f185-4aff-9327-7e020622e034`::moving from state preparing -> state finished
>Thread-3882::DEBUG::2012-10-25 16:03:24,320::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3882::DEBUG::2012-10-25 16:03:24,320::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3882::DEBUG::2012-10-25 16:03:24,321::task::978::TaskManager.Task::(_decref) Task=`92bb73f3-f185-4aff-9327-7e020622e034`::ref 0 aborting False
>Thread-3888::DEBUG::2012-10-25 16:03:34,420::task::588::TaskManager.Task::(_updateState) Task=`05dd2bc5-4c58-4d1b-a83f-1696859ab45f`::moving from state init -> state preparing
>Thread-3888::INFO::2012-10-25 16:03:34,420::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3888::INFO::2012-10-25 16:03:34,421::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3888::DEBUG::2012-10-25 16:03:34,421::task::1172::TaskManager.Task::(prepare) Task=`05dd2bc5-4c58-4d1b-a83f-1696859ab45f`::finished: {}
>Thread-3888::DEBUG::2012-10-25 16:03:34,421::task::588::TaskManager.Task::(_updateState) Task=`05dd2bc5-4c58-4d1b-a83f-1696859ab45f`::moving from state preparing -> state finished
>Thread-3888::DEBUG::2012-10-25 16:03:34,421::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3888::DEBUG::2012-10-25 16:03:34,421::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3888::DEBUG::2012-10-25 16:03:34,422::task::978::TaskManager.Task::(_decref) Task=`05dd2bc5-4c58-4d1b-a83f-1696859ab45f`::ref 0 aborting False
>Thread-3894::DEBUG::2012-10-25 16:03:44,529::task::588::TaskManager.Task::(_updateState) Task=`cb1e12b4-5189-40c0-8581-2607c34d7815`::moving from state init -> state preparing
>Thread-3894::INFO::2012-10-25 16:03:44,529::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3894::INFO::2012-10-25 16:03:44,529::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3894::DEBUG::2012-10-25 16:03:44,529::task::1172::TaskManager.Task::(prepare) Task=`cb1e12b4-5189-40c0-8581-2607c34d7815`::finished: {}
>Thread-3894::DEBUG::2012-10-25 16:03:44,530::task::588::TaskManager.Task::(_updateState) Task=`cb1e12b4-5189-40c0-8581-2607c34d7815`::moving from state preparing -> state finished
>Thread-3894::DEBUG::2012-10-25 16:03:44,530::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3894::DEBUG::2012-10-25 16:03:44,530::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3894::DEBUG::2012-10-25 16:03:44,530::task::978::TaskManager.Task::(_decref) Task=`cb1e12b4-5189-40c0-8581-2607c34d7815`::ref 0 aborting False
>Thread-3900::DEBUG::2012-10-25 16:03:54,644::task::588::TaskManager.Task::(_updateState) Task=`6f9776b3-c3b0-4b2c-9fc4-7b3d7970d099`::moving from state init -> state preparing
>Thread-3900::INFO::2012-10-25 16:03:54,645::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3900::INFO::2012-10-25 16:03:54,645::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3900::DEBUG::2012-10-25 16:03:54,645::task::1172::TaskManager.Task::(prepare) Task=`6f9776b3-c3b0-4b2c-9fc4-7b3d7970d099`::finished: {}
>Thread-3900::DEBUG::2012-10-25 16:03:54,645::task::588::TaskManager.Task::(_updateState) Task=`6f9776b3-c3b0-4b2c-9fc4-7b3d7970d099`::moving from state preparing -> state finished
>Thread-3900::DEBUG::2012-10-25 16:03:54,645::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3900::DEBUG::2012-10-25 16:03:54,646::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3900::DEBUG::2012-10-25 16:03:54,646::task::978::TaskManager.Task::(_decref) Task=`6f9776b3-c3b0-4b2c-9fc4-7b3d7970d099`::ref 0 aborting False
>Thread-3906::DEBUG::2012-10-25 16:04:04,749::task::588::TaskManager.Task::(_updateState) Task=`570f0168-dec8-441a-9668-a44655055445`::moving from state init -> state preparing
>Thread-3906::INFO::2012-10-25 16:04:04,750::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3906::INFO::2012-10-25 16:04:04,750::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3906::DEBUG::2012-10-25 16:04:04,750::task::1172::TaskManager.Task::(prepare) Task=`570f0168-dec8-441a-9668-a44655055445`::finished: {}
>Thread-3906::DEBUG::2012-10-25 16:04:04,750::task::588::TaskManager.Task::(_updateState) Task=`570f0168-dec8-441a-9668-a44655055445`::moving from state preparing -> state finished
>Thread-3906::DEBUG::2012-10-25 16:04:04,751::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3906::DEBUG::2012-10-25 16:04:04,751::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3906::DEBUG::2012-10-25 16:04:04,751::task::978::TaskManager.Task::(_decref) Task=`570f0168-dec8-441a-9668-a44655055445`::ref 0 aborting False
>Thread-3912::DEBUG::2012-10-25 16:04:14,861::task::588::TaskManager.Task::(_updateState) Task=`89b6a949-1f9a-4cf0-a056-254def638e67`::moving from state init -> state preparing
>Thread-3912::INFO::2012-10-25 16:04:14,861::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3912::INFO::2012-10-25 16:04:14,862::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-3912::DEBUG::2012-10-25 16:04:14,862::task::1172::TaskManager.Task::(prepare) Task=`89b6a949-1f9a-4cf0-a056-254def638e67`::finished: {}
>Thread-3912::DEBUG::2012-10-25 16:04:14,862::task::588::TaskManager.Task::(_updateState) Task=`89b6a949-1f9a-4cf0-a056-254def638e67`::moving from state preparing -> state finished
>Thread-3912::DEBUG::2012-10-25 16:04:14,862::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-3912::DEBUG::2012-10-25 16:04:14,862::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-3912::DEBUG::2012-10-25 16:04:14,863::task::978::TaskManager.Task::(_decref) Task=`89b6a949-1f9a-4cf0-a056-254def638e67`::ref 0 aborting False

Actions: View

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