Failed to run ISCSI login: exit status 19 about synology-csi

[benwbooth]

When I run sudo journalctl -u iscsid on a host node, I get this:

May 14 07:14:02 maple iscsid[3950]: Connection2497:0 to [target: iqn.2000-01.com.synology:kube-csi-pvc-47cb17bf-9cc8-42d6-b9f5-5c2280eba601, portal: 10.0.3.50
May 14 07:16:08 maple iscsid[3950]: Received invalid login PDU, current stage mismatch, session 1, response 0
May 14 07:16:08 maple iscsid[3950]: Login error (Login status 0) on conn 7

[benwbooth]

Do I need to change my loginApiVersion? Right now it's not specified, so is set to the default.

[jparklab]

You do not need to. This is an error happened while running iscsi command. loginApiVersion is used to access synology API. Is there any chance the iscsi access is blocked by the server or ip address has changed?

You can also verify if there's any issue connecting to the server by running(https://stackoverflow.com/questions/30581284/iscsiadm-login-i-o-error-failed-to-receive-a-pdu)

iscsiadm -m discovery -t st -d8 -p TARGETS_IP_ADDRESS

[benwbooth]

Thanks for your help. The IP address has not changed, I checked in the synology settings and I pinged the IP address and the ping works. I noticed that I had the firewall turned on in the synology settings, so I disabled it, but it didn't help. I am getting the following errors:

Unable to attach or mount volumes: unmounted volumes=[data], unattached volumes=[felix-db-token-np76r shared-memory local-archive data]: timed out waiting for the condition

MountVolume.SetUp failed for volume "pvc-b46bb6d2-f144-44cc-b283-ee9b95712f78" : kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = Internal desc = Failed to run ISCSI login: exit status 19

MountVolume.SetUp failed for volume "pvc-b46bb6d2-f144-44cc-b283-ee9b95712f78" : kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = NotFound desc = Unable to find target of ID: 13

I ran iscsiadm. I checked the log but couldn't find anything obviously wrong. I attached the log.
iscsiadm.log

[benwbooth]

I found the following in the log file I attached:

iscsiadm: connecting to 10.0.3.50:3260
iscsiadm: connected local port 37286 to 10.0.3.50:3260
iscsiadm: connected to discovery address 10.0.3.50
iscsiadm: discovery session to 10.0.3.50:3260 starting iSCSI login
iscsiadm: sending login PDU with current stage 1, next stage 3, transit 0x80, isid 0x00023d000000 exp_statsn 0
iscsiadm: >    InitiatorName=iqn.1993-08.org.debian:01:94ece350f671
iscsiadm: >    InitiatorAlias=monster
iscsiadm: >    SessionType=Discovery
iscsiadm: >    HeaderDigest=None
iscsiadm: >    DataDigest=None
iscsiadm: >    DefaultTime2Wait=2
iscsiadm: >    DefaultTime2Retain=0
iscsiadm: >    IFMarker=No
iscsiadm: >    OFMarker=No
iscsiadm: >    ErrorRecoveryLevel=0
iscsiadm: >    MaxRecvDataSegmentLength=32768
iscsiadm: wrote 48 bytes of PDU header
iscsiadm: wrote 248 bytes of PDU data
iscsiadm: iscsi_login: Poll return 1
iscsiadm: read 48 bytes of PDU header
iscsiadm: read 48 PDU header bytes, opcode 0x23, dlength 197, data 0x55e3b4047020, max 32768
iscsiadm: read 197 bytes of PDU data
iscsiadm: read 3 pad bytes
iscsiadm: finished reading login PDU, 48 hdr, 0 ah, 197 data, 3 pad
iscsiadm: login current stage 1, next stage 3, transit 0x80
iscsiadm: >    HeaderDigest=None
iscsiadm: >    DataDigest=None
iscsiadm: >    TargetAlias=LIO Target
iscsiadm: >    TargetPortalGroupTag=1
iscsiadm: >    MaxRecvDataSegmentLength=262144
iscsiadm: >    DefaultTime2Wait=2
iscsiadm: >    DefaultTime2Retain=0
iscsiadm: >    ErrorRecoveryLevel=0
iscsiadm: >    IFMarker=No
iscsiadm: >    OFMarker=No
iscsiadm: login response status 0000
iscsiadm: discovery login success to 10.0.3.50

It seems like login is working when running manually, just not when using the synology-csi plugin.

[benwbooth]

This is weird.. I just tried creating a test PV and it worked! So why do none of the existing volumes connect anymore?

[benwbooth]

When I attempted to redeploy the statefulset holding the PV, I got this error:

MountVolume.SetUp failed for volume "pvc-58153b70-3e40-44c8-879d-55319749efe7" : kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = Internal desc = Failed to mount /dev/disk/by-path/ip-10.0.3.50:3260-iscsi-iqn.2000-01.com.synology:kube-csi-pvc-58153b70-3e40-44c8-879d-55319749efe7-lun-1 to /var/lib/kubelet/pods/653730b2-d1e8-4a1e-b576-06e395cf6c05/volumes/kubernetes.io~csi/pvc-58153b70-3e40-44c8-879d-55319749efe7/mount(fstype: ext4, options: [rw]): failed to get disk format of disk /dev/disk/by-path/ip-10.0.3.50:3260-iscsi-iqn.2000-01.com.synology:kube-csi-pvc-58153b70-3e40-44c8-879d-55319749efe7-lun-1: blkid returns invalid output: /dev/disk/by-path/ip-10.0.3.50:3260-iscsi-iqn.2000-01.com.synology:kube-csi-pvc-58153b70-3e40-44c8-879d-55319749efe7-lun-1: UUID="7907eb8c-64a5-4ee2-b99e-496d8451a784" TYPE="ext4"

I redeployed again and I got the same error as earlier:

MountVolume.SetUp failed for volume "pvc-58153b70-3e40-44c8-879d-55319749efe7" : kubernetes.io/csi: mounter.SetupAt failed: rpc error: code = Internal desc = Failed to run ISCSI login: exit status 19

[benwbooth]

So initial PV creating and attaching works, but trying to re-attach the PV after a redeploy fails with error 19.

[benwbooth]

I think this might be related to #35 since it's hitting the blkid error first. Would it be possible to get an updated Dockerfile with @ahuffman's fixes? I'm going to try and see if that fix will solve my problem as well.

[benwbooth]

I tried @ahuffman's fix and I can confirm that that fix fixes the blkid issue in #35. However, I am still getting the error 19 issue for existing volumes. But if I create a new synology-csi volume, it now seems to work fine. Is there some invalidated information being cached somewhere?

[jparklab]

May 14 07:16:08 maple iscsid[3950]: Received invalid login PDU, current stage mismatch, session 1, response 0

This error means the client is in ISCSI_OP_PARMS_NEGOTIATION_STAGE but the server is in ISCSI_OP_PARMS_NEGOTIATION_STAGE, and it could happen when auth_client is null at https://github.com/open-iscsi/open-iscsi/blob/master/usr/login.c#L1185.

Is it possible that iscsi targets are configured to require authentication during the upgrade?

[benwbooth]

Thanks for the reply. I don't have CHAP authentication enabled for any of the targets. All of the targets were created by synology-csi so they have whatever options synology-csi gave them when they were created. I ended up deleting and re-creating all the LUNs. Luckily my k8s setup is still in testing and not used for production yet.

If this problem comes up again, I think I found a workaround. Since newly created PVs work, it's possible to simply create a new PV of the same size in the Synology UI, then reflink copy the old LUN image files in /volume1/@iSCSI/BLUN_THICK into the new LUN while both PVs are not being used. I haven't tried it but I don't see why it wouldn't work.

[jparklab]

Yes, recreating works too. :) Glad to know that you had that workaround.

