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
Attachment:
san4.pcap
Description: Binary data
