dss_ssn_specified_client packetdrill test fails (timeout)

[matttbe]

This test is available there: https://github.com/multipath-tcp/packetdrill/blob/mptcp-net-next/gtests/net/mptcp/dss/dss_ssn_specified_client.pkt

It is not failing on current net-next but it is with the current export branch.

Here is the output of a git bisect:

47d4beeecd06f283840cf2def08f0952a6c689c7 is the first bad commit
commit 47d4beeecd06f283840cf2def08f0952a6c689c7
Date:   Mon Oct 5 05:09:46 2020 +0000

    mptcp: refactor shutdown and close

    We must not close the subflows before all the MPTCP level
    data, comprising the DATA_FIN has been acked at the MPTCP
    level, otherwise we could be unable to retransmit as needed.

    __mptcp_wr_shutdown() shutdown is responsible to check for the
    correct status and close all subflows. Is called by the output
    path after spooling any data and at shutdown/close time.

    In a similar way, __mptcp_destroy_sock() is responsible to clean-up
    the MPTCP level status, and is called when the msk transition
    to TCP_CLOSE.

    The protocol level close() does not force anymore the TCP_CLOSE
    status, but orphan the msk socket and all the subflows.
    Orphaned msk sockets are forciby closed after a timeout or
    when all MPTCP-level data is acked.

    There is a caveat about keeping the orphaned subflows around:
    the TCP stack can asynchronusly call tcp_cleanup_ulp() on them via
    tcp_close(). To prevent accessing freed memory on later MPTCP
    level operations, the msk acquires a reference to each subflow
    socket and prevent subflow_ulp_release() from releasing the
    subflow context before __mptcp_destroy_sock().

    The additional subflow references are released by __mptcp_done()
    and the async ULP release is detected checking ULP ops. If such
    field has been already cleared by the ULP release path, the
    dangling context is freed directly by __mptcp_done().

 net/mptcp/options.c  |   2 +-
 net/mptcp/protocol.c | 269 ++++++++++++++++++++++++++++++++++++---------------
 net/mptcp/protocol.h |  10 +-
 net/mptcp/subflow.c  |  21 +++-
 4 files changed, 216 insertions(+), 86 deletions(-)
bisect run success

[matttbe]

I am going to apply the different patches shared by @pabeni recently and retest.

[matttbe]

Note that I still have the issue with the latest export branch updated 10minutes ago

[matttbe]

I got the opportunity to look a bit more and the FIN is not sent, the status is still ESTABLISHED:

# tcpdump: data link type LINUX_SLL2
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on any, link-type LINUX_SLL2 (Linux cooked v2), snapshot length 262144 bytes

