selftests: `mptcp_connect`: MPTCP -> TCP timeout during closing time

[matttbe]

The CI reported this issue with mptcp_connect.sh -m mmap:

# INFO: disconnect
# 63 ns1 MPTCP -> ns1 (10.0.1.1:20001      ) MPTCP     (duration  3292ms) [ OK ]
# 64 ns1 MPTCP -> ns1 (10.0.1.1:20002      ) TCP       (duration 61300ms) [FAIL] client exit code 124, server 0
# 
# netns ns1-0GyOLu (listener) socket stat for 20002:
# Failed to find cgroup2 mount
# Failed to find cgroup2 mount
# Netid State    Recv-Q Send-Q  Local Address:Port  Peer Address:Port 
# tcp   LAST-ACK 0      1243655      10.0.1.1:20002     10.0.1.1:35890 timer:(persist,034ms,0) ino:0 sk:a7 cgroup:unreachable:1 ---
# 	 skmem:(r0,rb131072,t0,tb2626560,f2810,w1266950,o0,bl0,d114) ts sack cubic wscale:10,10 rto:206 rtt:5.878/10.251 ato:40 mss:47616 pmtu:65535 rcvmss:47616 advmss:65483 cwnd:10 bytes_sent:5400576 bytes_acked:5400576 bytes_received:6644231 segs_out:332 segs_in:280 data_segs_out:115 data_segs_in:164 send 648057162bps lastsnd:172 lastrcv:17371 lastack:172 pacing_rate 1295976520bps delivery_rate 1295673464bps delivered:116 busy:17368ms rwnd_limited:17367ms(100.0%) rcv_rtt:1 rcv_space:65483 rcv_ssthresh:94770 notsent:1243655 minrtt:0.205 rcv_wnd:95232
# TcpActiveOpens                  3                  0.0
# TcpPassiveOpens                 3                  0.0
# TcpInSegs                       1966               0.0
# TcpOutSegs                      1969               0.0
# TcpExtTW                        2                  0.0
# TcpExtDelayedACKs               1                  0.0
# TcpExtTCPPureAcks               882                0.0
# TcpExtTCPFromZeroWindowAdv      98                 0.0
# TcpExtTCPToZeroWindowAdv        98                 0.0
# TcpExtTCPWantZeroWindowAdv      1                  0.0
# TcpExtTCPOrigDataSent           888                0.0
# TcpExtTCPACKSkippedSeq          95                 0.0
# TcpExtTCPWinProbe               193                0.0
# TcpExtTCPDelivered              891                0.0
# MPTcpExtMPCapableSYNTX          3                  0.0
# MPTcpExtMPCapableFallbackSYNACK 3                  0.0
# 
# netns ns1-0GyOLu (connector) socket stat for 20002:
# Failed to find cgroup2 mount
# Failed to find cgroup2 mount
# Failed to find cgroup2 mount
# Netid State      Recv-Q Send-Q Local Address:Port  Peer Address:Port                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                            
# tcp   FIN-WAIT-2 0      0           10.0.1.1:35890     10.0.1.1:20002 ino:48603 sk:10b6 cgroup:unreachable:1 <--
# 	 skmem:(r0,rb131072,t0,tb2626560,f2304,w0,o0,bl0,d194) ts sack cubic wscale:10,10 rto:203 rtt:2.522/0.68 ato:80 mss:47616 pmtu:65535 rcvmss:47616 advmss:65483 cwnd:10 bytes_sent:6644230 bytes_acked:6644232 bytes_received:5400576 segs_out:280 segs_in:334 data_segs_out:164 data_segs_in:115 send 1510420301bps lastsnd:17705 lastrcv:506 lastack:506 pacing_rate 3020690880bps delivery_rate 95351184bps delivered:165 busy:1113ms rwnd_limited:1088ms(97.8%) rcv_rtt:1.053 rcv_space:65495 rcv_ssthresh:95232 minrtt:0.161 snd_wnd:95232 tcp-ulp-mptcp flags:mc token:0000(id:0)/571c8429(id:0) seq:5365760 sfseq:5365761 ssnoff:3679620128 maplen:34816
# tcp   TIME-WAIT  0      0           10.0.1.1:42406     10.0.1.1:20002 timer:(timewait,19sec,0) ino:0 sk:10b7
# 	                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
# tcp   TIME-WAIT  0      0           10.0.1.1:55632     10.0.1.1:20002 timer:(timewait,41sec,0) ino:0 sk:10b8
# 	                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  
# mptcp FIN-WAIT-2 132736 0           10.0.1.1:35890     10.0.1.1:20002 timer:(keepalive,59sec,0) ino:0 sk:10b9 cgroup:unreachable:1 ---
# 	 skmem:(r132736,rb131072,t0,tb2630656,f128,w0,o0,bl0,d0) subflows_max:2 fallback token:571c8429 write_seq:9551119985441430328 snd_una:9551119985441430328 rcv_nxt:5400576 bytes_sent:6644230 bytes_received:5400576 bytes_acked:6644231 last_data_sent:17836 last_data_recv:513 last_ack_recv:61817                                                                                                                                                                                                                                                                                                                                     
# 
# 65 ns1 MPTCP -> ns1 (dead:beef:1::1:20003) MPTCP     (duration  3289ms) [ OK ]
# 66 ns1 MPTCP -> ns1 (dead:beef:1::1:20004) TCP       (duration 60007ms) [ OK ]
# 67 ns1 TCP   -> ns1 (dead:beef:1::1:20005) MPTCP     (duration  3176ms) [ OK ]
# [FAIL] Tests of the full disconnection have failed

