Hi,
I have an ovirt 4.4.3 with 2 clusters, hosted engine and iscsi storage.
First cluster, composed of 2 servers (host1 and host2), is dedicated to the
hosted engine, the second cluster is for vms. Furthermore, there is a SAN
with 3 luns: one for hosted engine storage, one for vms and one unused. My
SAN is built on top of a pacemaker/drbd cluster with 2 nodes with a virtual
ip used as iscsi Portal IP. Starting from today, after a failover of the
iscsi cluster, I'm unable to start the hosted engine. It seems that there
is some problem with storage.
Actually I have only one node (host1) running in the cluster. It seems
there is some lock on lvs, but I'm not sure of this.
Here are some details about the problem:
1. iscsiadm -m session
iSCSI Transport Class version 2.0-870
version 6.2.0.878-2
Target: iqn.2003-01.org.linux-iscsi.s1-node1.x8664:sn.2a734f67d5b1
(non-flash)
Current Portal: 10.3.8.8:3260,1
Persistent Portal: 10.3.8.8:3260,1
**********
Interface:
**********
Iface Name: default
Iface Transport: tcp
Iface Initiatorname: iqn.1994-05.com.redhat:4b668221d9a9
Iface IPaddress: 10.3.8.10
Iface HWaddress: default
Iface Netdev: default
SID: 1
iSCSI Connection State: LOGGED IN
iSCSI Session State: LOGGED_IN
Internal iscsid Session State: NO CHANGE
*********
Timeouts:
*********
Recovery Timeout: 5
Target Reset Timeout: 30
LUN Reset Timeout: 30
Abort Timeout: 15
*****
CHAP:
*****
username: <empty>
password: ********
username_in: <empty>
password_in: ********
************************
Negotiated iSCSI params:
************************
HeaderDigest: None
DataDigest: None
MaxRecvDataSegmentLength: 262144
MaxXmitDataSegmentLength: 262144
FirstBurstLength: 65536
MaxBurstLength: 262144
ImmediateData: Yes
InitialR2T: Yes
MaxOutstandingR2T: 1
************************
Attached SCSI devices:
************************
Host Number: 7 State: running
scsi7 Channel 00 Id 0 Lun: 0
Attached scsi disk sdb State: running
scsi7 Channel 00 Id 0 Lun: 1
Attached scsi disk sdc State: running
2. vdsm.log errors:
2020-11-27 18:37:16,786+0100 INFO (jsonrpc/0) [api] FINISH getStats
error=Virtual machine does not exist: {'vmId':
'f3a1194d-0632-43c6-8e12-7f22518cff87'} (api:129)
.....
2020-11-27 18:37:52,864+0100 INFO (jsonrpc/4) [vdsm.api] FINISH
getVolumeInfo error=(-223, 'Sanlock resource read failure', 'Lease does not
exist on storage') from=::1,60880,
task_id=138a3615-d537-4e5f-a39c-335269ad0917 (api:52)
2020-11-27 18:37:52,864+0100 ERROR (jsonrpc/4) [storage.TaskManager.Task]
(Task='138a3615-d537-4e5f-a39c-335269ad0917') Unexpected error (task:880)
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 887,
in _run
return fn(*args, **kargs)
File "<decorator-gen-159>", line 2, in getVolumeInfo
File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in
method
ret = func(*args, **kwargs)
File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 3142,
in getVolumeInfo
info = self._produce_volume(sdUUID, imgUUID, volUUID).getInfo()
File "/usr/lib/python3.6/site-packages/vdsm/storage/volume.py", line 258,
in getInfo
leasestatus = self.getLeaseStatus()
File "/usr/lib/python3.6/site-packages/vdsm/storage/volume.py", line 203,
in getLeaseStatus
self.volUUID)
File "/usr/lib/python3.6/site-packages/vdsm/storage/sd.py", line 549, in
inquireVolumeLease
return self._domainLock.inquire(lease)
File "/usr/lib/python3.6/site-packages/vdsm/storage/clusterlock.py", line
464, in inquire
sector=self._block_size)
sanlock.SanlockException: (-223, 'Sanlock resource read failure', 'Lease
does not exist on storage')
2020-11-27 18:37:52,865+0100 INFO (jsonrpc/4) [storage.TaskManager.Task]
(Task='138a3615-d537-4e5f-a39c-335269ad0917') aborting: Task is aborted:
"value=(-223, 'Sanlock resource read failure', 'Lease does not exist on
storage') abortedcode=100" (task:1190)
3. supervdsm.log
MainProcess|monitor/de4645f::DEBUG::2020-11-27
18:41:25,286::commands::153::common.commands::(start) /usr/bin/taskset
--cpu-list 0-11 /usr/sbin/dmsetup remove
de4645fc--f379--4837--916b--a0c2b89927d9-dfa4e933--2b9c--4057--a4c5--aa4485b070e9
(cwd None)
MainProcess|monitor/de4645f::DEBUG::2020-11-27
18:41:25,293::commands::98::common.commands::(run) FAILED: <err> =
b'device-mapper: remove ioctl on
de4645fc--f379--4837--916b--a0c2b89927d9-dfa4e933--2b9c--4057--a4c5--aa4485b070e9
failed: Device or resource busy\nCommand failed.\n'; <rc> = 1
MainProcess|monitor/de4645f::ERROR::2020-11-27
18:41:25,294::supervdsm_server::97::SuperVdsm.ServerCallback::(wrapper)
Error in devicemapper_removeMapping
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/vdsm/storage/devicemapper.py",
line 141, in removeMapping
commands.run(cmd)
File "/usr/lib/python3.6/site-packages/vdsm/common/commands.py", line
101, in run
raise cmdutils.Error(args, p.returncode, out, err)
vdsm.common.cmdutils.Error: Command ['/usr/sbin/dmsetup', 'remove',
'de4645fc--f379--4837--916b--a0c2b89927d9-dfa4e933--2b9c--4057--a4c5--aa4485b070e9']
failed with rc=1 out=b'' err=b'device-mapper: remove ioctl on
de4645fc--f379--4837--916b--a0c2b89927d9-dfa4e933--2b9c--4057--a4c5--aa4485b070e9
failed: Device or resource busy\nCommand failed.\n'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/vdsm/supervdsm_server.py", line
95, in wrapper
res = func(*args, **kwargs)
File
"/usr/lib/python3.6/site-packages/vdsm/supervdsm_api/devicemapper.py", line
29, in devicemapper_removeMapping
return devicemapper.removeMapping(deviceName)
File "/usr/lib/python3.6/site-packages/vdsm/storage/devicemapper.py",
line 143, in removeMapping
raise Error("Could not remove mapping: {}".format(e))
vdsm.storage.devicemapper.Error: Could not remove mapping: Command
['/usr/sbin/dmsetup', 'remove',
'de4645fc--f379--4837--916b--a0c2b89927d9-dfa4e933--2b9c--4057--a4c5--aa4485b070e9']
failed with rc=1 out=b'' err=b'device-mapper: remove ioctl on
de4645fc--f379--4837--916b--a0c2b89927d9-dfa4e933--2b9c--4057--a4c5--aa4485b070e9
failed: Device or resource busy\nCommand failed.\n'
4. /var/log/messages:
...
Nov 27 18:43:46 host1 journal[20573]: ovirt-ha-agent
ovirt_hosted_engine_ha.agent.hosted_engine.HostedEngine ERROR Failed to
start necessary monitors
Nov 27 18:43:46 host1 journal[20573]: ovirt-ha-agent
ovirt_hosted_engine_ha.agent.agent.Agent ERROR Traceback (most recent call
last):#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/lib/brokerlink.py",
line 85, in start_monitor#012 response = self._proxy.start_monitor(type,
options)#012 File "/usr/lib64/python3.6/xmlrpc/client.py", line 1112, in
__call__#012 return self.__send(self.__name, args)#012 File
"/usr/lib64/python3.6/xmlrpc/client.py", line 1452, in __request#012
verbose=self.__verbose#012 File "/usr/lib64/python3.6/xmlrpc/client.py",
line 1154, in request#012 return self.single_request(host, handler,
request_body, verbose)#012 File "/usr/lib64/python3.6/xmlrpc/client.py",
line 1166, in single_request#012 http_conn = self.send_request(host,
handler, request_body, verbose)#012 File
"/usr/lib64/python3.6/xmlrpc/client.py", line 1279, in send_request#012
self.send_content(connection, request_body)#012 File
"/usr/lib64/python3.6/xmlrpc/client.py", line 1309, in send_content#012
connection.endheaders(request_body)#012 File
"/usr/lib64/python3.6/http/client.py", line 1249, in endheaders#012
self._send_output(message_body, encode_chunked=encode_chunked)#012 File
"/usr/lib64/python3.6/http/client.py", line 1036, in _send_output#012
self.send(msg)#012 File "/usr/lib64/python3.6/http/client.py", line 974,
in send#012 self.connect()#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/lib/unixrpc.py",
line 74, in connect#012
self.sock.connect(base64.b16decode(self.host))#012FileNotFoundError:
[Errno 2] No such file or directory#012#012During handling of the above
exception, another exception occurred:#012#012Traceback (most recent call
last):#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/agent/agent.py",
line 131, in _run_agent#012 return action(he)#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/agent/agent.py",
line 55, in action_proper#012 return he.start_monitoring()#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/agent/hosted_engine.py",
line 437, in start_monitoring#012 self._initialize_broker()#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/agent/hosted_engine.py",
line 561, in _initialize_broker#012 m.get('options', {}))#012 File
"/usr/lib/python3.6/site-packages/ovirt_hosted_engine_ha/lib/brokerlink.py",
line 91, in start_monitor#012 ).format(t=type, o=options,
e=e)#012ovirt_hosted_engine_ha.lib.exceptions.RequestError: brokerlink -
failed to start monitor via ovirt-ha-broker: [Errno 2] No such file or
directory, [monitor: 'network', options: {'addr': '10.3.7.1',
'network_test': 'dns', 'tcp_t_address': '', 'tcp_t_port': ''}]
Nov 27 18:43:46 host1 journal[20573]: ovirt-ha-agent
ovirt_hosted_engine_ha.agent.agent.Agent ERROR Trying to restart agent
Nov 27 18:43:46 host1 systemd[1]: ovirt-ha-agent.service: Main process
exited, code=exited, status=157/n/a
Nov 27 18:43:46 host1 systemd[1]: ovirt-ha-agent.service: Failed with
result 'exit-code'.
....
Please, let me know if other logs are needed.
Thank you
--
Ai sensi dell'articolo 13 del Regolamento UE, n. 2016/679 (GDPR) si informa
che Titolare del trattamento dei Suoi dati personali, anche particolari,
compreso l'indirizzo di posta elettronica, è la EXTRAORDY S.r.l.. E'
possibile revocare il consenso in qualsiasi momento senza pregiudicare la
liceità del trattamento basata sul consenso prestato prima della revoca,
nonché proporre reclamo all'Autorità di controllo. Agli interessati sono
riconosciuti i diritti di cui agli artt. 15 ss. del Regolamento UE, n.
2016/679 e in particolare di chiedere al titolare del trattamento l'accesso
ai dati personali e la rettifica o la cancellazione degli stessi o la
limitazione del trattamento o la portabilità dei dati che lo riguardano o
di opporsi al loro trattamento rivolgendo le richieste inviando un
messaggio al seguente indirizzo e-mail privacy(a)extraordy.com.
