Lock errors in iscsi gateway
Hi; I've build two iscsi gateway for our (small) ceph cluster.The cluster is a nautilus installation, 4 nodes with 9x4TB each, and it's working fine. We mainly use it via s3 object storage interface, but I've deployed also some rbd block devices and a cephfs filesystem. Now I'm trying to connect it to my xenserver installation. Xenserver doesn't speak rados, so I've build the iscsi gateways. Right now they are self-hosted on the xenserver, with plan to move them into physical boxes if/when needed. The gateways are build on centos8, tcmu-runner just cloned from git (I think it's 1.5.2). I've been able to connect them to our six nodes xenserver cluster, and now I'm trying to use it. When I attempt a migration of a VM disk, on the new iscsi volume, I've got these messages on the logfile that I find very worrying: Apr 27 17:32:21 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:22 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:22 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:25 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:25 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:26 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:26 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:27 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:27 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:28 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:28 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:29 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:29 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:30 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:30 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:31 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:31 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:32 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:32 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:33 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:33 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:34 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:34 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:36 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. After a while the migration fails, and I keep seend the error on the logs: Apr 27 17:36:01 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:06 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:08 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:09 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:16 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:21 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:21 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:26 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:28 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:29 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:36 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Any hints? Is this a bug? -- *Simone Lazzaris* *Qcom S.p.A. a socio unico* simone.lazzaris@qcom.it[1] | www.qcom.it[2] * LinkedIn[3]* | *Facebook[4]* [5]
On 4/27/20 10:43 AM, Simone Lazzaris wrote:
Hi;
I've build two iscsi gateway for our (small) ceph cluster.The cluster is a nautilus installation, 4 nodes with 9x4TB each, and it's working fine. We mainly use it via s3 object storage interface, but I've deployed also some rbd block devices and a cephfs filesystem.
Now I'm trying to connect it to my xenserver installation. Xenserver doesn't speak rados, so I've build the iscsi gateways. Right now they are self-hosted on the xenserver, with plan to move them into physical boxes if/when needed.
The gateways are build on centos8, tcmu-runner just cloned from git (I think it's 1.5.2). I've been able to connect them to our six nodes xenserver cluster, and now I'm trying to use it.
Are you using the ceph-iscsi tools with tcmu-runner or did you setup tcmu-runner directly with targetcli?
When I attempt a migration of a VM disk, on the new iscsi volume, I've got these messages on the logfile that I find very worrying:
Apr 27 17:32:21 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:22 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:22 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 You would see these:
1. when paths are discovered initially. The initiator is sending IO to all paths at the same time, so the lock is bouncing between all the paths. You should only see this for 10-60 seconds depending on how many paths you have, number of nodes, etc. When the multipath layer kicks in and adds the paths to the dm-multipath device then they should stop. 2. during failover/failback when the multipath layer switches paths and one path takes the lock from the previously used one. Or, if you exported a disk to multiple initiator nodes, and some initiator nodes can't reach the active optimized path, so some initiators are using the optimized path and some are using the non-optimized path. 3. If you have misconfigured the system. If you used active/active or had initiator nodes discover different paths for the same disk or not log into all the paths.
Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:23 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:25 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:25 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:26 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:26 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:27 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:27 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:28 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:28 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:29 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:29 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:30 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:30 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:31 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:31 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:32 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:32 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:33 iscsi2 tcmu-runner[2344]: tcmu_notify_lock_lost:222 rbd/rbdindex0.scsidisk0: Async lock drop. Old state 1 Apr 27 17:32:33 iscsi2 tcmu-runner[2344]: alua_implicit_transition:574 rbd/ rbdindex0.scsidisk0: Starting lock acquisition operation. Apr 27 17:32:34 iscsi2 tcmu-runner[2344]: tcmu_rbd_lock:762 rbd/rbdindex0.scsidisk0: Acquired exclusive lock. Apr 27 17:32:34 iscsi2 tcmu-runner[2344]: tcmu_acquire_dev_lock:441 rbd/ rbdindex0.scsidisk0: Lock acquisition successful Apr 27 17:32:36 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown.
After a while the migration fails, and I keep seend the error on the logs:
Apr 27 17:36:01 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown.
What are you using for path_checker in /etc/multipath.conf on the initiator side? This is a bug but can be ignored. I am working on a fix. Basically, we the multipath layer is checking our state. We report we do not have the lock correctly to the initiator, but we also get this log message over and over when the multipath layer sends its path checker command.
Apr 27 17:36:06 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:08 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:09 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:16 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:21 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:21 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:26 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:28 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:29 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. Apr 27 17:36:36 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown.
Any hints? Is this a bug? -- *Simone Lazzaris* *Qcom S.p.A. a socio unico* simone.lazzaris@qcom.it[1] | www.qcom.it[2] * LinkedIn[3]* | *Facebook[4]* [5]
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
In data lunedì 27 aprile 2020 18:46:09 CEST, Mike Christie ha scritto: [snip]
Are you using the ceph-iscsi tools with tcmu-runner or did you setup tcmu-runner directly with targetcli?
I followed this guide: https://docs.ceph.com/docs/master//rbd/iscsi-target-cli/[1] and configured the target with gwcli, so I think I'm using ceph-iscsi tools. [snip]
You would see these:
1. when paths are discovered initially. The initiator is sending IO to all paths at the same time, so the lock is bouncing between all the paths.
Ok, but the nodes are already configured and all path discovered. So that's not the case.
You should only see this for 10-60 seconds depending on how many paths you have, number of nodes, etc. When the multipath layer kicks in and adds the paths to the dm-multipath device then they should stop.
I have NO such logs when the system is running unless I start USING the luns
2. during failover/failback when the multipath layer switches paths and one path takes the lock from the previously used one.
No failover/failback is occuring.
Or, if you exported a disk to multiple initiator nodes, and some initiator nodes can't reach the active optimized path, so some initiators are using the optimized path and some are using the non-optimized path.
I do have exported the disk to multiple initiator nodes. How can I tell if they are using all the active path?
3. If you have misconfigured the system. If you used active/active or had initiator nodes discover different paths for the same disk or not log into all the paths.
That may be the case, as I don't have much experience with multipath. Anyway, following the ceph guide, I've setup the device in /etc/multipath.conf like this: device { vendor "LIO-ORG" product ".*" path_grouping_policy "failover" path_selector "queue-length 0" path_checker "tur" hardware_handler "1 alua" prio "alua" prio_args "exclusive_pref_bit" failback 60 no_path_retry "queue" fast_io_fail_tmo 25 } and multipath -ll show this on all the six nodes: 36001405d7480e5f84b94ab19ebeebd6c dm-1 LIO-ORG ,TCMU device size=1.0T features='1 queue_if_no_path' hwhandler='1 alua' wp=rw |-+- policy='queue-length 0' prio=50 status=active | `- 16:0:0:0 sdb 8:16 active ready running `-+- policy='queue-length 0' prio=10 status=enabled `- 15:0:0:0 sdc 8:32 active ready running Al all nodes, one path (sdb 8:16) is always "active" with prio 50 and the other (sdc 8:32) is always "enabled" with prio 10. I haven't figured out how can I check which iscsi-gateway is mapped to the "active" path... [snip]
Apr 27 17:36:01 iscsi2 tcmu-runner[2344]: tcmu_rbd_has_lock:516 rbd/rbdindex0.scsidisk0: Could not check lock ownership. Error: Cannot send after transport endpoint shutdown. What are you using for path_checker in /etc/multipath.conf on the initiator side?
path_checker is set to "tur".
This is a bug but can be ignored. I am working on a fix. Basically, we the multipath layer is checking our state. We report we do not have the lock correctly to the initiator, but we also get this log message over and over when the multipath layer sends its path checker command.
And that's ok... Thanks for all the help you can provide! *Simone Lazzaris* *Qcom S.p.A. a socio unico* simone.lazzaris@qcom.it[2] | www.qcom.it[3] * LinkedIn[4]* | *Facebook[5]* [6] -------- [1] https://docs.ceph.com/docs/master//rbd/iscsi-target-cli/ [2] mailto:simone.lazzaris@qcom.it [3] https://www.qcom.it [4] https://www.linkedin.com/company/qcom-spa [5] http://www.facebook.com/qcomspa [6] https://www.qcom.it/pdf/other/bannerfirmamail.gif
On 4/28/20 2:21 AM, Simone Lazzaris wrote:
In data lunedì 27 aprile 2020 18:46:09 CEST, Mike Christie ha scritto:
[snip]
Are you using the ceph-iscsi tools with tcmu-runner or did you setup
tcmu-runner directly with targetcli?
I followed this guide: https://docs.ceph.com/docs/master//rbd/iscsi-target-cli/ and configured the target with gwcli, so I think I'm using ceph-iscsi tools.
[snip]
You would see these:
1. when paths are discovered initially. The initiator is sending IO to
all paths at the same time, so the lock is bouncing between all the paths.
Ok, but the nodes are already configured and all path discovered. So that's not the case.
You should only see this for 10-60 seconds depending on how many paths
you have, number of nodes, etc. When the multipath layer kicks in and
adds the paths to the dm-multipath device then they should stop.
I have NO such logs when the system is running unless I start USING the luns
Could you send me: 1. The /var/log/messages for the initiator when you do IO and see those lock messages. 2. The output of From one of the gateways: # gwcli ls From the initiator node you send the /var/log/messages for: # iscsiadm -m session -P 3 # multipath -ll 3. version info: # uname -a If you using rpm do: # rpm -q ceph-iscsi # rpm -q tcmu-runner # rpm -q python-rtslib
2. during failover/failback when the multipath layer switches paths and
one path takes the lock from the previously used one.
No failover/failback is occuring.
Or, if you exported a disk to multiple initiator nodes, and some
initiator nodes can't reach the active optimized path, so some
initiators are using the optimized path and some are using the
non-optimized path.
I do have exported the disk to multiple initiator nodes. How can I tell if they are using all the active path?
For linux's multipath-tools prio=50 is the active optimized (AO) path. prio=10 is the active non-optimized (ANO) path. The prio=50 one should be the one with status=active. To map that to an iscsi gateway then you can do the following. If sdb is the AO one, then run iscsiadm -m session -P 3 Here you can see the sdXYZ name to iscsi session mapping. The iscsi session/connection's target IP address from that command should match to the gateway that is listed as the "owner" of the LUN in the "gwcli ls" output.
In data martedì 28 aprile 2020 18:41:27 CEST, Mike Christie ha scritto:
Could you send me:
1. The /var/log/messages for the initiator when you do IO and see those lock messages.
On the initiator (XenServer 7.1 which is based on CentOS AFAIK) the /var/log/messages is empty. I (sporadicly) see: Apr 29 09:00:36 xs-n1 systemd[1]: Starting Multipath Count Service... Apr 29 09:00:36 xs-n1 systemd[1]: Started Multipath Count Service. Apr 29 09:00:36 xs-n1 systemd[1]: Started Session 146 of user root. Apr 29 09:00:36 xs-n1 systemd[1]: Starting Session 146 of user root. Apr 29 09:00:40 xs-n1 multipathd: dm-3: remove map (uevent) Apr 29 09:00:40 xs-n1 multipathd: dm-3: devmap not registered, can't remove Apr 29 09:00:40 xs-n1 multipathd: dm-3: remove map (uevent) Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="PBD.get_all_records"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"]; Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_all_records"];
2. The output of
From one of the gateways: # gwcli ls
Attached (gwcli.txt)
From the initiator node you send the /var/log/messages for: # iscsiadm -m session -P 3
attacched (iscsi-session.txt)
# multipath -ll
36001405d7480e5f84b94ab19ebeebd6c dm-0 LIO-ORG ,TCMU device size=3.0T features='1 queue_if_no_path' hwhandler='1 alua' wp=rw |-+- policy='queue-length 0' prio=50 status=active | `- 2:0:0:0 sdc 8:32 active ready running `-+- policy='queue-length 0' prio=10 status=enabled `- 3:0:0:0 sdb 8:16 active ready running
3. version info:
# uname -a
On the Initiator: Linux xs-n1 4.4.0+2 #1 SMP Thu Jun 15 16:38:02 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux On the Target: Linux iscsi1 4.18.0-147.8.1.el8_1.x86_64 #1 SMP Thu Apr 9 13:49:54 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
If you using rpm do: # rpm -q ceph-iscsi # rpm -q tcmu-runner # rpm -q python-rtslib
No, I've installed them from source on the target
To map that to an iscsi gateway then you can do the following.
If sdb is the AO one, then run
iscsiadm -m session -P 3
Here you can see the sdXYZ name to iscsi session mapping. The iscsi session/connection's target IP address from that command should match to the gateway that is listed as the "owner" of the LUN in the "gwcli ls" output.
I see... thanks for the hint. I've done a test: I've unmapped all the drive, then mapped the first gateway (iscsi1) on all the nodes, waited, then mapped the second gateway, to be sure that all the nodes would see the first node as the active/master one. Now things seems a little better in "normal" vm use: I only see the "Cannot send after transport endpoint shutdown." on the secondary target node. I do see some hopping between the nodes when importing a disk drive, but at this point I'm starting to suspect some strange activity from the Xen infrastructure in that circumstance. -- *Simone Lazzaris* *Qcom S.p.A. a socio unico*
On 4/29/20 2:11 AM, Simone Lazzaris wrote:
In data martedì 28 aprile 2020 18:41:27 CEST, Mike Christie ha scritto:
Could you send me:
1. The /var/log/messages for the initiator when you do IO and see those
lock messages.
On the initiator (XenServer 7.1 which is based on CentOS AFAIK) the /var/log/messages is empty.
I (sporadicly) see:
Apr 29 09:00:36 xs-n1 systemd[1]: Starting Multipath Count Service...
Apr 29 09:00:36 xs-n1 systemd[1]: Started Multipath Count Service.
Apr 29 09:00:36 xs-n1 systemd[1]: Started Session 146 of user root.
Apr 29 09:00:36 xs-n1 systemd[1]: Starting Session 146 of user root.
Apr 29 09:00:40 xs-n1 multipathd: dm-3: remove map (uevent)
Apr 29 09:00:40 xs-n1 multipathd: dm-3: devmap not registered, can't remove
Apr 29 09:00:40 xs-n1 multipathd: dm-3: remove map (uevent)
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="PBD.get_all_records"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_uuid"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_name_label"];
Apr 29 09:00:40 xs-n1 mpathalert: [debug|xs-n1|2 ||mscgen] mpathalert=>xapi [label="host.get_all_records"];
2. The output of
From one of the gateways:
# gwcli ls
Attached (gwcli.txt)
From the initiator node you send the /var/log/messages for:
# iscsiadm -m session -P 3
attacched (iscsi-session.txt)
# multipath -ll
36001405d7480e5f84b94ab19ebeebd6c dm-0 LIO-ORG ,TCMU device
size=3.0T features='1 queue_if_no_path' hwhandler='1 alua' wp=rw
|-+- policy='queue-length 0' prio=50 status=active
| `- 2:0:0:0 sdc 8:32 active ready running
`-+- policy='queue-length 0' prio=10 status=enabled
`- 3:0:0:0 sdb 8:16 active ready running
3. version info:
# uname -a
On the Initiator:
Linux xs-n1 4.4.0+2 #1 SMP Thu Jun 15 16:38:02 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
On the Target:
Linux iscsi1 4.18.0-147.8.1.el8_1.x86_64 #1 SMP Thu Apr 9 13:49:54 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
If you using rpm do:
# rpm -q ceph-iscsi
# rpm -q tcmu-runner
# rpm -q python-rtslib
No, I've installed them from source on the target
What version of tcmu-runner did you use? Was it one of the 1.4 or 1.5 releases or from the github master branch? There was a bug in the older 1.4 release where due to a linux kernel initiator side change the behavior for an error code we used went from retrying for up to 5 minutes to 5 times. The 5 retries were then used in less than a second, so we could see the issue you are seeing.
To map that to an iscsi gateway then you can do the following.
If sdb is the AO one, then run
iscsiadm -m session -P 3
Here you can see the sdXYZ name to iscsi session mapping. The iscsi
session/connection's target IP address from that command should match to
the gateway that is listed as the "owner" of the LUN in the "gwcli ls"
output.
I see... thanks for the hint.
I've done a test: I've unmapped all the drive, then mapped the first gateway (iscsi1) on all the nodes, waited, then mapped the second gateway, to be sure that all the nodes would see the first node as the active/master
Now things seems a little better in "normal" vm use: I only see the "Cannot send after transport endpoint shutdown." on the secondary target node.
I do see some hopping between the nodes when importing a disk drive, but at this point I'm starting to suspect some strange activity from the Xen infrastructure in that circumstance.
--
*Simone Lazzaris*
*Qcom S.p.A. a socio unico*
simone.lazzaris@qcom.it <mailto:simone.lazzaris@qcom.it> | www.qcom.it <https://www.qcom.it>
* LinkedIn <https://www.linkedin.com/company/qcom-spa>* | *Facebook* <http://www.facebook.com/qcomspa>
What version of tcmu-runner did you use? Was it one of the 1.4 or 1.5 releases or from the github master branch?
There was a bug in the older 1.4 release where due to a linux kernel initiator side change the behavior for an error code we used went from retrying for up to 5 minutes to 5 times. The 5 retries were then used in less than a second, so we could see the issue you are seeing.
I've done a git clone https://github.com/open-iscsi/tcmu-runner In version.h i see: #define TCMUR_VERSION "1.5.2" So I think I'm using the latest source available. *Simone Lazzaris* *Qcom S.p.A. a socio unico* simone.lazzaris@qcom.it[1] | www.qcom.it[2] * LinkedIn[3]* | *Facebook*[4] [5] -------- [1] mailto:simone.lazzaris@qcom.it [2] https://www.qcom.it [3] https://www.linkedin.com/company/qcom-spa [4] http://www.facebook.com/qcomspa [5] https://www.qcom.it/pdf/other/bannerfirmamail.gif
You can check the lock lists on each rbd and you can try removing the lock but only when the vm is shutdown and rbd is not used rbd lock list pool/volume-id rbd lock rm pool/volume-id "lock_id" client_id This was a bug in luminous upgrade i believe and i found it back in the days from this article but seems the link doesn't work now https://der-jd.de/blog/2018/12/27/openstack-ceph-luminous-upgrade.html
participants (3)
-
Mike Christie
-
Simone Lazzaris
-
tdados＠hotmail.com