It looks like the last data + fin are dropped by the MPTCP stack.

From Paolo:

I think commit dbbbba3 is wrong. If fin is carried by a data packet, subflow_state_change() / subflow_sched_work_if_closed() will be executed before the dummy mapping for the incoming packet is created (tcp_queue_data() will happen later). The dummy mapping for the dummy data fin will be wrong (will reference/use the previous dummy mapping seq number) and will be ignored by the stack
on the flip side the above should be reproducible with pktdrill:

• fallback
• kernel shutdown
• incoming pktdrill fin + data
• kernel socket should be closed, will be stuck in fin_wait2?

[matttbe]

@pabeni : with the following packetdrill test

// 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    getsockopt(3, SOL_TCP, TCP_IS_MPTCP, [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.1      <  S.  0:0(0)  ack 1  win 65535  <mss 1460, sackOK, TS val 700 ecr 100>
+0.0      >   .  1:1(0)  ack 1             <nop, nop,         TS val 100 ecr 700>

+0.200  getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
+0.200  fcntl(3, F_SETFL, O_RDWR) = 0   // set back to blocking

// Check for fallback
+0.0    getsockopt(3, SOL_TCP, TCP_IS_MPTCP, [0], [4]) = 0

// ensure that traffic plane is functional and does not use DSS
+0.0    shutdown(3, SHUT_WR) = 0
+0.0      >  F.  1:1(0)    ack 1           <nop, nop,         TS val 100 ecr 700>
+0.1      <  F.  1:11(10)  ack 2  win 257  <nop, nop,         TS val 700 ecr 100>
+0.0      >   .  2:2(0)    ack 12          <nop, nop,         TS val 100 ecr 700>
+0.0    `ss -Mtnia`

the test runs successfully, and ss reports:

Netid State     Recv-Q Send-Q Local Address:Port  Peer Address:Port                
tcp   LISTEN    0      100          0.0.0.0:44063      0.0.0.0:*   
         cubic cwnd:10
tcp   TIME-WAIT 0      0        192.168.0.1:34874    192.0.2.1:8080
                      
mptcp UNCONN    896    0        192.168.0.1:34874    192.0.2.1:8080
         subflows_max:2 fallback token:9f7080f7 write_seq:14807721103619733649 snd_una:14807721103619733649 rcv_nxt:11 bytes_received:10 last_data_sent:631 last_data_recv:30 last_ack_recv:631

No FIN_WAIT_2.

Note: is UNCONN normal? yes: I do a shutdown(), not a close()

[pabeni]

@matttbe: could you please add a read() after the fin 3whs? with no bugs it should return 10, I suspect you it will fail with the drill

[matttbe]

@pabeni I tried with this:

// 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    getsockopt(3, SOL_TCP, TCP_IS_MPTCP, [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.1      <  S.  0:0(0)  ack 1  win 65535  <mss 1460, sackOK, TS val 700 ecr 100>
+0.0      >   .  1:1(0)  ack 1             <nop, nop,         TS val 100 ecr 700>

+0.200  getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
+0.200  fcntl(3, F_SETFL, O_RDWR) = 0   // set back to blocking

// Check for fallback
+0.0    getsockopt(3, SOL_TCP, TCP_IS_MPTCP, [0], [4]) = 0