iscsi stores target information on the host under /etc/iscsi. when this happens again, you can also try removing files/directories under nodes/send_targets(after making a backup) to let iscsi refetch them from the synology again.

csi-driver itself does not store any data other than target name, therefore if there is anything cached it would be on the host.

[benwbooth]

Thanks! That's good to know. I will try that next time.

[benwbooth]

I'm getting this same error message after rebooting my nodes. I tried deieting /etc/iscsi/nodes and /etc/iscsi/send_targets, then re-starting iscsid and open-iscsi. But it doesn't help.

[benwbooth]

It looks like I was able to fix it by going into the synology server iSCSI settings, then for each target, I enabled "Allow multiple sessions". Any ideas why I would need to do that?

It should be safe right? Since k8s is making sure only one pod can access the volume at at time? Or should I be worried?

[kbreit]

@benwbooth I'm having a similar problem to you. Unfortunately, the multiple sessions workaround doesn't work for me.

[Golgautier]

I have exactly the same issue. "Allow multiple sessions" saved me, but I would like to know if it is the good way to proceed ?

[vaskozl]

Can confirm that these errors occur when the status for the LUN in the Synology interface for the PVC is still "Connected" when in reality nothing is connected to it. Typically tends to happen after a sudden reboot of a node or similar.

"Allow multiple sessions" is a easy fix. Kubernetes does ensure that the volume is mounted in only one place so it should be safe.