# packetdrill -vvv dss_ssn_specified_client.pkt &
[3] 207
socket syscall: 1601999857.704910
setsockopt syscall: 1601999857.707578
fcntl syscall: 1601999857.710214
fcntl syscall: 1601999857.712603
connect syscall: 1601999857.715185
outbound sniffed packet:  0.010372 S 971032171:971032171(0) win 65535 <mss 1460,sackOK,TS val 2492150980 ecr 0,nop,wscale 8,mp_capable v1 flags: |H| >
inbound injected packet:  0.020924 S. 0:0(0) ack 971032172 win 65535 <mss 1460,sackOK,TS val 700 ecr 2492150980,nop,wscale 8,mp_capable v1 flags: |H| sender_key: 2>
outbound sniffed packet:  0.029541 . 971032172:971032172(0) ack 1 win 256 <nop,nop,TS val 2492150999 ecr 700,mp_capable v1 flags: |H| sender_key: 2310140576115051019 receiver_key: 2>
15:57:37.715175 tun0  Out IP 192.168.234.140.48588 > 192.0.2.1.8080: Flags [S], seq 971032171, win 65535, options [mss 1460,sackOK,TS val 2492150980 ecr 0,nop,wscale 8,mptcp capable v1], length 0
15:57:37.734267 tun0  In  IP 192.0.2.1.8080 > 192.168.234.140.48588: Flags [S.], seq 0, ack 971032172, win 65535, options [mss 1460,sackOK,TS val 700 ecr 2492150980,nop,wscale 8,mptcp capable v1 {0x200000000000000}], length 0
15:57:37.734344 tun0  Out IP 192.168.234.140.48588 > 192.0.2.1.8080: Flags [.], ack 1, win 256, options [nop,nop,TS val 2492150999 ecr 700,mptcp capable v1 {0xbca8d449d440f20,0x200000000000000}], length 0
getsockopt syscall: 1601999857.944294
fcntl syscall: 1601999858.153181
inbound injected packet:  0.551480 P. 1:1001(1000) ack 971032172 win 450 <nop,nop,dss dack8 16733486346948834518 dsn8 13263177308786788773 ssn 1 dll 1000 no_checksum flags: MmAa>
outbound sniffed packet:  0.561527 . 971032172:971032172(0) ack 1001 win 264 <nop,nop,TS val 2492151531 ecr 700,dss dack8 13263177308786789773 flags: Aa>
15:57:38.266261 tun0  In  IP 192.0.2.1.8080 > 192.168.234.140.48588: Flags [P.], seq 1:1001, ack 1, win 450, options [nop,nop,mptcp dss ack 16733486346948834518 seq 13263177308786788773 subseq 1 len 1000], length 1000: HTTP
15:57:38.266330 tun0  Out IP 192.168.234.140.48588 > 192.0.2.1.8080: Flags [.], ack 1001, win 264, options [nop,nop,TS val 2492151531 ecr 700,mptcp dss ack 13263177308786789773], length 0
read syscall: 1601999858.575194
write syscall: 1601999858.577826
outbound sniffed packet:  0.873012 P. 971032172:971032272(100) ack 1001 win 264 <nop,nop,TS val 2492151843 ecr 700,dss dack8 13263177308786789773 dsn8 16733486346948834518 ssn 1 dll 100 no_checksum flags: MmAa,nop,nop>
inbound injected packet:  0.887556 . 1001:1001(0) ack 971032272 win 450 <dss dack8 16733486346948834618 flags: Aa>
15:57:38.577815 tun0  Out IP 192.168.234.140.48588 > 192.0.2.1.8080: Flags [P.], seq 1:101, ack 1001, win 264, options [nop,nop,TS val 2492151843 ecr 700,mptcp dss ack 13263177308786789773 seq 16733486346948834518 subseq 1 len 100,nop,nop], length 100: HTTP
15:57:38.598978 tun0  In  IP 192.0.2.1.8080 > 192.168.234.140.48588: Flags [.], ack 101, win 450, options [mptcp dss ack 16733486346948834618], length 0
close syscall: 1601999858.999334
outbound sniffed packet:  1.294509 . 971032272:971032272(0) ack 1001 win 264 <nop,nop,TS val 2492151864 ecr 700,dss dack8 13263177308786789773 dsn8 16733486346948834618 ssn 0 dll 1 no_checksum flags: MmAaF,nop,nop>
15:57:38.999312 tun0  Out IP 192.168.234.140.48588 > 192.0.2.1.8080: Flags [.], ack 1001, win 264, options [nop,nop,TS val 2492151864 ecr 700,mptcp dss fin ack 13263177308786789773 seq 16733486346948834618 subseq 0 len 1,nop,nop], length 0