// ensure that traffic plane is functional and does not use DSS
+0.0    shutdown(3, SHUT_WR) = 0
+0.0      >  F.  1:1(0)         ack 1              <nop, nop, TS val 100 ecr 700>
+0.0      <   .  1:1001(1000)   ack 2     win 257  <nop, nop, TS val 700 ecr 100>  // also no issues if these 1000 bytes are in the FIN and not in a dedicated packet
+0.0      >   .  2:2(0)         ack 1001           <nop, nop, TS val 100 ecr 700>
+0.0      <  F.  1001:1011(10)  ack 2     win 257  <nop, nop, TS val 700 ecr 100>
+0.0      >   .  2:2(0)         ack 1012           <nop, nop, TS val 100 ecr 700>
+0.0    read(3, ..., 1500) = 1010
+0.0    `! ss -Mtn | grep FIN_WAIT_2`

So more data sent before or after the FIN, nor more delays, and still everything fine.

I will try to reproduce the selftest issue with a packet trace.

[pabeni]

I think commit dbbbba3 is wrong. If fin is carried by a data packet, subflow_state_change() / subflow_sched_work_if_closed() will be executed before the dummy mapping for the incoming packet is created (tcp_queue_data() will happen later). The dummy mapping for the dummy data fin will be wrong (will reference/use the previous dummy mapping seq number) and will be ignored by the stack
on the flip side the above should be reproducible with pktdrill:

I have to take back the above: subflow_state_change unconditionally invokes mptcp_subflow_data_available() before checking for data fin, and that update the subflow mapping.

BTW interesting data point from the relevant log:

tcp FIN-WAIT-2 /*... */ bytes_sent:6644230 bytes_acked:6644232

This is the "stuck" peer, bytes_acked is only updated by the TCP stack, and should never be greater then bytes_sent+1

[matttbe]

tcp FIN-WAIT-2 /*... */ bytes_sent:6644230 bytes_acked:6644232

This is the "stuck" peer, bytes_acked is only updated by the TCP stack, and should never be greater then bytes_sent+1

In this case, the FIN had been acked, no? bytes sent + SYN + FIN?

(I'm on my phone, I didn't check the code)

[pabeni]

tcp FIN-WAIT-2 /*... */ bytes_sent:6644230 bytes_acked:6644232
This is the "stuck" peer, bytes_acked is only updated by the TCP stack, and should never be greater then bytes_sent+1

In this case, the FIN had been acked, no? bytes sent + SYN + FIN?

(I'm on my phone, I didn't check the code)

Uhmmm... you are right, I think.

Reading again the data, I notice only now that the connection is stuck before completion, with the mptcp-side announcing zero window, and the tcp side with a lot of data pending in the tx queue and doing zero window probe.

The received has processed all the data send from the sender (receiver->bytes_received == sender->bytes_sent), but has rmem usage is above sk_rcvbuf size. It looks like msk->sk_rmem_alloc is corrupted ?!?

[matttbe]

I managed to get a packet trace during the night:

# INFO: Packet capture files will have this prefix: ut15YB-
# INFO: set ns3-zYymBv dev ns3eth2: ethtool -K  gso off gro off
# INFO: set ns4-Nx5NLT dev ns4eth3: ethtool -K  gso off gro off
# Created /tmp/tmp.pSFpHFLbg9 (size 6519695 B) containing data sent by client
# Created /tmp/tmp.2ndDrEa56D (size 1276757 B) containing data sent by server
# INFO: Using loss of 0.83% delay 9 ms reorder 95% 64% with delay 2ms on ns3eth4
# INFO: disconnect
# INFO: extra options: -I 3 -i /tmp/tmp.pSFpHFLbg9 -m mmap
(...)
# 02 ns1 MPTCP -> ns1 (10.0.1.1:10001      ) TCP       (duration 61338ms) [FAIL] client exit code 124, server 0
#
# netns ns1-ut15YB (listener) socket stat for 10001:
# Failed to find cgroup2 mount
# Failed to find cgroup2 mount
# Netid State    Recv-Q Send-Q Local Address:Port  Peer Address:Port
# tcp   LAST-ACK 0      944272      10.0.1.1:10001     10.0.1.1:55726 timer:(persist,340ms,0) ino:0 sk:1 cgroup:unreachable:1 ---
#        skmem:(r0,rb131072,t0,tb2626560,f1265,w961295,o0,bl0,d119) ts sack cubic wscale:8,8 rto:207 backoff:2 rtt:6.445/10.244 ato:40 mss:47488 pmtu:65535 rcvmss:47488 advmss:65483 cwnd:10 bytes_sent:5575424 bytes_acked:5575424 bytes_received:6519696 segs_out:338 segs_in:283 data_segs_out:119 data_segs_in:162 send 589455392bps lastsnd:1112 lastrcv:19052 lastack:488 pacing_rate 1178796464bps delivery_rate 590830480bps delivered:120 busy:19044ms rwnd_limited:19044ms(100.0%) rcv_
rtt:1 rcv_space:65483 rcv_ssthresh:94770 notsent:944272 minrtt:0.475 rcv_wnd:94976
#   TcpActiveOpens                  3
#   TcpPassiveOpens                 3
#   TcpInSegs                       1956
#   TcpOutSegs                      1959
#   TcpExtTW                        2
#   TcpExtDelayedACKs               1
#   TcpExtTCPPureAcks               877
#   TcpExtTCPFromZeroWindowAdv      97
#   TcpExtTCPToZeroWindowAdv        98
#   TcpExtTCPWantZeroWindowAdv      7
#   TcpExtTCPOrigDataSent           883
#   TcpExtTCPACKSkippedSeq          95
#   TcpExtTCPWinProbe               193
#   TcpExtTCPDelivered              886
#   MPTcpExtMPCapableSYNTX          3
#   MPTcpExtMPCapableFallbackSYNACK 3
#
# netns ns1-ut15YB (connector) socket stat for 10001:
# Failed to find cgroup2 mount
# Failed to find cgroup2 mount
# Failed to find cgroup2 mount
# Netid State      Recv-Q Send-Q Local Address:Port  Peer Address:Port
# tcp   FIN-WAIT-2 0      0           10.0.1.1:55726     10.0.1.1:10001 ino:35604 sk:1001 cgroup:unreachable:1 <--
#        skmem:(r0,rb131072,t0,tb2626560,f0,w0,o0,bl0,d193) ts sack cubic wscale:8,8 rto:203 rtt:2.628/0.464 ato:80 mss:47488 pmtu:65535 rcvmss:47488 advmss:65483 cwnd:10 bytes_sent:6519695 bytes_acked:6519697 bytes_received:5575424 segs_out:283 segs_in:339 data_segs_out:162 data_segs_in:119 send 1445601218bps lastsnd:19393 lastrcv:1453 lastack:1453 pacing_rate 2890927416bps delivery_rate 592673944bps delivered:163 busy:1451ms rwnd_limited:1429ms(98.5%) rcv_rtt:1.266 rcv_space:
65495 rcv_ssthresh:94976 minrtt:0.393 snd_wnd:94976 tcp-ulp-mptcp flags:mc token:0000(id:0)/b48e7966(id:0) seq:5541376 sfseq:5541377 ssnoff:4276019928 maplen:34048
# tcp   TIME-WAIT  0      0           10.0.1.1:49930     10.0.1.1:10001 timer:(timewait,18sec,0) ino:0 sk:1002
#
# tcp   TIME-WAIT  0      0           10.0.1.1:50332     10.0.1.1:10001 timer:(timewait,39sec,0) ino:0 sk:1003
#
# mptcp FIN-WAIT-2 131712 0           10.0.1.1:55726     10.0.1.1:10001 timer:(keepalive,57sec,0) ino:0 sk:1004 cgroup:unreachable:1 ---
#        skmem:(r131712,rb131072,t0,tb2630656,f3456,w0,o0,bl0,d0) subflows_max:2 fallback token:b48e7966 write_seq:16251014111104039372 snd_una:16251014111104039372 rcv_nxt:5575424 bytes_sent:6519695 bytes_received:5575424 bytes_acked:6519696 last_data_sent:19549 last_data_recv:1456 last_ack_recv:63025
#
# tcpdump: WARNING: any: That device doesn't support promiscuous mode
# (Promiscuous mode not supported on the "any" device)
# tcpdump: WARNING: any: That device doesn't support promiscuous mode
# (Promiscuous mode not supported on the "any" device)
# tcpdump: listening on any, link-type LINUX_SLL2 (Linux cooked v2), snapshot length 65535 bytes
# tcpdump: listening on any, link-type LINUX_SLL2 (Linux cooked v2), snapshot length 65535 bytes
# 1956 packets captured
# 3914 packets received by filter1956 packets captured
#
# 0 packets dropped by kernel3914 packets received by filter
#
# 0 packets dropped by kernel

The packet trace: ut15YB-ns1-ns1-MPTCP-TCP-10.0.1.1-10001-connector.tar.xz.gz (sorry, it is a gzip of a tar.xz just to be able to upload it here)

There, we can see that the timeout happened because the transfer are too slow: it took more than 60 seconds to upload 3x7MB

The client (MPTCP socket which fell back to TCP) can send data quickly, but not the server (plain TCP). In this slow case, the receiver is the MPTCP socket: the data it got are ACKed quickly with a zero win, but the window update is sent after a while (~0.6 sec). Note that in this test, the client sends its file, then closes the connection on its end, and finally the server sends everything back (slowly here).