daire-byrne
commented
2 months ago I left "ip mptcp monitor" running on the client that was initiating the connection to the remote server and waited until I found an rsync that had dropped a subflow:
ELAPSED
06:25:13
tcp ESTAB 0 0 10.11.22.251:36173 10.29.22.251:873 users:(("rsync",pid=427974,fd=4),("rsync",pid=425159,fd=4)) ino:38112481 sk:cf cgroup:unreachable:1 <->
skmem:(r0,rb536870912,t6,tb14155776,f0,w0,o0,bl0,d582931) ts sack bbr wscale:14,14 rto:276 rtt:75.829/0.401 ato:40 mss:1386 pmtu:1500 rcvmss:1358 advmss:1448 cwnd:2048 bytes_sent:151634143 bytes_retrans:588 bytes_acked:151560224 bytes_received:563738216278 segs_out:95395099 segs_in:415887627 data_segs_out:116860 data_segs_in:415832178 bbr:(bw:46134520bps,mrtt:74.7,pacing_gain:2.77344,cwnd_gain:2) send 299466220bps lastsnd:1403807 pacing_rate 821865448bps delivery_rate 46134440bps delivered:116807 app_limited busy:544393ms sndbuf_limited:34346ms(6.3%) retrans:0/5 dsack_dups:5 reordering:9 rcv_rtt:79.149 rcv_space:14480 rcv_ssthresh:333447168 minrtt:74.7 rcv_ooopack:250911776 snd_wnd:1392640 tcp-ulp-mptcp flags:Jjecv token:30ad89d5(id:3)/8cccfd70(id:3) seq:34087e61b72d69c1 sfseq:4169d2fb ssnoff:8214a217 maplen:fea0
--
tcp ESTAB 0 0 10.11.20.251:33058 10.29.20.251:873 users:(("rsync",pid=427974,fd=4),("rsync",pid=425159,fd=4)) ino:38112481 sk:d7 cgroup:unreachable:1 <->
skmem:(r0,rb536870912,t0,tb103680,f0,w0,o0,bl0,d0) ts sack bbr wscale:14,14 rto:272 rtt:71.709/17.103 ato:40 mss:1386 pmtu:1500 rcvmss:1358 advmss:1448 cwnd:15 bytes_sent:189 bytes_acked:190 bytes_received:13295 segs_out:27 segs_in:25 data_segs_out:5 data_segs_in:16 bbr:(bw:206192bps,mrtt:67.005,pacing_gain:2.77344,cwnd_gain:2) send 2319374bps lastsnd:23447562 lastrcv:23227053 lastack:23227053 pacing_rate 4529304bps delivery_rate 205672bps delivered:6 app_limited busy:312ms rcv_rtt:27324.2 rcv_space:14480 rcv_ssthresh:102103 minrtt:67.005 snd_wnd:868352 tcp-ulp-mptcp flags:MmBbec token:0000(id:0)/8cccfd70(id:0) seq:34087ddc0c298eaf sfseq:32a2 ssnoff:8edbdeda maplen:14e
--
mptcp ESTAB 33383936 0 10.11.20.251:33058 10.29.20.251:873 users:(("rsync",pid=427974,fd=4),("rsync",pid=425159,fd=4)) ino:38112481 sk:e4 cgroup:unreachable:1 <->
skmem:(r33383936,rb536870912,t0,tb28419328,f2560,w0,o0,bl0,d22092) subflows:2 add_addr_signal:2 add_addr_accepted:2 subflows_max:4 add_addr_signal_max:2 add_addr_accepted_max:4 remote_key token:8cccfd70 write_seq:3bd8518f857a1bb1 snd_una:3bd8518f857a1bb1 rcv_nxt:34087e61b73b5133 In this case it dropped the 10.11.21.251 -> 10.29.21.251:873 subflow sometime in the 6 hours since it started. The backup subflow is still alive but it's not actually transferring any data on it yet. Weirdly, the mptcp connection still report that there are 2 subflows?
Now if we look at all the output from mptcp monitor this is all I captured:
[ CREATED] token=8cccfd70 remid=0 locid=0 saddr4=10.11.20.251 daddr4=10.29.20.251 sport=33058 dport=873
[ ESTABLISHED] token=8cccfd70 remid=0 locid=0 saddr4=10.11.20.251 daddr4=10.29.20.251 sport=33058 dport=873
[ SF_PRIO] token=8cccfd70 remid=0 locid=0 saddr4=10.11.20.251 daddr4=10.29.20.251 sport=33058 dport=873 backup=1
[ ANNOUNCED] token=8cccfd70 remid=2 daddr4=10.29.21.251 dport=873
[ ANNOUNCED] token=8cccfd70 remid=3 daddr4=10.29.22.251 dport=873
[SF_ESTABLISHED] token=8cccfd70 remid=2 locid=2 saddr4=10.11.21.251 daddr4=10.29.21.251 sport=55633 dport=873 backup=0
[SF_ESTABLISHED] token=8cccfd70 remid=3 locid=3 saddr4=10.11.22.251 daddr4=10.29.22.251 sport=36173 dport=873 backup=0So there is the initial connection but no further reporting on any subflow disconnects.
Maybe I need to also capture data from mptcp monitor on the remote server too?
If I look at the other end and the rsyncd process running on the server, it does at least show that there is only one active subflow:
tcp ESTAB 0 120995840 10.29.22.251:873 10.11.22.251:36173 users:(("rsync",pid=956743,fd=6)) timer:(on,007ms,0) ino:35155024 sk:17f6 cgroup:unreachable:1 <->
skmem:(r0,rb6081280,t36204,tb265572864,f3968,w122736768,o0,bl0,d1269) ts sack bbr wscale:14,14 rto:276 rtt:75.166/0.131 ato:40 mss:1386 pmtu:1500 rcvmss:1358 advmss:1448 cwnd:1976 ssthresh:2224 bytes_sent:634793653666 bytes_retrans:10581430522 bytes_acked:624206091774 bytes_received:151560223 segs_out:467633876 segs_in:105033615 data_segs_out:467577944 data_segs_in:116806 bbr:(bw:297283048bps,mrtt:74,pacing_gain:1,cwnd_gain:2) send 291486683bps lastrcv:2995328 lastack:1 pacing_rate 294310216bps delivery_rate 292572840bps delivered:460332536 busy:20022125ms rwnd_limited:92848ms(0.5%) sndbuf_limited:1271983ms(6.4%) unacked:4515 retrans:40/7793481 lost:40 sacked:2955 dsack_dups:549664 reordering:300 reord_seen:10542 rcv_rtt:170.566 rcv_space:14600 rcv_ssthresh:1395336 notsent:114864470 minrtt:74 snd_wnd:120995840 tcp-ulp-mptcp flags:Jec token:0000(id:3)/30ad89d5(id:3) seq:3bd8518f857a1bad sfseq:908a01c ssnoff:2f823191 maplen:4
--
mptcp ESTAB 5116672 0 10.29.20.251:873 10.11.20.251:33058 users:(("rsync",pid=956743,fd=6)) ino:35155024 sk:17c0 cgroup:unreachable:1 <->
skmem:(r5116672,rb6081280,t0,tb265715200,f6690,w170836702,o0,bl0,d574) subflows:1 add_addr_signal:2 add_addr_accepted:2 subflows_max:8 add_addr_signal_max:2 add_addr_accepted_max:8 remote_key token:30ad89d5 write_seq:34087e6fd4e1c902 snd_una:34087e6fcab634d4 rcv_nxt:3bd8518f857a1bb1 But also the active "backup" subflow reported on the client is not present on the server....
I'll try running mptcp monitor on the server and catch one of these going bad.
I know it was mentioned before that I shouldn't really be running "signal" subflows on both client and server, but we wanted these two host to be able to act as both server & client and independently initiate rsync transfers to each other. I'm not sure if this behaviour is a consequence of that? A quick refresher of the config on each server/client pair :
# serverA
ip mptcp endpoint flush
ip mptcp endpoint add 10.13.20.251 id 1 backup dev ens192
ip mptcp endpoint add 10.13.21.251 id 2 signal dev ens224
ip mptcp endpoint add 10.13.22.251 id 3 signal dev ens256
ip mptcp limits set subflow 4 add_addr_accepted 4
ip route add 10.17.21.251 via 10.13.21.1 dev ens224
ip route add 10.17.22.251 via 10.13.22.1 dev ens256One thing is certain, all mptcp rsyncs are always initiated with fully working subflows, and then a subset of those will drop one or more subflows after many hours. Of the sublows dropped, sometimes it's the "idle" backup subflow and then after that it's almost always the "first" signal endpoint rather than the second.
pabeni
matttbe
Hi,
You may remember me from such great issues as #430 and a few others. We are doing large rsync transfer using MPTCP over two ISP connections between our WAN offices.
Our setup is pretty much still as described in https://github.com/multipath-tcp/mptcp_net-next/issues/430#issuecomment-1693081415
We have just started noticing that some long running transfers are dropping one of the TCP endpoints (as yet unknown) and I'm also wondering if there is a way to "repair" such a mptcp connection and get it to reconnect the lost subflow endpoints?
So here is an example of a transfer that starts out and is still fully connected (ss -neimMtp):
And then by comparison here's an rsync transfer that started out like above, but then something happened to drop some endpoints:
Namely the "backup" endpoint on ens192 and the second signal (bulk transfer) endpoint on ens256 have disconnected. The transfer continues on the remaining ens224 endpoint but at much reduced performance.
Now, I have also seen some cases where the two signal bulk transfers are still there, but the backup endpoint is gone. In the case of the disconnected backup connection, is it possible that it might drop out due to no data traversing it and the keepalive timeout killing it? Whatever the blip might have been, all routing and connectivity seems to be working again by the time I get to it.
One thing that does seem to happen is that all the running connections between two hosts seem to suffer this problem at the same time, so blips in the connectivity or maybe TCP memory exhaustion (we use large buffers) on one host could be the underlying root cause?
I'm not sure how best to debug the drops so any tips around that would be great. I'm also wondering if it's possible to "repair" such connections and force them to readd the endpoint connections? My quick searching did not throw up anything useful.
We are currently running v6.9.3.
Many thanks.