[ovirt-users] Hyperconverged Ovirt 4.3.10.4: Unresponsive Host

Tuesday, 7 June 2022

Hi, 
I have a hyperconverged ovirt 4.3.10 installation. One host is unresponsive. This has
happened in the past but most often resolved itself within a few minutes. This time it is
a different beast. 
The host does not come back. Putting the host in maintenance is not possible because
"Host is unresponsive but has running virtual machines". Putting the host into
local maintenance on the local CLI does not help. Global maintenance does not have any
effect either. The host has been rebooted several times both locally and via the web
interface on the engine, which worked but did not resolve the issue. 
Logs:
/var/log/ovirt-engine/engine.log
2022-06-07 06:40:17,606+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-34)
[26f286ba-58d0-44be-96e0-f874057fe603] EVENT_ID: GENERIC_ERROR_MESSAGE(14,001), Cannot
switch Host to Maintenance mode.
Host still has running VMs on it and is in Non Responsive state.
2022-06-07 06:40:17,606+02 WARN 
[org.ovirt.engine.core.bll.MaintenanceNumberOfVdssCommand] (default task-34)
[26f286ba-58d0-44be-96e0-f874057fe603] Validation of action
'MaintenanceNumberOfVdss' failed for user admin@internal-authz. Reasons:
VAR__TYPE__HOST,VAR__ACTION__MAINTENANCE,VDS_CANNOT_MAINTENANCE_VDS_IS_NOT_RESPONDING_WITH_VMS,$HostNotResponding
ovirt3.os-s.de
2022-06-07 06:41:23,974+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-33) [] EVENT_ID:
VDS_BROKER_COMMAND_FAILURE(10,802), VDSM ovirt3.os-s.de command Get Host Capabilities
failed: Message timeout which can be caused by communication issues
2022-06-07 06:41:23,974+02 ERROR
[org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring]
(EE-ManagedThreadFactory-engineScheduled-Thread-33) [] Unable to RefreshCapabilities:
VDSNetworkException: VDSGenericException: VDSNetworkException: Message timeout which can
be caused by communication issues
2022-06-07 06:44:47,033+02 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-4) [] EVENT_ID:
VDS_BROKER_COMMAND_FAILURE(10,802), VDSM ovirt3.os-s.de command Get Host Capabilities
failed: Message timeout which can be caused by communication issues
2022-06-07 06:44:47,034+02 ERROR
[org.ovirt.engine.core.vdsbroker.monitoring.HostMonitoring]
(EE-ManagedThreadFactory-engineScheduled-Thread-4) [] Unable to RefreshCapabilities:
VDSNetworkException: VDSGenericException: VDSNetworkException: Message timeout which can
be caused by communication issues

vdsmd status:

Jun 06 08:51:09 ovirt3.os-s.de vdsm[3567]: WARN Worker blocked: <Worker name=jsonrpc/1
running <Task <JsonRpcTask {'params': {}, 'jsonrpc': '2.0',
'method': u'Host.getStats', 'id':
u'ce7ab5d1-3034-4b5a-91c5-9446e17341a2'} at 0x7fe1646563d0> timeout=60,
duration=120.00 at 0x7fe1646562d0> task#=15 at 0x7fe165f47e50>, 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 260, 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 194, in
_dynamicMethod
                                             result = fn(*methodArgs)
                                           File: "<string>", line 2, in
getStats
                                           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 1435, in getStats
                                             multipath=True)}
                                           File:
"/usr/lib/python2.7/site-packages/vdsm/host/api.py", line 79, in get_stats
                                             ret['haStats'] = _getHaInfo()
                                           File:
"/usr/lib/python2.7/site-packages/vdsm/host/api.py", line 182, in _getHaInfo
                                             stats = instance.get_all_stats(timeout=5)
                                           File:
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line
94, in get_all_stats
                                             stats = broker.get_stats_from_storage()
                                           File:
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/brokerlink.py",
line 146, in get_stats_from_storage
                                             result = self._proxy.get_stats()
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1233, in __call__
                                             return self.__send(self.__name, args)
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1591, in __request
                                             verbose=self.__verbose
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1273, in request
                                             return self.single_request(host, handler,
request_body, verbose)
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1301, in single_request
                                             self.send_content(h, request_body)
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1448, in send_content
                                             connection.endheaders(request_body)
                                           File:
