iscsid initialization failure

[Corey Bryant]

In the gate we are very frequently tripping over the following tempest failure with
tempest.api.compute.volumes.test_attach_volume.AttachVolumeTestJSON.test_list_get_volume_attachments: .

Traceback (most recent call last):
  File "/home/ubuntu/snap/microstack-test/3/.rally/verification/verifier-05c0b896-ce38-4b0b-9547-01a84ca98a3c/repo/tempest/api/compute/volumes/test_attach_volume.py", line 171, in test_list_get_volume_attachment
s
    self.volumes_client, attachment['volumeId'], 'available')
  File "/home/ubuntu/snap/microstack-test/3/.rally/verification/verifier-05c0b896-ce38-4b0b-9547-01a84ca98a3c/repo/tempest/common/waiters.py", line 221, in wait_for_volume_resource_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: volume aacda34c-a1b6-40c6-b8f7-430bd4a945d4 failed to reach available status (current detaching) within the required time (300 s).

Manually creating a volume works ok. Attaching the volume to an instance doesn't fail on the CLI. Inspecting the server, it doesn't show any attached volumes for the instance. Things work fine after restarting snap.microstack.iscsid.service.

More details from iscsid inspection:

● snap.microstack.iscsid.service - Service for snap application microstack.iscsid
   Loaded: loaded (/etc/systemd/system/snap.microstack.iscsid.service; enabled; vendor preset: enabled)
   Active: active (running) since Fri 2021-03-05 21:59:03 UTC; 3h 2min ago
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/snap.microstack.iscsid.service
           ├─2525 /snap/microstack/x1/sbin/iscsid -p /var/snap/microstack/common/var/run/iscsid.pid --initiatorname=/var/snap/microstack/common/etc/iscsi/initiatorname.iscsi --config=/var/snap/microstack/common/etc/iscsi/iscsid.conf
           └─2533 /snap/microstack/x1/sbin/iscsid -p /var/snap/microstack/common/var/run/iscsid.pid --initiatorname=/var/snap/microstack/common/etc/iscsi/initiatorname.iscsi --config=/var/snap/microstack/common/etc/iscsi/iscsid.conf

Mar 05 22:06:58 b1 iscsid[2525]: unsupported opcode 0x23
Mar 05 22:06:58 b1 iscsid[2525]: unsupported opcode 0x23
Mar 05 22:07:04 b1 iscsid[2525]: Connection2:0 to [target: iqn.2010-10.org.openstack:volume-6c7d627c-b0e0-4d89-90a0-a06e5eedc3f3, portal: 10.5.0.15,3260] through [iface: default] is operational now
Mar 05 22:07:28 b1 iscsid[2525]: Received iferror -22: Invalid argument.
Mar 05 22:07:28 b1 iscsid[2525]: can not safely destroy session 1
Mar 05 22:07:28 b1 iscsid[2525]: Received iferror -22: Invalid argument.
Mar 05 22:07:28 b1 iscsid[2525]: can not safely destroy session 1
Mar 05 22:07:28 b1 iscsid[2525]: BUG: Could not shutdown session.
Mar 05 22:07:43 b1 iscsid[2525]: Received iferror -22: Invalid argument.
Mar 05 22:07:43 b1 iscsid[2525]: can not safely destroy session 1

ubuntu@b1:~/microstack$ journalctl -u snap.microstack.iscsid
-- Logs begin at Fri 2021-03-05 19:59:49 UTC, end at Sat 2021-03-06 01:06:26 UTC. --
Mar 05 21:59:02 b1 systemd[1]: Starting Service for snap application microstack.iscsid...
Mar 05 21:59:03 b1 iscsid[2426]: iSCSI logger with pid=2525 started!
Mar 05 21:59:03 b1 systemd[1]: Started Service for snap application microstack.iscsid.
Mar 05 21:59:04 b1 iscsid[2525]: iSCSI daemon with pid=2533 started!
Mar 05 22:06:56 b1 iscsid[2525]: Connection1:0 to [target: iqn.2010-10.org.openstack:volume-aacda34c-a1b6-40c6-b8f7-430bd4a945d4, portal: 10.5.0.15,3260] through [iface: default] is operational now
Mar 05 22:06:58 b1 iscsid[2525]: unsupported opcode 0x23
Mar 05 22:06:58 b1 iscsid[2525]: unsupported opcode 0x23
Mar 05 22:06:58 b1 iscsid[2525]: unsupported opcode 0x23
Mar 05 22:06:58 b1 iscsid[2525]: unsupported opcode 0x23
Mar 05 22:07:04 b1 iscsid[2525]: Connection2:0 to [target: iqn.2010-10.org.openstack:volume-6c7d627c-b0e0-4d89-90a0-a06e5eedc3f3, portal: 10.5.0.15,3260] through [iface: default] is operational now
Mar 05 22:07:28 b1 iscsid[2525]: Received iferror -22: Invalid argument.
Mar 05 22:07:28 b1 iscsid[2525]: can not safely destroy session 1
Mar 05 22:07:28 b1 iscsid[2525]: Received iferror -22: Invalid argument.
Mar 05 22:07:28 b1 iscsid[2525]: can not safely destroy session 1
Mar 05 22:07:28 b1 iscsid[2525]: BUG: Could not shutdown session.
Mar 05 22:07:43 b1 iscsid[2525]: Received iferror -22: Invalid argument.
Mar 05 22:07:43 b1 iscsid[2525]: can not safely destroy session 1