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@extraordy.com.