"/usr/lib64/python2.7/httplib.py", line 1052, in endheaders
                                             self._send_output(message_body)
                                           File:
"/usr/lib64/python2.7/httplib.py", line 890, in _send_output
                                             self.send(msg)
                                           File:
"/usr/lib64/python2.7/httplib.py", line 852, in send
                                             self.connect()
                                           File:
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/unixrpc.py", line
60, in connect

self.sock.connect(base64.b16decode(self.host))
                                           File:
"/usr/lib64/python2.7/socket.py", line 224, in meth
                                             return getattr(self._sock,name)(*args)
Jun 06 08:51:14 ovirt3.os-s.de vdsm[3567]: WARN Worker blocked: <Worker name=periodic/0
running <Task <Operation action=<vdsm.virt.sampling.HostMonitor object at
0x7fe16457ba90> at 0x7fe16457bad0> timeout=15, duration=120.00 at 0x7fe1644c3910>
task#=22 at 0x7fe1646e4550>, 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 260, 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/vdsm/virt/periodic.py", line 186, in __call__
                                             self._func()
                                           File:
"/usr/lib/python2.7/site-packages/vdsm/virt/sampling.py", line 481, in __call__
                                             stats = hostapi.get_stats(self._cif,
self._samples.stats())
                                           File:
"/usr/lib/python2.7/site-packages/vdsm/host/api.py", line 79, in get_stats
                                             ret['haStats'] = _getHaInfo()
                                           File:
"/usr/lib/python2.7/site-packages/vdsm/host/api.py", line 182, in _getHaInfo
                                             stats = instance.get_all_stats(timeout=5)
                                           File:
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/client/client.py", line
94, in get_all_stats
                                             stats = broker.get_stats_from_storage()
                                           File:
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/brokerlink.py",
line 146, in get_stats_from_storage
                                             result = self._proxy.get_stats()
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1233, in __call__
                                             return self.__send(self.__name, args)
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1591, in __request
                                             verbose=self.__verbose
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1273, in request
                                             return self.single_request(host, handler,
request_body, verbose)
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1301, in single_request
                                             self.send_content(h, request_body)
                                           File:
"/usr/lib64/python2.7/xmlrpclib.py", line 1448, in send_content
                                             connection.endheaders(request_body)
                                           File:
"/usr/lib64/python2.7/httplib.py", line 1052, in endheaders
                                             self._send_output(message_body)
                                           File:
"/usr/lib64/python2.7/httplib.py", line 890, in _send_output
                                             self.send(msg)
                                           File:
"/usr/lib64/python2.7/httplib.py", line 852, in send
                                             self.connect()
                                           File:
"/usr/lib/python2.7/site-packages/ovirt_hosted_engine_ha/lib/unixrpc.py", line
60, in connect

self.sock.connect(base64.b16decode(self.host))
                                           File:
"/usr/lib64/python2.7/socket.py", line 224, in meth
                                             return getattr(self._sock,name)(*args)

