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

--