Data channel hangs over a lossy connection

[enobufs]

Your environment.

• Version: pion/[email protected] (pion/[email protected])
• Browser: n/a

What did you do?

• Offerer: Chrome, answerer: pion (both on the same PC)
• One data channel with ordered=false, maxRetransmits=0
• Forced network impairment using comcast: delay 100msec, packet loss 6%
• Start sending packets from pion to chrome:
  • Packet size: 2500B
  • Interval: 20 msec

What did you expect?

The packets sent from pion should be continuously received by Chrome.

What happened?

• Chrome stops receiving packets in about a few seconds. (occurrence ratio ~= 20 ~ 50 % with above settings)
• TRACE log indicates that receiver side's receive buffer becomes 0 ("a_rwnd=0")
• If the packet size is <= 1200B or packet loss is small, this does not occur.

[enobufs]

I have noticed that DATA_CHANNEL_ACK message was not sent reliably and marked as "abandoned" immediately after the first transmission.

draft-ietf-rtcweb-data-protocol-09.txt in Section 6, says:

   All Data Channel Establishment Protocol messages MUST be sent using
   ordered delivery and reliable transmission.

Clearly, pion/sctp's implementation needs to be correct.

[enobufs]

The above fix did not solve the problem. Data channel still hangs, and Chrome still returns SACK with advertise receive window being 0.

[enobufs]

@tuexen I have been working on this datachannel hang issue for a while, found multiple of bugs in pion, which was good. But now, I'm struggling to find the cause of this hang, and I am hoping to hear your thoughts/suggestions if possible.

The attachment (zip) contains two files:

• pion_chrome_01.pcapng
  • pcap file of sctp packets observed by pion/sctp. (inboud: 5000/udp, outbound: 5001/udp)
• dc-hang-01.log
  • pion's trace log

Summary of what I see:

• Chrome initiates connection (and a data-channel) to pion.
• Reliability options: Ordered: false, maxRetransmits=0
• Data channel messages are sent from Pion to Chrome.
• Chrome, in its SACK, reports a_rwnd=0 at 17:50:50.938268

What I don't understand is, SACK chunks sent by Chrome indicates its cumulative TSN is advances event after a_rwnd hits 0. But the app on the Chrome stops receiving onmessage callbacks.

From the pcap above, Pion does not receive any chunks reporting error or abort.

I am not 100% sure, although this does not occur always, when it happens, it happens more at the very beginning of the connection.

attachment_01.zip

[enobufs]

I tried with Firefox and Safari but I have not been able to reproduce the hang with these browsers. (I did at least 10 times for each browser with the same settings; unordered, maxRetransmts=0, 2500B/msg).

Also, when I set unordered flag to false (ordered transmission), this does not happen with Chrome.
This may be a bug in Chrome... I am using Chrom Version 84.0.4147.89 (Official Build) (64-bit)

[enobufs]

I used browsers instead of pion (the answerer side). The hang occurs with Chrome (offerer). It does not happen with Firefox nor Safari. Browsers I used for the offerer side were Firefox and Chrome.

@tuexen I have to conclude that the hang I am seeing with data channel (ordered=false & maxRetransmits=0) is caused by a bug in Chrome, and Firefox also uses usrsctp, I guess the bug is in libwebrtc. (Does anyone know what user-space implementation of SCTP Safari use?)

Summary (conditions to cause the data channel hang)

