Hi Martin, Nic, > On Mar 21, 2017, at 3:29 PM, Martin Svec <martin.svec@xxxxxxxx> wrote: > > Hello Nick, > > Dne 19.3.2017 v 1:59 Nicholas A. Bellinger napsal(a): >> Hello Martin, >> >> Good to hear from you. > > Yes, I'm still here :-) > >> >> (Adding Himanshu + Giri CC'. Note they are qla2xxx folks, but hopefully >> they can pass this along to proper MSFT/iSCSI driver folks within >> Cavium/QLogic). >> >> On Tue, 2017-03-14 at 14:58 +0100, Martin Svec wrote: >>> Hello, >>> >>> we're trying to connect from Windows 2016 to iSCSI LIO storage using >>> QLogic 57840S iSCSI Offload Engine (iSOE). On target side, it fails with >>> "Got unknown iSCSI OpCode: 0x43" error. Initiator side says "Target >>> returned an invalid login response packet. The login response packet >>> is given in the dump data." >>> >>> Initiator: >>> Dell FC630, 2x QLogic 57840S 10GE NIC, Windows 2016, CHAP authentication >>> >>> Target: >>> Dell R730xd, 2x Intel X710 10GE NIC, iBLOCK LIO, kernel v4.9.14 >>> >>> Reference doc: >>> http://en.community.dell.com/techcenter/extras/m/white_papers/20403565/download >>> >>> Target debug log and initiator error event are below. Note that the same setup >>> with software Windows iSCSI initiator works fine. >>> >> Thanks for the bug-report. Comments below. >> >>> Any ideas what's wrong? >>> >> Interesting, it's been a few years since we've had any login interopt >> related issues. ;) >> >>> Mar 14 14:06:58 lio-201 kernel: [66559.459607] Added timeout timer to iSCSI login request for 15 seconds. >>> Mar 14 14:06:58 lio-201 kernel: [66559.459609] Moving to TARG_CONN_STATE_XPT_UP. >>> Mar 14 14:06:58 lio-201 kernel: [66559.459667] rx_loop: 48, total_rx: 48, data: 48 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459670] Got Login Command, Flags 0x00, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0x00000000, CID: 0, Length: 141 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459673] rx_loop: 144, total_rx: 144, data: 144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459676] Received iSCSI login request from 10.22.1.51:55265 on iSCSI/TCP Network Portal 10.22.1.201:3260 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459677] Moving to TARG_CONN_STATE_IN_LOGIN. >>> Mar 14 14:06:58 lio-201 kernel: [66559.459686] Entering iscsi_target_set_sock_callbacks: conn: ffff88026e41e800 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459691] Located Storage Object: iqn.2011-07.com.zoner:fx2-hyv-test >>> Mar 14 14:06:58 lio-201 kernel: [66559.459692] Located Portal Group Object: 1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459771] iSCSI Parameter updated to TargetPortalGroupTag=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459774] iSCSI Parameter updated to ErrorRecoveryLevel=0 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459776] Got key: InitiatorName=iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.459779] iSCSI Parameter updated to InitiatorName=iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.459780] Got key: SessionType=Normal >>> Mar 14 14:06:58 lio-201 kernel: [66559.459783] iSCSI Parameter updated to SessionType=Normal >>> Mar 14 14:06:58 lio-201 kernel: [66559.459784] Got key: TargetName=iqn.2011-07.com.zoner:fx2-hyv-test >>> Mar 14 14:06:58 lio-201 kernel: [66559.459787] iSCSI Parameter updated to TargetName=iqn.2011-07.com.zoner:fx2-hyv-test >>> Mar 14 14:06:58 lio-201 kernel: [66559.459788] Got key: AuthMethod=CHAP >>> Mar 14 14:06:58 lio-201 kernel: [66559.459791] iSCSI Parameter updated to AuthMethod=CHAP >>> Mar 14 14:06:58 lio-201 kernel: [66559.459799] Sending key: AuthMethod=CHAP >>> Mar 14 14:06:58 lio-201 kernel: [66559.459801] Sending key: TargetAlias=LIO Target >>> Mar 14 14:06:58 lio-201 kernel: [66559.459802] Sending key: TargetPortalGroupTag=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459806] Sending Login Response, Flags: 0x00, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x99868726, Length: 62 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459814] ret: 112, sent data: 112 >>> Mar 14 14:06:58 lio-201 kernel: [66559.459819] Moving to TARG_CONN_STATE_FREE. >>> Mar 14 14:06:58 lio-201 kernel: [66559.460005] Entering iscsi_target_sk_data_ready: conn: ffff88026e41e800 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460012] entering iscsi_target_do_login_rx, conn: ffff88026e41e800, kworker/6:2:15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460013] Starting login_timer for kworker/6:2/15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460016] rx_loop: 48, total_rx: 48, data: 48 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460018] Got Login Command, Flags 0x00, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0x27878699, CID: 0, Length: 9 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460020] rx_loop: 12, total_rx: 12, data: 12 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460022] iscsi_target_do_login_rx after rx_login_io, ffff88026e41e800, kworker/6:2:15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460024] Got key: CHAP_A=5 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460027] Selected MD5 Algorithm >>> Mar 14 14:06:58 lio-201 kernel: [66559.460027] [server] Got CHAP_A=5 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460028] [server] Sending CHAP_A=5 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460030] [server] Sending CHAP_I=66 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460035] [server] Sending CHAP_C=0x06440f2a1188c37053f2e1e76407c3e8 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460035] >>> Mar 14 14:06:58 lio-201 kernel: [66559.460036] Received OK response from LIO Authentication, continuing. >>> Mar 14 14:06:58 lio-201 kernel: [66559.460038] Sending Login Response, Flags: 0x00, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x99868727, Length: 61 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460043] ret: 112, sent data: 112 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460169] Entering iscsi_target_sk_data_ready: conn: ffff88026e41e800 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460173] entering iscsi_target_do_login_rx, conn: ffff88026e41e800, kworker/6:2:15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460175] Starting login_timer for kworker/6:2/15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460176] rx_loop: 48, total_rx: 48, data: 48 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460178] Got Login Command, Flags 0x81, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0x28878699, CID: 0, Length: 95 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460181] rx_loop: 96, total_rx: 96, data: 96 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460182] iscsi_target_do_login_rx after rx_login_io, ffff88026e41e800, kworker/6:2:15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460184] Got key: CHAP_N=iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.460189] [server] Got CHAP_N=iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.460191] [server] Got CHAP_R=6656f75505ac2bb13210dc4ac0636872 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460198] [server] MD5 Server Digest: 6656f75505ac2bb13210dc4ac0636872 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460199] [server] MD5 Digests match, CHAP connection successful. >>> Mar 14 14:06:58 lio-201 kernel: [66559.460199] >>> Mar 14 14:06:58 lio-201 kernel: [66559.460200] iSCSI security negotiation completed successfully. >>> Mar 14 14:06:58 lio-201 kernel: [66559.460203] Sending Login Response, Flags: 0x81, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x99868728, Length: 0 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460207] ret: 48, sent data: 48 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460374] Entering iscsi_target_sk_data_ready: conn: ffff88026e41e800 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460377] entering iscsi_target_do_login_rx, conn: ffff88026e41e800, kworker/6:2:15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460379] Starting login_timer for kworker/6:2/15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460381] rx_loop: 48, total_rx: 48, data: 48 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460382] Got Login Command, Flags 0x87, ITT: 0x00000000, CmdSN: 0x00000000, ExpStatSN: 0x29878699, CID: 0, Length: 245 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460385] rx_loop: 248, total_rx: 248, data: 248 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460387] iscsi_target_do_login_rx after rx_login_io, ffff88026e41e800, kworker/6:2:15242 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460388] Got key: DataPDUInOrder=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460391] iSCSI Parameter updated to DataPDUInOrder=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460393] Got key: DataSequenceInOrder=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460395] iSCSI Parameter updated to DataSequenceInOrder=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460396] Got key: ErrorRecoveryLevel=0 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460399] iSCSI Parameter updated to ErrorRecoveryLevel=0 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460400] Got key: FirstBurstLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460403] iSCSI Parameter updated to FirstBurstLength=65536 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460405] Got key: ImmediateData=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460407] Got key: InitialR2T=No >>> Mar 14 14:06:58 lio-201 kernel: [66559.460409] iSCSI Parameter updated to InitialR2T=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460410] Got key: MaxBurstLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460412] iSCSI Parameter updated to MaxBurstLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460413] Got key: MaxConnections=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460416] iSCSI Parameter updated to MaxConnections=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460417] Got key: MaxOutstandingR2T=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460419] iSCSI Parameter updated to MaxOutstandingR2T=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460420] Got key: DataDigest=None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460423] iSCSI Parameter updated to DataDigest=None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460424] Got key: HeaderDigest=None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460426] iSCSI Parameter updated to HeaderDigest=None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460427] Got key: MaxRecvDataSegmentLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460430] iSCSI Parameter updated to MaxRecvDataSegmentLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460431] Saving op->MaxRecvDataSegmentLength from original initiator received value: 262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460433] iSCSI Parameter updated to MaxRecvDataSegmentLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460434] Updated MaxRecvDataSegmentLength to target MXDSL value: 262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460445] Sending key: HeaderDigest=None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460446] Sending key: DataDigest=None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460447] Sending key: MaxConnections=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460449] Sending key: InitialR2T=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460450] Sending key: ImmediateData=Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460451] Sending key: MaxRecvDataSegmentLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460453] Sending key: MaxBurstLength=262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460454] Sending key: FirstBurstLength=65536 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460456] Sending key: DefaultTime2Wait=2 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460457] Sending key: DefaultTime2Retain=20 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460459] Sending key: MaxOutstandingR2T=1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460460] Sending key: ErrorRecoveryLevel=0 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460462] Entering iscsi_target_restore_sock_callbacks: conn: ffff88026e41e800 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460464] Sending Login Response, Flags: 0x87, ITT: 0x00000000, ExpCmdSN; 0x00000000, MaxCmdSN: 0x00000000, StatSN: 0x99868729, Length: 243 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460593] ret: 292, sent data: 292 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460595] Moving to TARG_CONN_STATE_LOGGED_IN. >>> Mar 14 14:06:58 lio-201 kernel: [66559.460598] ------------------------------------------------------------------ >>> Mar 14 14:06:58 lio-201 kernel: [66559.460599] AuthMethod: CHAP >>> Mar 14 14:06:58 lio-201 kernel: [66559.460600] HeaderDigest: None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460601] DataDigest: None >>> Mar 14 14:06:58 lio-201 kernel: [66559.460605] MaxXmitDataSegmentLength: 262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460606] MaxRecvDataSegmentLength: 262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460611] ------------------------------------------------------------------ >>> Mar 14 14:06:58 lio-201 kernel: [66559.460612] ------------------------------------------------------------------ >>> Mar 14 14:06:58 lio-201 kernel: [66559.460616] MaxConnections: 1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460617] TargetName: iqn.2011-07.com.zoner:fx2-hyv-test >>> Mar 14 14:06:58 lio-201 kernel: [66559.460619] InitiatorName: iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.460620] TargetAlias: LIO Target >>> Mar 14 14:06:58 lio-201 kernel: [66559.460622] TargetPortalGroupTag: 1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460623] InitialR2T: Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460624] ImmediateData: Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460627] MaxBurstLength: 262144 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460628] FirstBurstLength: 65536 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460630] DefaultTime2Wait: 2 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460632] DefaultTime2Retain: 20 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460633] MaxOutstandingR2T: 1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460635] DataPDUInOrder: Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460637] DataSequenceInOrder: Yes >>> Mar 14 14:06:58 lio-201 kernel: [66559.460638] ErrorRecoveryLevel: 0 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460640] SessionType: Normal >>> Mar 14 14:06:58 lio-201 kernel: [66559.460641] ------------------------------------------------------------------ >>> Mar 14 14:06:58 lio-201 kernel: [66559.460649] Moving to TARG_SESS_STATE_LOGGED_IN. >>> Mar 14 14:06:58 lio-201 kernel: [66559.460652] iSCSI Login successful on CID: 0 from 10.22.1.51:55265 to 10.22.1.201:3260,1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460653] Incremented iSCSI Connection count to 1 from node: iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.460654] Established iSCSI session from node: iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.460655] Incremented number of active iSCSI sessions to 1 on iSCSI Target Portal Group: 1 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460678] Started NOPIN Timer on CID: 0 at 15 second interval >>> Mar 14 14:06:58 lio-201 kernel: [66559.460869] rx_loop: 48, total_rx: 48, data: 48 >>> Mar 14 14:06:58 lio-201 kernel: [66559.460872] Got unknown iSCSI OpCode: 0x43 >>> Mar 14 14:06:58 lio-201 kernel: [66559.462599] Cannot recover from unknown opcode while ERL=0, closing iSCSI connection. >>> Mar 14 14:06:58 lio-201 kernel: [66559.464336] Moving to TARG_CONN_STATE_CLEANUP_WAIT. >>> Mar 14 14:06:58 lio-201 kernel: [66559.464338] Performing cleanup for failed iSCSI Connection ID: 0 from iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.464339] Closing iSCSI connection CID 0 on SID: 6211 >>> Mar 14 14:06:58 lio-201 kernel: [66559.464378] Moving to TARG_CONN_STATE_FREE. >>> Mar 14 14:06:58 lio-201 kernel: [66559.464380] Decremented iSCSI connection count to 0 from node: iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.464384] Moving to TARG_SESS_STATE_FREE. >>> Mar 14 14:06:58 lio-201 kernel: [66559.464384] Released iSCSI session from node: iqn.1991-05.com.microsoft:hyv-051.zarea.local >>> Mar 14 14:06:58 lio-201 kernel: [66559.464385] Decremented number of active iSCSI Sessions on iSCSI TPG: 1 to 0 >>> >>> >> The 'Got unknown iSCSI OpCode: 0x43' here means the initiator sent >> another ISCSI_OP_LOGIN, after target sent the last ISCSI_OP_LOGIN_RSP, >> signaling a successful login and transition to full feature phase >> operation. >> >> AFAICT, it looks like QLogic MSFT initiator didn't like a key=value >> response to one of the keys it proposed, or is expecting some other key >> to be negotiated. > > You're right, the initiator replies by another login command with DefaultTime2Wait=2 > and DefaultTime2Retain=20. If I change the keys on target side, it's clear that initiator > always returns the values received from the target. The initiator itself proposes no > values for them. So, these two keys seem to be the issue. > >> Looking at the log, the only key=value that was proposed and changed by >> LIO was InitialR2T=No to InitialR2T=Yes. >> >> One quick thing you can try is change the LIO side parameter default to >> InitialR2T=No, and see if that makes any difference. > > It makes no difference. > >> Beyond that, please send along a wireshark capture to see what the >> key=value payload looks like in the subsequent ISCSI_OP_LOGIN_PDU, which >> should give a clue to what is going on. > > Please see the attached dump captured on target. > > Martin > > > <san4.pcap> Here’s response i got from our windows driver team —— <snip> —— There is a known issue with iscsi login in tcm/lio side and we have a driver workaround for handling this target issue. Please try with registry key ‘wkflg=1’. —— </snip> —— Thanks, - Himanshu ��.n��������+%������w��{.n����j� ����{ay� ʇڙ���f���h������_�(�階�ݢj"��������G����?���&��
