Comment 1 Dave Cottlehuber 2021-10-13 19:15:39 UTC

https://mailarchive.ietf.org/arch/msg/ips/8WBo2pcVojpuwBoCb2IPPRW6VWA/may be relevant.

Comment 2 Ed Maste 2021-10-13 19:32:35 UTC

https://mailarchive.ietf.org/arch/msg/ips/8WBo2pcVojpuwBoCb2IPPRW6VWA/

Comment 3 Dave Cottlehuber 2021-10-13 19:39:08 UTC

see URL https://reviews.freebsd.org/D31594 for additional context

Comment 4 Dave Cottlehuber 2021-10-13 22:16:08 UTC

commentin out the error handling as added in D31594 as suggested by Ed,
*and* bumping up mtu to 16000, gets us a bit further, but volume is
still inaccessible and causes the new disk to hang.

[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): connection error; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): PDU 0x0 StatSN 0 != session ExpStatSN 1 (or + 1); reconnecting
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): received PDU with unsupported opcode 0x0; reconnecting
[2655] WARNING: icl_conn_receive_pdu: received data segment length 16384 is larger than negotiated; dropping connection
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): connection error; reconnecting
[2655] WARNING: icl_conn_receive_pdu: received data segment length 16306705 is larger than negotiated; dropping connection
[2655] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): connection error; reconnecting
...
[2709] da1 at iscsi1 bus 0 scbus1 target 0 lun 1
da1: <ORACLE BlockVolume 1.0>  detached
[2709] GEOM: da1: corrupt or invalid GPT detected.
[2709] GEOM: da1: GPT rejected -- may not be recoverable.
[2709] g_dev_taste: g_dev_taste(da1) failed to g_attach, error=6
[2709] (da1:iscsi1:0:0:1): Periph destroyed
[2722] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): ExpDataSN mismatch in SCSI Response (0 vs 1)
[2722] da1 at iscsi2 bus 0 scbus1 target 0 lun 1
da1: <ORACLE BlockVolume 1.0> Fixed Direct Access SPC-4 SCSI device
da1: 150.000MB/s transfers
da1: Command Queueing enabled
da1: 48128MB (98566144 512 byte sectors)
[2722] (da1:iscsi2:0:0:1): READ(6)/WRITE(6) not supported, increasing minimum_cmd_size to 10.
[2727] WARNING: 169.254.2.7:3260 (iqn.2015-02.oracle.boot:uefi): no ping reply (NOP-In) after 5 seconds; reconnecting
...

root@a01 /u/h/dch# gpart show

^c
^z

Comment 5 John Baldwin 2021-10-15 16:04:48 UTC

Please redo the packet capture with '-s 0'.  The SCSI response PDUs are in the same packet as the Data-In but can't be seen in WireShark since the captured packets are truncated.  Given the small number of packets involved, using '-s 0' should be ok without risk of dropping packets.

Note that since there is a Data-In, the ExpDataSN field should be 1 in the SCSI Response.  It is a count of the Data-In PDUs sent in the reply to the original request prior to the SCSI Response PDU that closes it:

https://datatracker.ietf.org/doc/html/rfc7143#section-11.4.8

The error messages in comment #4 suggest a completely garbled connection, e.g. if there are extra bytes in the stream that cause the client to read PDU headers at the wrong offset.  'PDU 0x0' means that it thinks the opcode of the PDU is 0 (NOP-Out).  However, NOP-out PDUs are only sent by the initiator (client), not the target.

I wonder if OCI is using AHS (which isn't generally supported in FreeBSD's iSCSI stack)?  A full pcap might help.

Oh, also, the LoginRespone shows 'iSCSIProtocolLevel=Not Understood" in the reply.  That may be ok though as that just means we can't use features from RFC 7144 I think (reading in RFC 7144 which defines version 2 where as 7143 is version 1).

Comment 6 Dave Cottlehuber 2021-10-15 17:09:31 UTC

Created attachment 228726 [details]
pcap v2 with -s 0

# tcpdump -i vtnet0 -w /var/tmp/iscsi2.pcap -s 0 port 3260

root@a01:~ # grep -v \# /etc/iscsi.conf
behemoth {
        targetaddress   = 169.254.2.9:3260
        targetname      = iqn.2015-02.oracle.boot:uefi
}

root@a01:~ # sysctl kern.iscsi.debug=10
kern.iscsi.debug: 1 -> 10

root@a01:~ # tcpdump -i vtnet0 -w /tmp/iscsi.pcap -s 0 port 3260 &
[2] 56458

root@a01:~ # service iscsid onestart
Starting iscsid.
root@a01:~ # iscsictl -Lv
root@a01:~ # iscsictl -Aa
root@a01:~ # iscsictl -Lv
Session ID:               7
Initiator name:           iqn.1994-09.org.freebsd:a01.cabal5.net
Initiator portal:         
Initiator alias:          
Target name:              iqn.2015-02.oracle.boot:uefi
Target portal:            169.254.2.9:3260
Target alias:             
User:                     
Secret:                   
Mutual user:              
Mutual secret:            
Session type:             Normal
Enable:                   Yes
Session state:            Disconnected
Failure reason:           Connection refused
Header digest:            None
Data digest:              None
MaxRecvDataSegmentLength: 8192
MaxSendDataSegmentLength: 8192
MaxBurstLen:              262144
FirstBurstLen:            65536
ImmediateData:            Yes
iSER (RDMA):              No
Offload driver:           None
Device nodes:             probe0

Comment 7 Dave Cottlehuber 2021-10-15 17:38:03 UTC

note to self; more learnings https://reviews.freebsd.org/D31577

Comment 8 John Baldwin 2021-10-15 22:43:41 UTC

Created attachment 228734 [details]
permit_expdatasn_0.patch

Not tested, but I did notice that we should require an ExpDataSN of 0 if the response is not command completed.

Looking at the latest trace, it does seem that the SCSI response does include an ExpDataSN of 0, and I've added an exception that tries to exempt this check for errors.  It's not conformant, but Linux also doesn't check for this that I can see (linux/drivers/scsi/libiscsi.c:iscsi_scsi_cmd_rsp()).

This though will just get you back to comment #4 I think and we will still need a pcap with -s 0 of the result to look at for the next issue.

Comment 9 Dave Cottlehuber 2021-10-21 11:36:59 UTC

thanks John!

permit_expdatasn_0.patch gets us further - we can successfully attach a volume now, and partition the device:


# iscsictl -A -p 169.254.2.2:3260 -t iqn.2015-12.com.oracleiaas:f896d637-0a99-4fc7-9aed-ecfc8c2166f2
# iscsictl -Lv
Session ID:               1
Initiator name:           iqn.1994-09.org.freebsd:hobbes.skunkwerks.at
Initiator portal:         
Initiator alias:          
Target name:              iqn.2015-12.com.oracleiaas:f896d637-0a99-4fc7-9aed-ecfc8c2166f2
Target portal:            169.254.2.2:3260
Target alias:             
User:                     
Secret:                   
Mutual user:              
Mutual secret:            
Session type:             Normal
Enable:                   Yes
Session state:            Connected
Failure reason:           
Header digest:            None
Data digest:              None
MaxRecvDataSegmentLength: 8192
MaxSendDataSegmentLength: 8192
MaxBurstLen:              262144
FirstBurstLen:            65536
ImmediateData:            Yes
iSER (RDMA):              No
Offload driver:           None
Device nodes:             da1 


next, we run into:

# tcpdump -nns 0 -C 32 -w /var/tmp/iscsi/iscsi.pcap port 3260 &
# time dd if=/dev/random of=/dev/da1 count=1 bs=1g

Password:WARNING: icl_conn_receive_pdu: received data segment length 16384 is larger than negotiated; dropping connection

WARNING: 169.254.2.2:3260 (iqn.2015-12.com.oracleiaas:f896d637-0a99-4fc7-9aed-ecfc8c2166f2): connection error; reconnecting
panic: isc->receive_pdu != NULL
cpuid = 1
time = 1634815845
KDB: stack backtrace:
db_trace_self() at db_trace_self
db_trace_self_wrapper() at db_trace_self_wrapper+0x30
vpanic() at vpanic+0x184
panic() at panic+0x44
icl_receive_thread() at icl_receive_thread+0x734
fork_exit() at fork_exit+0x74
fork_trampoline() at fork_trampoline+0x14
KDB: enter: panic
[ thread pid 0 tid 100279 ]
Stopped at      kdb_enter+0x44: undefined       f901811f
db>

Comment 10 Dave Cottlehuber 2021-10-21 12:25:25 UTC

Created attachment 228921 [details]
post permit_expdatasn_0.patch with iscsi attach & running gpart

Soon after transferring data, we lose connection and panic. I do not yet have a pcap *during* the crash.

Comment 11 Dave Cottlehuber 2021-10-21 13:07:42 UTC

Created attachment 228924 [details]
icl_conn_receive_pdu crash data segment length error

putting haproxy in between, in tcp mode, and attaching (but not mounting via iscsi) the block vol to the other node, gives us both a crash, and a pcap.

da1: <ORACLE BlockVolume 1.0> Fixed Direct Access SPC-4 SCSI device
da1: 150.000MB/s transfers
da1: Command Queueing enabled
da1: 51200MB (104857600 512 byte sectors)
iscsi_pdu_handle_scsi_response: 10.0.0.86 (iqn.2015-12.com.oracleiaas:f896d637-0a99-4fc7-9aed-ecfc8c2166f2): freezing devq
(da1:iscsi6:0:0:1): READ(6)/WRITE(6) not supported, increasing minimum_cmd_size to 10.
WARNING: icl_conn_receive_pdu: received data segment length 16384 is larger than negotiated; dropping connection
WARNING: 10.0.0.86 (iqn.2015-12.com.oracleiaas:f896d637-0a99-4fc7-9aed-ecfc8c2166f2): connection error; reconnecting
panic: isc->receive_pdu != NULL
cpuid = 3
time = 1634821349
KDB: stack backtrace:
db_trace_self() at db_trace_self
db_trace_self_wrapper() at db_trace_self_wrapper+0x30
vpanic() at vpanic+0x184
panic() at panic+0x44
icl_receive_thread() at icl_receive_thread+0x734
fork_exit() at fork_exit+0x74
fork_trampoline() at fork_trampoline+0x14
KDB: enter: panic
[ thread pid 0 tid 100287 ]
Stopped at      kdb_enter+0x44: undefined       f901811f

Comment 12 Ed Maste 2021-10-21 14:32:19 UTC

