Hello Martin, Good to hear from you. (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. 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. 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. -- To unsubscribe from this list: send the line "unsubscribe target-devel" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