• Partial reliability: ordered=false, maxRetransmits=0
• Packet size: 2500 bytes (large enough to cause fragmentation, e.g. It wouldn't hang with 1024B.)
• Loss ratio: 2% or above
• Latency: (appears to be not relevant. I used 0ms and 100ms)
• Chrome being the receiver (occurrence ratio: above 50% in one minute)

Comcast command example to reproduce:

% comcast --device=en0 --latency=100 --target-bw=1000 --packet-loss=2%
sudo pfctl -E
(cat /etc/pf.conf && echo "dummynet-anchor \"mop\"" && echo "anchor \"mop\"") | sudo pfctl -f -
echo $'dummynet in all pipe 1' | sudo pfctl -a mop -f -
sudo dnctl pipe 1 config delay 100ms bw 1000Kbit/s plr 0.0200 mask  proto tcp
sudo dnctl pipe 1 config delay 100ms bw 1000Kbit/s plr 0.0200 mask  proto udp
sudo dnctl pipe 1 config delay 100ms bw 1000Kbit/s plr 0.0200 mask  proto icmp

These are the browser versions I used:

• Chrome: Version 84.0.4147.89 (Official Build) (64-bit)
• Firefox: 76.0.1 (64-bit)
• Safari: Version 13.1.2 (15609.3.5.1.3)

[tuexen]

There were some bug fixes in this area which might not be in the version used by the browsers yet. Let me test this locally...

[enobufs]

@tuexen In case it helps, here is what navigator.userAgent returns on my browsers:

Chrome:

Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36

usersctp: info

Safari:

Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/13.1.2 Safari/605.1.15

The problem does not happen on my Safari though both use AppleWebKit. Do you think the bug was fixed between versions, 537.36 and 605.1.15 ?

[tuexen]

Can't reproduce the issue with the current master branch. Using

programs/tsctp -d 1 -L 192.168.1.205 -E 9899

as the receiver and

programs/tsctp -L 192.168.1.204 -E 9899 -U 9899 -u -l 2500 -n 0 -P 2 -t 0 192.168.1.205

as the sender. Using a packet drop rate of 2%. The transfer has a constant bandwidth for an hour.

[enobufs]

@tuexen I was able to reproduce it using tsctp (current master)! Occurrence ratio in the first 20 seconds is about 50% to me. I was able to capture packets with wireshark and also console logs of both ends - attached.

Comcast command:

comcast --device=lo0 --latency=100 --target-bw=1000 --packet-loss=2%

Receiver command:

./tsctp -d 1 -L 10.0.0.135 -E 9899

Sender command:

./tsctp -L 10.0.0.135 -E 9900 -U 9899 -u -l 2500 -n 0 -P 2 -t 0 10.0.0.135

In about 4 seconds, the sender receives SACK with a_rwnd=0 then it wouldn't recover.

I am using macOS (version 10.15.6 (19G73))

attachment_02.zip

[tuexen]

@enobufs Using the latest sources?

[enobufs]

Yes. Current master HEAD at rev: 31f4eb5.

% git rev-parse --short HEAD
31f4eb5

[tuexen]

Yes. Current master HEAD at rev: 31f4eb5.

% git rev-parse --short HEAD
31f4eb5

OK. Will retest. I was testing on two FreeBSD based (slow) machines. That should not matter...

[enobufs]

@tuexen I have been running the tests repeatedly and noticed when it happens, it happens within the first 10 seconds. If not it never happens in the next 50 seconds. So, it looks like the trigger is at the very beginning...
Also, occurrence is slightly higher with 4% packet loss than 2%...

[tuexen]

@enobufs Are you applying the packet loss rate uni-directional (which direction) or bi-directional? I was applying the packet loss uni-directional such that only packets with DATA chunks (or FORWARD-TSN chunks) are affected, but not packets with SACK chunks.

[enobufs]

Bi-directional and not targeted to a specific type of chunk. I am using this tool for the network impairment.

[tuexen]

Bi-directional and not targeted to a specific type of chunk. I am using this tool for the network impairment.

I'm using ipfw directly. Filtering on specific chunks is not yet supported, adding support for it is on my ToDo list (for a long time).

[enobufs]

@tuexen I added some debug logs to the code to track how cum_tsn, new_cum_tsn (by ForwardTSN), size_on_reasm_queue (and a few others) are moving. Please find the attachment (zip) to this message which has the receiver side log in it.

I do not fully understand but size_on_reasm_queue starts accumulating (stop decreasing) with last decrement with this line:

[S][1.272] @YT: dec size_on_reasm_queue(2) -= 1056

After this line, DATA chunk with TSN=3299948022 appears to be lost. Later, Forward TSN comes in as you can see with these (adjacent) lines:

[S][1.759] @YT: FWDTSN: new_cum_tsn=3299948023 <=> cum_tsn=3299948021
[S][1.759] @YT: cum_tsn=3299948023 (4)
[S][1.759] @YT: cum_tsn=3299948033 (3)
[S][1.759] @YT: cum_tsn=3299948033 (3)

I notice, in the above lines, TSN jumps from 3299948023 to 3299948033. This line is printed in the function, sctp_slide_mapping_arrays():

	asoc->cumulative_tsn = asoc->mapping_array_base_tsn + (at-1);
	SCTPDBG(SCTP_DEBUG_INDATA1, "@YT: cum_tsn=%u (3)\n", asoc->cumulative_tsn);

I have no clue what "slide mapping" means, but I believe it is advancing cum_tsn beyond new_cum_tsn as it already received those DATA chunks. The problem I see is, once this TSN advancement occurs, I see a bunch of this log messages:

[S][1.760] @YT: FWDTSN: new_cum_tsn=3299948023 <=> cum_tsn=3299948033
[S][1.760] @YT: FWDTSN: already got three...

which comes from the function sctp_handle_forward_tsn(), like this:

	if (SCTP_TSN_GE(asoc->cumulative_tsn, new_cum_tsn)) {
		/* Already got there ... */
		SCTPDBG(SCTP_DEBUG_INDATA1, "@YT: FWDTSN: already got three...\n");
		return;
	}

my typo lol: "three" => "there"

As it hits the return statement, it seems to fail to clean up the reassembly queue that would have been done in the later part of this function.

I have no idea if I am getting close to the bottom of it, but I am just hoping that this would help you finding some clue, and reproducing on your environment.

attachment_03.zip

[tuexen]

Update: I can reproduce this locally. Will look into it.

[enobufs]

@tuexen That's great news!

[enobufs]

@tuexen I'm wondering if you'd like to me to create an issue in the sctplab/usrsctp as this is no longer a pion's issue?

[tuexen]

Will work on it soon... My day job kicked in... If you prefer, you can move it over to usrsctp. It is not a bug in pion...

[tuexen]

Here is a packetdrill script to reproduce the issue:

--tolerance_usecs=50000
 0.0 socket(..., SOCK_STREAM, IPPROTO_SCTP) = 3
+0.0 fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
+0.0 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
+0.0 setsockopt(3, SOL_SOCKET, SO_RCVBUF, [10000], 4) = 0
+0.0 connect(3, ..., ...) = -1 EINPROGRESS (Operation now in progress)
+0.0 > sctp: INIT[flgs=0, tag=1, a_rwnd=10000, os=10, is=2048, tsn=1, ...]
+0.1 < sctp: INIT_ACK[flgs=0, tag=2, a_rwnd=1500, os=1, is=1, tsn=2685767820,
                      STATE_COOKIE[len=5, val=...], FORWARD_TSN_SUPPORTED[]]
+0.0 > sctp: COOKIE_ECHO[flgs=0, len=5, val=...]
+0.1 < sctp: COOKIE_ACK[flgs=0]
+0.0 < sctp: DATA[flgs=UE, len=1064, tsn=2685767821, sid=0, ssn=0, ppid=0]
// XE           -> 10000 - (1048 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767819, a_rwnd=8696, gaps=[2:2], dups=[]]
+0.0 < sctp: DATA[flgs=UB, len=1468, tsn=2685767822, sid=0, ssn=0, ppid=0]
// XEB          -> 10000 - (1048 + 256 + 1452 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767819, a_rwnd=6988, gaps=[2:3], dups=[]]
+0.0 < sctp: DATA[flgs=UB, len=1468, tsn=2685767824, sid=0, ssn=0, ppid=0]
// XEBXB        -> 10000 - (1048 + 256 + 1452 + 256 + 1452 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767819, a_rwnd=5280, gaps=[2:3,5:5], dups=[]]
+0.0 < sctp: DATA[flgs=UE, len=1064, tsn=2685767825, sid=0, ssn=0, ppid=0]
// XEBXBE       -> 10000 - (1048 + 256 + 1452 + 256 + 1452 + 256 + 1048 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767819, a_rwnd=3976, gaps=[2:3,5:6], dups=[]]
+0.0 < sctp: FORWARD_TSN[cum_tsn=2685767821, ids=[]]
// BXBE         -> 10000 - (1452 + 256 + 1048 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767822, a_rwnd=6988, gaps=[2:3], dups=[]]
+0.0 < sctp: DATA[flgs=UB, len=1468, tsn=2685767826, sid=0, ssn=0, ppid=0]
// BXBEB        -> 10000 - (1452 + 256 + 1048 + 256 + 1452 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767822, a_rwnd=5280, gaps=[2:4], dups=[]]
+0.0 < sctp: FORWARD_TSN[cum_tsn=2685767823, ids=[]]
// BEB          -> 10000 - (1048 + 256 + 1452 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767826, a_rwnd=6988, gaps=[], dups=[]]
+0.0 recv(3, ..., 3000, 0) = 2500
// B            -> 10000 - (1048 + 256) ???
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767826, a_rwnd=8696, gaps=[], dups=[]]
+0.0 < sctp: DATA[flgs=UB, len=1468, tsn=2685767828, sid=0, ssn=0, ppid=0]
// BXB          -> 10000 - (1452 + 256)
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767826, a_rwnd=8292, gaps=[2:2], dups=[]]
+0.0 < sctp: FORWARD_TSN[cum_tsn=2685767827, ids=[]]
// B            -> 10000
+0.0 > sctp: SACK[flgs=0, cum_tsn=2685767828, a_rwnd=10000, gaps=[], dups=[]]
+0.0 < sctp: DATA[flgs=UE, len=1064, tsn=2685767829, sid=0, ssn=0, ppid=0]
+0.0 recv(3, ..., 3000, 0) = 2500
//              -> 10000
+0.2 > sctp: SACK[flgs=0, cum_tsn=2685767829, a_rwnd=10000, gaps=[], dups=[]]
+0.0 close(3) = 0
+0.0 > sctp: SHUTDOWN[flgs=0, cum_tsn=2685767829]
+0.0 < sctp: SHUTDOWN_ACK[flgs=0]
+0.0 > sctp: SHUTDOWN_COMPLETE[flgs=0]

Now figuring out what is going wrong...

[tuexen]

OK, I think the issue is fixed. The problem was that in sctp_flush_reassm_for_str_seq() the condition

	if (!asoc->idata_supported && !ordered &&
	    SCTP_TSN_GT(control->fsn_included, cumtsn)) {
		return;
	}

is checking fsn_included, even if it is not set to an appropriate value, but still has its default -1. Then it depends on the initial sequence number, if the conditions is true when it should not be true. The corrected version

	if (!asoc->idata_supported && !ordered &&
	    control->first_frag_seen &&
	    SCTP_TSN_GT(control->fsn_included, cumtsn)) {
		return;
	}

avoids this problem.

Thanks a again for testing and reporting the issue!

[enobufs]

@tuexen That's great news! I am glad if this helped WebRTC community be a better place!

[tuexen]

@enobufs If you want, you can close this issue. Up to you.

[Sean-Der]

Closing, it was great reading this back @enobufs :D