11:38 a.m.
Hello
We have a cluster with 9 ovirt host and a storage cluster with 3 storage servers, we run
ovirt 4.3.6.6-1.
Storage is setup is replica 3 with arbiter.
There is another unmanaged gluster volume which is replica 3 based on local disks of ovirt
hosts and the engine and a few small pfsense vm reside on it.
Yesterday we experienced a hardware failure on one raid controler on one of the storage
servers, so the server stopped working.
On that particular server on it's local disks was a nfs storage domain used as ISO.
After the storage server failure multiple machines got stuck and in not responding state,
others kept working but we could not manage them from ovirt. many machines had iso mounted
so it may have to do with this. https://bugzilla.redhat.com/show_bug.cgi?id=1337073
But machines with ISO mounted were not the only ones affected. Allmost every host on ovirt
clusterd switched from non responding to ok status, many machines were on unknown status
even if they did not have mounted iso or even resided in any storage domain of the
gluster cluster. I.E. pfsense machines residing on local drives as the engine. These
machines could not be Powered off from inside the engine. In any case I could not put the
iso domain on maintenance because isos were still mounted on varius virtual machines.
I'm wondering what caused the allmost total failure, was it the nfs domain that could
not be mounted ? And of course how could I prevent such a situation.
I'm sending you the logs from the critical time period from one of the hosts. Please
let me know if you need more debug info.
2019-10-17 06:01:43,039+0300 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer] RPC call
Host.getStats succeeded in 0.25 seconds (__init__:312)
2019-10-17 06:01:46,638+0300 WARN (check/loop) [storage.check] Checker
u'/rhev/data-center/mnt/g2-car0133.gfs-int.uoc.gr:_nfs-exports_isos/ec67be6b-367f-4e41-a686-695ab50c0034/dom_md/metadata'
is blocked for 39
0.00 seconds (check:282)
2019-10-17 06:01:49,318+0300 WARN (itmap/0) [storage.scanDomains] Could not collect
metadata file for domain path
/rhev/data-center/mnt/g2-car0133.gfs-int.uoc.gr:_nfs-exports_isos (fileSD:913)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/fileSD.py", line 902, in
collectMetaFiles
metaFiles = oop.getProcessPool(client_name).glob.glob(mdPattern)
File "/usr/lib/python2.7/site-packages/vdsm/storage/outOfProcess.py", line
110, in glob
return self._iop.glob(pattern)
File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 561, in
glob
return self._sendCommand("glob", {"pattern": pattern},
self.timeout)
File "/usr/lib/python2.7/site-packages/ioprocess/__init__.py", line 442, in
_sendCommand
raise Timeout(os.strerror(errno.ETIMEDOUT))
Timeout: Connection timed out
2019-10-17 06:01:49,319+0300 ERROR (monitor/ec67be6) [storage.Monitor] Error checking
domain ec67be6b-367f-4e41-a686-695ab50c0034 (monitor:425)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/storage/monitor.py", line 406, in
_checkDomainStatus
self.domain.selftest()
File "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 48, in
__getattr__
return getattr(self.getRealDomain(), attrName)
File "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 51, in
getRealDomain
return self._cache._realProduce(self._sdUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 134, in
_realProduce
domain = self._findDomain(sdUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/sdc.py", line 151, in
_findDomain
return findMethod(sdUUID)
File "/usr/lib/python2.7/site-packages/vdsm/storage/nfsSD.py", line 145, in
findDomain
return NfsStorageDomain(NfsStorageDomain.findDomainPath(sdUUID))
File "/usr/lib/python2.7/site-packages/vdsm/storage/nfsSD.py", line 135, in
findDomainPath
raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist:
(u'ec67be6b-367f-4e41-a686-695ab50c0034',)
2019-10-17 06:01:50,253+0300 INFO (periodic/42) [vdsm.api] START repoStats(domains=())
from=internal, task_id=25ab44e7-26f7-4494-a970-f73f01892156 (api:48)
2019-10-17 06:01:50,253+0300 INFO (periodic/42) [vdsm.api] FINISH repoStats
return={u'3c973b94-a57d-4462-bcb3-3cef13290327': {'code': 0,
'actual': True, 'version': 5, 'acquired': True, 'delay':
'0.000932761', '
lastCheck': '3.6', 'valid': True},
u'ec67be6b-367f-4e41-a686-695ab50c0034': {'code': 2001, 'actual':
True, 'version': -1, 'acquired': False, 'delay': '0',
'lastCheck': '0.9', 'valid': False}, u'a1ecca6f-1487-492
d-b9bf-d3fb60f1bc99': {'code': 0, 'actual': True, 'version':
5, 'acquired': True, 'delay': '0.00142361', 'lastCheck':
'3.7', 'valid': True}, u'd5c52bc8-1a83-4915-b82f-d98e33db7c99':
{'code': 0, 'actual': True, '
version': 5, 'acquired': True, 'delay': '0.00124982',
'lastCheck': '3.6', 'valid': True},
u'453eb3c2-c3a5-4d5f-8c1d-b16588fc5eff': {'code': 0, 'actual':
True, 'version': 5, 'acquired': True, 'delay':
'0.001343',
'lastCheck': '3.6', 'valid': True}} from=internal,
task_id=25ab44e7-26f7-4494-a970-f73f01892156 (api:54)
2019-10-17 06:01:50,403+0300 WARN (vdsm.Scheduler) [Executor] executor state: count=8
workers=set([<Worker name=qgapoller/58 waiting task#=1 at 0x7fcd61483310>,
<Worker name=qgapoller/53 running <Task discardab
le <Operation action=<VmDispatcher operation=<function <lambda> at
0x7fcd80036668> at 0x7fcd80492850> at 0x7fcd80492890> timeout=10, duration=30.00
at 0x7fcd615adcd0> discarded task#=11 at 0x7fcd615ad2d0>, <Work
er name=qgapoller/56 running <Task discardable <Operation action=<VmDispatcher
operation=<function <lambda> at 0x7fcd80036668> at 0x7fcd80492850> at
0x7fcd80492890> timeout=10, duration=10.00 at 0x7fcd614cd8d0>
discarded task#=11 at 0x7fcd610013d0>, <Worker name=qgapoller/60 waiting task#=0 at
0x7fcd612cd910>, <Worker name=qgapoller/57 running <Task discardable
<Operation action=<VmDispatcher operation=<function <lambd
a> at 0x7fcd80036668> at 0x7fcd80492850> at 0x7fcd80492890> timeout=10,
duration=20.00 at 0x7fcd8003f190> discarded task#=0 at 0x7fcd3c355310>, <Worker
name=qgapoller/55 running <Task discardable <Operation acti
on=<VmDispatcher operation=<function <lambda> at 0x7fcd80036668> at
0x7fcd80492850> at 0x7fcd80492890> timeout=10, duration=40.00 at 0x7fcd61483bd0>
discarded task#=57 at 0x7fcd611dd150>, <Worker name=qgapoller/
59 waiting task#=0 at 0x7fcd614318d0>, <Worker name=qgapoller/54 waiting task#=14 at
0x7fcd3c3f5fd0>]) (executor:213)
2019-10-17 06:01:50,403+0300 INFO (vdsm.Scheduler) [Executor] Worker discarded:
<Worker name=qgapoller/56 running <Task discardable <Operation
action=<VmDispatcher operation=<function <lambda> at 0x7fcd80036668
at 0x7fcd80492850> at 0x7fcd80492890> timeout=10,
duration=10.00 at 0x7fcd614cd8d0> discarded task#=11 at 0x7fcd610013d0>
(executor:355)
2019-10-17 06:01:52,094+0300 WARN (vdsm.Scheduler) [Executor]
executor state: count=10 workers=set([<Worker name=periodic/42 waiting task#=4 at
0x7fcd3c592850>, <Worker name=periodic/43 waiting task#=0 at 0x7fc
d6124a090>, <Worker name=periodic/39 running <Task discardable <Operation
action=<vdsm.virt.sampling.VMBulkstatsMonitor object at 0x7fcd3c5a5090> at
0x7fcd3c5a52d0> timeout=7.5, duration=37.50 at 0x7fcd61483610>
discarded task#=10 at 0x7fcd8003fed0>, <Worker name=periodic/2 running <Task
discardable <Operation action=<vdsm.virt.sampling.VMBulkstatsMonitor object at
0x7fcd3c5a5090> at 0x7fcd3c5a52d0> timeout=7.5, durati
on=832.50 at 0x7fcd3c505f10> discarded task#=287729 at 0x7fcd806020d0>, <Worker
name=periodic/41 waiting task#=7 at 0x7fcd3c5927d0>, <Worker name=periodic/3 running
<Task discardable <Operation action=<vdsm.virt
.sampling.VMBulkstatsMonitor object at 0x7fcd3c5a5090> at 0x7fcd3c5a52d0>
timeout=7.5, duration=802.50 at 0x7fcd6162d550> discarded task#=287772 at
0x7fcd3c592910>, <Worker name=periodic/34 running <Task discard
able <Operation action=<vdsm.virt.sampling.VMBulkstatsMonitor object at
0x7fcd3c5a5090> at 0x7fcd3c5a52d0> timeout=7.5, duration=22.50 at 0x7fcd3c529d10>
discarded task#=43 at 0x7fcd3c4add50>, <Worker name=perio
dic/40 running <Task discardable <Operation action=<VmDispatcher
operation=<class 'vdsm.virt.periodic.UpdateVolumes'> at 0x7fcd3c5924d0>
at 0x7fcd3c592e10> timeout=30.0, duration=2.89 at 0x7fcd3c433710> task#=20
at 0x7fcd612cd890>, <Worker name=periodic/38 running <Task discardable
<Operation action=<vdsm.virt.sampling.VMBulkstatsMonitor object at
0x7fcd3c5a5090> at 0x7fcd3c5a52d0> timeout=7.5, duration=7.50 at 0x7fcd3
c315fd0> discarded task#=18 at 0x7fcd6124a1d0>, <Worker name=periodic/4 running
<Task discardable <Operation action=<vdsm.virt.sampling.VMBulkstatsMonitor object
at 0x7fcd3c5a5090> at 0x7fcd3c5a52d0> timeout=7.5
, duration=817.50 at 0x7fcd615d62d0> discarded task#=284811 at 0x7fcd614495d0>])
(executor:213)
2019-10-17 06:01:52,094+0300 INFO (vdsm.Scheduler) [Executor] Worker discarded:
<Worker name=periodic/38 running <Task discardable <Operation
action=<vdsm.virt.sampling.VMBulkstatsMonitor object at 0x7fcd3c5a5090> at
0x7fcd3c5a52d0> timeout=7.5, duration=7.50 at 0x7fcd3c315fd0> discarded task#=18 at
0x7fcd6124a1d0> (executor:355)
2019-10-17 06:01:52,495+0300 INFO (monitor/453eb3c) [IOProcessClient]
(/g2-car0133.gfs-int.uoc.gr:_nfs-exports_isos) Closing client (__init__:610)
2019-10-17 06:01:52,495+0300 INFO (monitor/453eb3c) [IOProcessClient]
(/glusterSD/10.252.166.128:_volume1) Closing client (__init__:610)
2019-10-17 06:01:52,496+0300 INFO (monitor/453eb3c) [IOProcessClient]
(/glusterSD/10.252.166.130:_volume3) Closing client (__init__:610)
2019-10-17 06:01:52,496+0300 INFO (monitor/453eb3c) [IOProcessClient]
(/glusterSD/10.252.166.129:_volume2) Closing client (__init__:610)
2019-10-17 06:01:52,496+0300 INFO (monitor/453eb3c) [IOProcessClient]
(/glusterSD/o5-car0118.gfs-int.uoc.gr:_engine) Closing client (__init__:610)
2019-10-17 06:01:53,123+0300 INFO (itmap/0) [IOProcessClient]
(/glusterSD/o5-car0118.gfs-int.uoc.gr:_engine) Starting client (__init__:308)
2019-10-17 06:01:53,133+0300 INFO (itmap/1) [IOProcessClient]
(/glusterSD/10.252.166.130:_volume3) Starting client (__init__:308)
2019-10-17 06:01:53,136+0300 INFO (ioprocess/28525) [IOProcess]
(/glusterSD/o5-car0118.gfs-int.uoc.gr:_engine) Starting ioprocess (__init__:434)
2019-10-17 06:01:53,149+0300 INFO (itmap/2) [IOProcessClient]
(/glusterSD/10.252.166.128:_volume1) Starting client (__init__:308)
2019-10-17 06:01:53,152+0300 INFO (ioprocess/28534) [IOProcess]
(/glusterSD/10.252.166.130:_volume3) Starting ioprocess (__init__:434)
2019-10-17 06:01:53,161+0300 INFO (itmap/3) [IOProcessClient]
(/glusterSD/10.252.166.129:_volume2) Starting client (__init__:308)
2019-10-17 06:01:53,165+0300 WARN (monitor/a1ecca6) [storage.PersistentDict] Could not
parse line
`^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^
so on
2019-10-17 06:01:53,166+0300 INFO (ioprocess/28540) [IOProcess]
(/glusterSD/10.252.166.128:_volume1) Starting ioprocess (__init__:434)
2019-10-17 06:01:53,175+0300 INFO (ioprocess/28547) [IOProcess]
(/glusterSD/10.252.166.129:_volume2) Starting ioprocess (__init__:434)
2019-10-17 06:01:54,763+0300 INFO (monitor/a1ecca6) [storage.StorageDomain] Removing
remnants of deleted images [] (fileSD:726)
2019-10-17 06:01:55,271+0300 INFO (jsonrpc/4) [api.host] START getAllVmStats()
from=::1,32814 (api:48)
2019-10-17 06:01:55,274+0300 WARN (jsonrpc/4) [virt.vm]
(vmId='38586008-37a0-4400-83b2-771090c50a9a') monitor became unresponsive (command
timeout, age=850.680000001) (vm:6061)
2019-10-17 06:01:55,277+0300 WARN (vdsm.Scheduler) [Executor] Worker blocked: <Worker
name=jsonrpc/3 running <Task <JsonRpcTask {'params': {}, 'jsonrpc':
'2.0', 'method': u'Host.getAllVmStats', 'id':
u'33b72799-68cd-419c-bb6c-d9c9f61664b5'} at 0x7fcd3c329d10> timeout=60,
duration=60.01 at 0x7fcd3c3298d0> task#=39322 at 0x7fcd3c581ed0>, traceback:
File: "/usr/lib64/python2.7/threading.py", line 785, in __bootstrap
self.__bootstrap_inner()
File: "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner
self.run()
File: "/usr/lib64/python2.7/threading.py", line 765, in run
self.__target(*self.__args, **self.__kwargs)
File: "/usr/lib/python2.7/site-packages/vdsm/common/concurrent.py", line 195, in
run
ret = func(*args, **kwargs)
File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 301, in _run
self._execute_task()
File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 315, in
_execute_task
task()
File: "/usr/lib/python2.7/site-packages/vdsm/executor.py", line 391, in
__call__
self._callable()
File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 262, in
__call__
self._handler(self._ctx, self._req)
File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 305, in
_serveRequest
response = self._handle_request(req, ctx)
File: "/usr/lib/python2.7/site-packages/yajsonrpc/__init__.py", line 345, in
_handle_request
res = method(**params)
File: "/usr/lib/python2.7/site-packages/vdsm/rpc/Bridge.py", line 198, in
_dynamicMethod
result = fn(*methodArgs)
File: "<string>", line 2, in getAllVmStats
File: "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 50, in method
ret = func(*args, **kwargs)
File: "/usr/lib/python2.7/site-packages/vdsm/API.py", line 1395, in
getAllVmStats
statsList = self._cif.getAllVmStats()
File: "/usr/lib/python2.7/site-packages/vdsm/clientIF.py", line 569, in
getAllVmStats
return [v.getStats() for v in self.getVMs().values()]
File: "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 1781, in
getStats
oga_stats = self._getGuestStats()
File: "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2000, in
_getGuestStats
self._update_guest_disk_mapping()
File: "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2015, in
_update_guest_disk_mapping
self._sync_metadata()
File: "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5142, in
_sync_metadata
self._md_desc.dump(self._dom)
File: "/usr/lib/python2.7/site-packages/vdsm/virt/metadata.py", line 515, in
dump
0)
File: "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 100, in f
ret = attr(*args, **kwargs)
File: "/usr/lib/python2.7/site-packages/vdsm/common/libvirtconnection.py", line
131, in wrapper
ret = f(*args, **kwargs)
File: "/usr/lib/python2.7/site-packages/vdsm/common/function.py", line 94, in
wrapper
return func(inst, *args, **kwargs)
File: "/usr/lib64/python2.7/site-packages/libvirt.py", line 2364, in
setMetadata
ret = libvirtmod.virDomainSetMetadata(self._o, type, metadata, key, uri, flags)
(executor:363)
2019-10-17 06:01:55,279+0300 WARN (jsonrpc/3) [virt.vm]
(vmId='b14cbec9-7acb-4f80-ad5e-3169e17d5328') Couldn't update metadata: Timed
out during operation: cannot acquire state change lock (held by
monitor=remoteDispatchConnectGetAllDomainStats) (vm:2018)
2019-10-17 06:01:55,285+0300 INFO (jsonrpc/3) [api.host] FINISH getAllVmStats
return={'status': {'message': 'Done', 'code': 0},
'statsList': (suppressed)} from=::1,32814 (api:54)
2019-10-17 06:01:55,290+0300 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call
Host.getAllVmStats succeeded in 60.02 seconds (__init__:312)