vdsmd log:
2022-06-07 05:02:13,717+0000 INFO  (jsonrpc/3) [vdsm.api] FINISH multipath_health
return={} from=::1,54704, task_id=169b447f-fd52-4a6f-9277-eff9870ffb81 (api:54)
2022-06-07 05:02:13,725+0000 INFO  (jsonrpc/3) [api.host] FINISH getStats
return={'status': {'message': 'Done', 'code': 0},
'info': {'cpuStatistics': {'20': {'cpuUser':
'0.07', 'nodeIndex': 1, 'cpuSys': '0.00',
'cpuIdle': '99.93'}, '21': {'cpuUser': '0.00',
'nodeIndex': 1, 'cpuSys': '0.00', 'cpuIdle':
'100.00'}, '22': {'cpuUser': '0.00', 'nodeIndex':
1, 'cpuSys': '0.00', 'cpuIdle': '100.00'}, '23':
{'cpuUser': '0.00', 'nodeIndex': 1, 'cpuSys':
'0.07', 'cpuIdle': '99.93'}, '1': {'cpuUser':
'0.87', 'nodeIndex': 0, 'cpuSys': '0.60',
'cpuIdle': '98.53'}, '0': {'cpuUser': '0.40',
'nodeIndex': 0, 'cpuSys': '0.27', 'cpuIdle':
'99.33'}, '3': {'cpuUser': '0.27', 'nodeIndex': 0,
'cpuSys': '0.33', 'cpuIdle': '99.40'}, '2':
{'cpuUser': '0.53', 'nodeIndex': 0, 'cpuSys':
'0.40', 'cpuIdle': '99.07'}, '5': {'cpuUser':
'0.33', 'nodeIndex': 0, 'cpuSys': '0.33',
'cpuIdle': '99.34'}, '4': {'cpuUser': '0.33',
'nodeIndex': 0, 'cpuSys': '0.40', 'cpuIdle':
'99.27'}, '7': {'cpuUser': '0.13', 'nodeIndex': 1,

 'cpuSys': '0.07', 'cpuIdle': '99.80'}, '6':
{'cpuUser': '0.13', 'nodeIndex': 1, 'cpuSys':
'0.07', 'cpuIdle': '99.80'}, '9': {'cpuUser':
'0.13', 'nodeIndex': 1, 'cpuSys': '0.13',
'cpuIdle': '99.74'}, '8': {'cpuUser': '0.07',
'nodeIndex': 1, 'cpuSys': '0.13', 'cpuIdle':
'99.80'}, '11': {'cpuUser': '0.20', 'nodeIndex':
1, 'cpuSys': '0.13', 'cpuIdle': '99.67'}, '10':
{'cpuUser': '0.20', 'nodeIndex': 1, 'cpuSys':
'0.27', 'cpuIdle': '99.53'}, '13': {'cpuUser':
'0.80', 'nodeIndex': 0, 'cpuSys': '0.47',
'cpuIdle': '98.73'}, '12': {'cpuUser': '0.00',
'nodeIndex': 0, 'cpuSys': '0.00', 'cpuIdle':
'100.00'}, '15': {'cpuUser': '0.07', 'nodeIndex':
0, 'cpuSys': '0.00', 'cpuIdle': '99.93'}, '14':
{'cpuUser': '0.20', 'nodeIndex': 0, 'cpuSys':
'0.27', 'cpuIdle': '99.53'}, '17': {'cpuUser':
'0.07', 'nodeIndex': 0, 'cpuSys': '0.00',
'cpuIdle': '99.93'}, '16': {'cpuUser': '0.07',
'nodeIndex': 0, 'cpuSys': '0.00', 'cpuIdle':
'99.93'}, '19': {'cpuUser': '1.46', 'nodeIndex':
1, 'cpuSys': '0.33', 'cpuIdle'
 : '98.21'}, '18': {'cpuUser': '0.27',
'nodeIndex': 1, 'cpuSys': '0.07', 'cpuIdle':
'99.66'}}, 'numaNodeMemFree': {'1': {'memPercent': 18,
'memFree': '52935'}, '0': {'memPercent': 17,
'memFree': '53551'}}, 'memShared': 0, 'haScore': 0,
'thpState': 'always', 'ksmMergeAcrossNodes': True,
'vmCount': 3, 'memUsed': '3', 'storageDomains': {},
'incomingVmMigrations': 0, 'network': {'bond0':
{'rxErrors': '0', 'txErrors': '0', 'speed':
'2000', 'rxDropped': '4', 'name': 'bond0',
'tx': '84766340728', 'txDropped': '0', 'duplex':
'full', 'sampleTime': 1654578133.717023, 'rx':
'102755561238', 'state': 'up'}, 'eno50':
{'rxErrors': '0', 'txErrors': '0', 'speed':
'1000', 'rxDropped': '0', 'name': 'eno50',
'tx': '0', 'txDropped': '0', 'duplex':
'unknown', 'sampleTime': 1654578133.717023, 'rx': '0',
'state': 'down'}, ';vdsmdummy;': {'rxErrors': '0',
'txErrors': '0', 'speed': '1000', 'rxDropped':
'0', 'name': ';vdsmdummy;', 'tx': '0',
'txDropped': '0', 'duplex': 'unknown',
'sampleTime': 1654578133.71702
 3, 'rx': '0', 'state': 'down'}, 'ovirtmgmt':
{'rxErrors': '0', 'txErrors': '0', 'speed':
'1000', 'rxDropped': '122', 'name': 'ovirtmgmt',
'tx': '81789466633', 'txDropped': '0', 'duplex':
'unknown', 'sampleTime': 1654578133.717023, 'rx':
'99028291927', 'state': 'up'}, 'lo': {'rxErrors':
'0', 'txErrors': '0', 'speed': '1000',
'rxDropped': '0', 'name': 'lo', 'tx':
'10214215104', 'txDropped': '0', 'duplex':
'unknown', 'sampleTime': 1654578133.717023, 'rx':
'10214215104', 'state': 'up'}, 'ovs-system':
{'rxErrors': '0', 'txErrors': '0', 'speed':
'1000', 'rxDropped': '0', 'name': 'ovs-system',
'tx': '0', 'txDropped': '0', 'duplex':
'unknown', 'sampleTime': 1654578133.717023, 'rx': '0',
'state': 'down'}, 'eno49': {'rxErrors': '0',
'txErrors': '0', 'speed': '1000', 'rxDropped':
'0', 'name': 'eno49', 'tx': '0',
'txDropped': '0', 'duplex': 'unknown',
'sampleTime': 1654578133.717023, 'rx': '0', 'state':
'down'}, 'br-int': {'rxErrors': '0', 'txErrors':
'0', 'speed': '1000', 'rxDropped': '0', 'na
 me': 'br-int', 'tx': '0', 'txDropped': '0',
'duplex': 'unknown', 'sampleTime': 1654578133.717023,
'rx': '0', 'state': 'down'}, 'eno1':
{'rxErrors': '0', 'txErrors': '0', 'speed':
'1000', 'rxDropped': '0', 'name': 'eno1',
'tx': '0', 'txDropped': '0', 'duplex':
'unknown', 'sampleTime': 1654578133.717023, 'rx': '0',
'state': 'down'}, 'eno2': {'rxErrors': '0',
'txErrors': '0', 'speed': '1000', 'rxDropped':
'0', 'name': 'eno2', 'tx': '0',
'txDropped': '0', 'duplex': 'unknown',
'sampleTime': 1654578133.717023, 'rx': '0', 'state':
'down'}, 'eno3': {'rxErrors': '0', 'txErrors':
'0', 'speed': '1000', 'rxDropped': '1',
'name': 'eno3', 'tx': '42493183527', 'txDropped':
'0', 'duplex': 'full', 'sampleTime': 1654578133.717023,
'rx': '20793574', 'state': 'up'}, 'eno4':
{'rxErrors': '0', 'txErrors': '0', 'speed':
'1000', 'rxDropped': '1', 'name': 'eno4',
'tx': '42273157201', 'txDropped': '0', 'duplex':
'full', 'sampleTime': 1654578133.717023, 'rx':
'102734767664', 'state': 'up'}, 'genev_sys_6081': 
 {'rxErrors': '0', 'txErrors': '8', 'speed':
'1000', 'rxDropped': '0', 'name':
'genev_sys_6081', 'tx': '0', 'txDropped': '0',
'duplex': 'unknown', 'sampleTime': 1654578133.717023,
'rx': '0', 'state': 'up'}}, 'txDropped':
'128', 'anonHugePages': '326', 'ksmPages': 100,
'elapsedTime': '391.12', 'cpuLoad': '0.16',
'cpuSys': '0.18', 'diskStats': {'/var/log':
{'free': '6478'}, '/var/run/vdsm/': {'free':
'64294'}, '/tmp': {'free': '906'}},
'cpuUserVdsmd': '0.47', 'netConfigDirty': 'False',
'memCommitted': 28672, 'ksmState': False, 'vmMigrating': 0,
'ksmCpu': 0, 'memAvailable': 126975, 'bootTime':
'1654505219', 'haStats': {'active': True, 'configured':
True, 'score': 0, 'localMaintenance': True, 'globalMaintenance':
False}, 'momStatus': 'active', 'multipathHealth': {},
'rxDropped': '0', 'outgoingVmMigrations': 0, 'swapTotal':
32191, 'swapFree': 32191, 'hugepages': defaultdict(<type
'dict'>, {1048576: {'resv_hugepages': 0, 'free_hugepages': 0,
'nr_overcommit_hugepages': 0, 'surplus_hugepages
 ': 0, 'vm.free_hugepages': 0, 'nr_hugepages': 0,
'nr_hugepages_mempolicy': 0}, 2048: {'resv_hugepages': 0,
'free_hugepages': 0, 'nr_overcommit_hugepages': 0,
'surplus_hugepages': 0, 'vm.free_hugepages': 0, 'nr_hugepages': 0,
'nr_hugepages_mempolicy': 0}}), 'dateTime': '2022-06-07T05:02:13
GMT', 'cpuUser': '0.27', 'memFree': 126719, 'cpuIdle':
'99.55', 'vmActive': 0, 'v2vJobs': {}, 'cpuSysVdsmd':
'0.13'}} from=::1,54704 (api:54)
2022-06-07 05:02:13,726+0000 INFO  (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call
Host.getStats succeeded in 0.03 seconds (__init__:312)
2022-06-07 05:02:13,973+0000 INFO  (vmrecovery) [vdsm.api] START
getConnectedStoragePoolsList(options=None) from=internal,
task_id=65629949-c74d-4f66-846a-1e2c40be9157 (api:48)
2022-06-07 05:02:13,973+0000 INFO  (vmrecovery) [vdsm.api] FINISH
getConnectedStoragePoolsList return={'poollist': []} from=internal,
task_id=65629949-c74d-4f66-846a-1e2c40be9157 (api:54)
2022-06-07 05:02:13,973+0000 INFO  (vmrecovery) [vds] recovery: waiting for storage pool
to go up (clientIF:723)
2022-06-07 05:02:14,468+0000 INFO  (jsonrpc/4) [jsonrpc.JsonRpcServer] RPC call Host.ping2
succeeded in 0.00 seconds (__init__:312)
2022-06-07 05:02:14,471+0000 INFO  (jsonrpc/5) [vdsm.api] START
repoStats(domains=[u'5d6276cc-08ab-47f6-81e7-4e64aac3d386']) from=::1,54704,
task_id=6918f715-bbf4-4c7f-af00-1764294ab665 (api:48)
2022-06-07 05:02:14,472+0000 INFO  (jsonrpc/5) [vdsm.api] FINISH repoStats return={}
from=::1,54704, task_id=6918f715-bbf4-4c7f-af00-1764294ab665 (api:54)
2022-06-07 05:02:14,472+0000 INFO  (jsonrpc/5) [jsonrpc.JsonRpcServer] RPC call
Host.getStorageRepoStats succeeded in 0.00 seconds (__init__:312)

Gluster volumes are all online.

systemctl status ovirt-ha-broker:
Jun 06 08:47:08 ovirt3.os-s.de systemd[1]: Started oVirt Hosted Engine High Availability
Communications Broker.
Jun 06 08:47:59 ovirt3.os-s.de ovirt-ha-broker[1524]: ovirt-ha-broker
mgmt_bridge.MgmtBridge ERROR Failed to getVdsStats: No 'network' in result

Any ideas? 

Ralf

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

[ovirt-users] Hyperconverged Ovirt 4.3.10.4: Unresponsive Host