(In reply to Dave Cottlehuber from comment #11)
Notes from an IRC debugging session with dch@ and andrew@:

The panic looks like failed error handling after a reconnect attempt so needs to be fixed but is not the primary issue; this is:

WARNING: icl_conn_receive_pdu: received data segment length 16384 is larger than negotiated; dropping connection

sys/dev/iscsi/icl_soft.c:

                len = icl_pdu_data_segment_length(request);
                if (len > ic->ic_max_recv_data_segment_length) {  <---
                        ICL_WARN("received data segment "
                            "length %zd is larger than negotiated; "
                            "dropping connection", len);
                        error = EINVAL;
                        break;
                }

ic_max_recv_data_segment_length ultimately gets set by iscsid handling the new connection. In usr.sbin/iscsid/login.c in login_negotiate_key:

        } else if (strcmp(name, "MaxRecvDataSegmentLength") == 0) {
                tmp = strtoul(value, NULL, 10);
                if (tmp <= 0)
                        log_errx(1, "received invalid "
                            "MaxRecvDataSegmentLength");
                if (tmp > isl->isl_max_send_data_segment_length) {
                        log_debugx("capping max_send_data_segment_length "
                            "from %d to %d", tmp,
                            isl->isl_max_send_data_segment_length);
                        tmp = isl->isl_max_send_data_segment_length;
                }
                conn->conn_max_send_data_segment_length = tmp;
                /* We received target's limit, that means it accepted our's. */
                conn->conn_max_recv_data_segment_length =   <---
                    isl->isl_max_recv_data_segment_length;  <---

So it appears conn_max_recv_data_segment_length is only set once we receive MaxRecvDataSegmentLength from the target

from proxied.pcap,

frame 15 our login command contains MaxRecvDataSegmentLength=262144
the response is in frame 17 and does not contain MaxRecvDataSegmentLength, so we never update conn_max_recv_data_segment_length 

This handling for conn_max_recv_data_segment_length came in with
https://cgit.freebsd.org/src/commit/?id=a15fbc904a4d535e0c438bcecac056fca4fa3c5e

Comment 13 Dave Cottlehuber 2021-10-21 16:18:09 UTC

relevant packets to save others opening tcpdump/wireshark

WARNING: icl_conn_receive_pdu: received data segment length 16384 is larger than negotiated; dropping connection

this is the initial login packet sent from FreeBSD to OCI iscsi target:

iSCSI (Login Command)
    Opcode: Login Command (0x03)
    1... .... = T: Transit to next login stage
    .0.. .... = C: Text is complete
    .... 01.. = CSG: Operational negotiation (0x1)
    .... ..11 = NSG: Full feature phase (0x3)
    VersionMax: 0x00
    VersionMin: 0x00
    TotalAHSLength: 0x00
    DataSegmentLength: 249 (0x000000f9)
    ISID: 80 d5 92 14 52 4d
        10.. .... = ISID_t: Random (0x2)
        ..00 0000 = ISID_a: 0x00
        ISID_b: 0xd592
        ISID_c: 0x14
        ISID_d: 0x524d
    TSIH: 0x0000
    InitiatorTaskTag: 0x00000000
    CID: 0x0000
    CmdSN: 0x00000000
    ExpStatSN: 0x00000001
    Key/Value Pairs
        KeyValue: iSCSIProtocolLevel=2
        KeyValue: HeaderDigest=None
        KeyValue: DataDigest=None
        KeyValue: ImmediateData=Yes
        KeyValue: MaxBurstLength=1048576
        KeyValue: FirstBurstLength=1048576
        KeyValue: InitialR2T=Yes
        KeyValue: MaxOutstandingR2T=1
        KeyValue: MaxRecvDataSegmentLength=262144 <----- 
        KeyValue: DefaultTime2Wait=0
        KeyValue: DefaultTime2Retain=0
        KeyValue: ErrorRecoveryLevel=0
    Padding: 00 00 00

and this below is the specific iscsi message that causes FreeBSD to panic:

Transmission Control Protocol, Src Port: 3260, Dst Port: 24622, Seq: 27737, Ack: 2441, Len: 48
[3 Reassembled TCP Segments (16432 bytes): #194(8948), #195(7436), #196(48)]
    [Frame: 194, payload: 0-8947 (8948 bytes)]
    [Frame: 195, payload: 8948-16383 (7436 bytes)]
    [Frame: 196, payload: 16384-16431 (48 bytes)]
    [Segment count: 3]
    [Reassembled TCP length: 16432]
    [Reassembled TCP Data: 25 81 00 00 00 00 40 00 00 00 00 00 00 00 00 00 27 00 00 00 ff ff ff ff …]
iSCSI (SCSI Data In)
    Opcode: SCSI Data In (0x25)
    Flags: 0x81
        1... .... = F: Final PDU in sequence
        .0.. .... = A: Acknowledge not requested
        .... .0.. = O: No residual overflow occurred
        .... ..0. = U: No residual underflow occurred
        .... ...1 = S: Response contains SCSI status
    Status: Good (0x00)
    TotalAHSLength: 0x00
    DataSegmentLength: 16384 (0x00004000)
    InitiatorTaskTag: 0x27000000
    StatSN: 0x00000029
    ExpCmdSN: 0x00000028
    MaxCmdSN: 0x000000a8
    DataSN: 0x00000000
    BufferOffset: 0x00000000
    ResidualCount: 0x00000000
    Request in: 188
    Time from request: 0.000568000 seconds
SCSI Payload (Read(10) Response Data)
    [LUN: 0x0001]
    [Command Set:Direct Access Device (0x00) ]
    [SBC Opcode: Read(10) (0x28)]
    [Request in: 188]
    [Response in: 196]
SCSI Response (Read(10))
    [LUN: 0x0001]
    [Command Set:Direct Access Device (0x00) ]
    [SBC Opcode: Read(10) (0x28)]
    [Request in: 188]
    [Time from request: 0.000568000 seconds]
    [Status: Good (0x00)]

Comment 14 Dave Cottlehuber 2021-10-22 07:55:33 UTC

Created attachment 228938 [details]
iscsid: default conn_max_recv_data_segment_length to our request

Author: Ed Maste <emaste@FreeBSD.org>
Date:   Thu Oct 21 11:09:58 2021 -0400

    iscsid: default conn_max_recv_data_segment_length to our request
    
    XXX attempted workaround for PR259152; target did not respond with
    MaxRecvDataSegmentLength and so we did not update
    conn_max_recv_data_segment_length.
    
    PR:             259152

Ed's patch here "works for me" - I can see, mount, & use iscsi targets on both VM and BM now, handling a full 20GiB zpool resilver between volumes without issue. I expect we'll survive a buildworld as well.

My understanding is that we have several "wip patches" that need somebody who's more familiar with the spec and the code to make a call if this is (a) appropriate and (b) if patches need to evolve further to commit to main.

Comment 15 Ed Maste 2021-10-22 14:01:45 UTC

MaxRecvDataSegmentLength issue (first mentioned in comment #11) split out to PR259355.

Comment 16 commit-hook 2021-10-26 21:56:11 UTC

A commit in branch main references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=cdbc4a074bec094dc7f1dfde0773a9417d118ffa

commit cdbc4a074bec094dc7f1dfde0773a9417d118ffa
Author:     John Baldwin <jhb@FreeBSD.org>
AuthorDate: 2021-10-26 21:50:05 +0000
Commit:     John Baldwin <jhb@FreeBSD.org>
CommitDate: 2021-10-26 21:50:05 +0000

    Further refine the ExpDataSN checks for SCSI Response PDUs.

    According to 11.4.8 in RFC 7143, ExpDataSN MUST be 0 if the response
    code is not Command Completed, but we were requiring it to always be
    the count of DataIn PDUs regardless of the response code.

    In addition, at least one target (OCI Oracle iSCSI block device)
    returns an ExpDataSN of 0 when returning a valid completion with an
    error status (Check Condition) in response to a SCSI Inquiry.  As a
    workaround for this target, only warn without resetting the connection
    for a 0 ExpDataSN for responses with a non-zero error status.

    PR:             259152
    Reported by:    dch
    Reviewed by:    dch, mav, emaste
    Fixes:          4f0f5bf99591 iscsi: Validate DataSN values in Data-In PDUs in the initiator.
    Sponsored by:   Chelsio Communications
    Differential Revision:  https://reviews.freebsd.org/D32650

 sys/dev/iscsi/iscsi.c | 40 ++++++++++++++++++++++++++++++++--------
 1 file changed, 32 insertions(+), 8 deletions(-)

Comment 17 commit-hook 2021-11-23 23:14:24 UTC

A commit in branch stable/13 references this bug:

URL: https://cgit.FreeBSD.org/src/commit/?id=412a8b92d9c0490ba700f5ea4f676a16778643bd

commit 412a8b92d9c0490ba700f5ea4f676a16778643bd
Author:     John Baldwin <jhb@FreeBSD.org>
AuthorDate: 2021-10-26 21:50:05 +0000
Commit:     John Baldwin <jhb@FreeBSD.org>
CommitDate: 2021-11-23 23:11:44 +0000

    Further refine the ExpDataSN checks for SCSI Response PDUs.

    According to 11.4.8 in RFC 7143, ExpDataSN MUST be 0 if the response
    code is not Command Completed, but we were requiring it to always be
    the count of DataIn PDUs regardless of the response code.

    In addition, at least one target (OCI Oracle iSCSI block device)
    returns an ExpDataSN of 0 when returning a valid completion with an
    error status (Check Condition) in response to a SCSI Inquiry.  As a
    workaround for this target, only warn without resetting the connection
    for a 0 ExpDataSN for responses with a non-zero error status.

    PR:             259152
    Reported by:    dch
    Reviewed by:    dch, mav, emaste
    Fixes:          4f0f5bf99591 iscsi: Validate DataSN values in Data-In PDUs in the initiator.
    Sponsored by:   Chelsio Communications
    Differential Revision:  https://reviews.freebsd.org/D32650

    (cherry picked from commit cdbc4a074bec094dc7f1dfde0773a9417d118ffa)

 sys/dev/iscsi/iscsi.c | 40 ++++++++++++++++++++++++++++++++--------
 1 file changed, 32 insertions(+), 8 deletions(-)

Comment 18 John Baldwin 2023-03-24 04:03:51 UTC

I think this can be closed now.