# netstat -tnp
Active Internet connections (w/o servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
tcp        0      0 192.168.234.140:48588   192.0.2.1:8080          ESTABLISHED -                   

# cat dss_ssn_specified_client.pkt 
// connect() function, connection initiated by the kernel
--tolerance_usecs=100000
`../common/defaults.sh`


0.0   socket(..., SOCK_STREAM, IPPROTO_MPTCP) = 3
+0.0  setsockopt(3, SOL_SOCKET, SO_REUSEADDR, [1], 4) = 0
+0.0  fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
+0.0  fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0

// Establish connection and verify that there was no error.

+0.0  connect(3, ..., ...) = -1 EINPROGRESS (Operation now in progress)
+0.0   > S 0:0(0) <mss 1460,sackOK,TS val 100 ecr 0,nop,wscale 8,mpcapable v1 flags[flag_h] nokey>
+0.0   < S. 0:0(0) ack 1 win 65535 <mss 1460,sackOK,TS val 700 ecr 100,nop,wscale 8,mpcapable v1 flags[flag_h] key[skey=2] >
+0.0   > . 1:1(0) ack 1 <nop, nop, TS val 100 ecr 700,mpcapable v1 flags[flag_h] key[ckey,skey]>
+0.200 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
+0.205 fcntl(3, F_SETFL, O_RDWR) = 0   // set back to blocking
+0.1   < P. 1:1001(1000) ack 1 win 450  <nop, nop, dss dack8=1 dsn8=1 ssn=1 dll=1000 nocs>
+0.0   > . 1:1(0) ack 1001 <nop, nop, TS val 100 ecr 700,dss dack8=1001 ssn=1 dll=0 nocs>
+0.3  read(3, ..., 1000) = 1000
+0.0 write(3,..., 100) = 100
+0.0   > P. 1:101(100) ack 1001 <nop, nop, TS val 100 ecr 700, dss dack8=1001 dsn8=1 ssn=1 dll=100 nocs, nop, nop>
+0.0   < .  1001:1001(0) ack 101 win 450 <dss dack8=101 nocs>
+0.4 close(3) = 0
+0.0   > . 101:101(0) ack 1001 <nop, nop,TS val 100 ecr 700,dss dack8=1001 dsn8=101 ssn=0 dll=1 nocs fin, nop, nop>
+0.0   > F. 101:101(0) ack 1001 <nop, nop,TS val 100 ecr 700, dss dack8=1001 dsn8=101 ssn=0 dll=1 nocs fin, nop, nop>

[dcaratti]

I got the opportunity to look a bit more and the FIN is not sent, the status is still ESTABLISHED:

as per recent (verbal) discussion, this is probably intentional because commit 47d4bee requires an outbound DATA_FIN to be explicitly acked with an ACK. Something like:

--- a/gtests/net/mptcp/dss/dss_ssn_specified_client.pkt
+++ b/gtests/net/mptcp/dss/dss_ssn_specified_client.pkt
@@ -24,4 +24,5 @@
 +0.0   < .  1001:1001(0) ack 101 win 450 <dss dack8=101 nocs>
 +0.4 close(3) = 0
 +0.0   > . 101:101(0) ack 1001 <nop, nop,TS val 100 ecr 700,dss dack8=1001 dsn8=101 ssn=0 dll=1 nocs fin, nop, nop>
-+0.0   > F. 101:101(0) ack 1001 <nop, nop,TS val 100 ecr 700, dss dack8=1001 dsn8=101 ssn=0 dll=1 nocs fin, nop, nop>
++0.0   < . 1001:1001(0) ack 101 win 450 <dss dack8=102 nocs>
++0.0   > F. 101:101(0) ack 1001 <nop, nop,TS val 100 ecr 700, dss dack8=1001 nocs>

the problem with current export branch is: changing the script like in the above example is not sufficient to convince Linux to transmit an outbound FIN/ACK packet. After the kernel under test received the DACK8 equal to 102, the value sk_state transitions from TCP_FIN_WAIT_1 to TCP_FIN_WAIT_2, so, after the call to mptcp_check_data_fin(), this:

+       /* if the msk data is completely acked, or the socket timedout,
+        * there is no point in keeping around an orphaned sk
+        */
+       if (sock_flag(sk, SOCK_DEAD) &&
+           (mptcp_check_close_timeout(sk) ||
+           (state != sk->sk_state && sk->sk_state == TCP_CLOSE))) {
+               inet_sk_state_store(sk, TCP_CLOSE);
+               __mptcp_destroy_sock(sk, 0);
+               goto unlock;
+       }
+

does not happen because of the value of sk->sk_state.