UdpReceiver - handling of "SocketError.ConnectionReset"

[euantorano]

I've been seeing an intermittent problem where the RTP channel times out after 30 seconds with no audio or DTMF being received from the remote party.

I added some log statements in to UdpReceiver::BeginReceiveFrom and determined that m_isClosing is set to true right after the call has established when I see this behaviour.

Looking at the code, the m_isClosing is only set in one place - UdpReceiver::EndReceiveFrom when a SocketException is caught with the error code SocketError.ConnectionReset.

There is some logging further down stating:

This means it's not safe to close if BeginReceive gets an ICMP error since the remote party may not have initialised their socket yet.

The SocketError.ConnectionReset error as far as I understand it is raised when an ICMP "port unreachable" packet is received by the OS. This would kind of match-up with this comment, though the comment is for a different catch {} block.

I've commented out the assignment to m_isClosing to see if it alleviates the issue I'm seeing and will respond back with my findings.

[euantorano]

I commented out the assignment to m_isClosing and added a call to logger.LogTrace in its place. After a bunch of testing over yesterday afternoon and this morning, commenting out this code seems to have helped.

My extra logging in combination with using SIPTransport::EnableTraceLogs results in logs like the following:

25-11-21 10:00:47     sipsorcery[0] Request received: udp:0.0.0.0:5074<-udp:10.1.2.20:5060 ACK sip:10.1.1.10:5074 SIP/2.0
25-11-21 10:00:47     sipsorcery[0] Request: ACK sip:10.1.1.10:5074 SIP/2.0 ...
25-11-21 10:00:47     sipsorcery[0] Setting remote audio track with sdp destination 172.28.1.10:50442 and control destination 172.28.1.10:50443.
25-11-21 10:00:47     sipsorcery[0] Setting audio source format to 8:PCMA 8000 (RTP clock rate 8000).
25-11-21 10:00:47     sipsorcery[0] Audio track negotiated DTMF payload ID 101.
25-11-21 10:00:47     sipsorcery[0] Starting RTCP session for 4fbbda1a-2df3-4ff0-9215-c280e41fab48.
25-11-21 10:00:47     SipWorker[ProcessIncomingCallAsync] Answered call from: udp:10.1.2.20:5060; call ID: 3824035976-4029841831; 
25-11-21 10:00:47     sipsorcery[0] [DBG] UDP connection reset socket error for socket [::]:14440<00A>System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.<00D><00A>   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)<00D><00A>   at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)<00D><00A>--- End of stack trace from previous location ---<00D><00A>   at SIPSorcery.Net.UdpReceiver.EndReceiveFrom(IAsyncResult ar) in C:\Users\euant\Desktop\sipsorcery\src\net\RTP\UdpReceiver.cs:line 168
25-11-21 10:00:47     sipsorcery[0] [DBG] RTP packet received to 17246; from [::ffff:172.28.124.135]:50080
25-11-21 10:00:47     sipsorcery[0] RTP Session OnReceive from [::ffff:172.28.124.135]:50080 172 bytes buffer[0]=128.
25-11-21 10:00:47     sipsorcery[0] RTPSession OnReceiveRTPPacket received from 172.28.124.135:50080 172 bytes.
...
25-11-21 10:00:47     sipsorcery[0] [DBG] RTP packet received to 14440; from [::ffff:172.28.1.10]:50442

So it looks like the remote party (the caller) hasn't actually finished setting up its RTP socket until some time later, which triggers an ICMP "port unreachable", which then essentially shuts down the RTP stream as no further BeginReceiveFrom calls are attempted on the socket.

---

Whether simply removing removing the use of m_isClosing is the correct solution is questionable, but removing it certainly seems to have resolved the problem I was seeing.

[ha-ves]

@euantorano The SocketException handling of ConnectionReset in EndReceiveFrom part, I believe it was there to prevent the APM-pattern receive loop from continuing if the socket was self-closed, not by remote ICMP.

For the remote ICMP, it should've been caught here, but it didn't.

sipsorcery/src/net/RTP/UdpReceiver.cs

Lines 135 to 144 in 4a5cf6f

	catch (SocketException sockExcp)
	{
	// This exception can be thrown in response to an ICMP packet. The problem is the ICMP packet can be a false positive.
	// For example if the remote RTP socket has not yet been opened the remote host could generate an ICMP packet for the
	// initial RTP packets. Experience has shown that it's not safe to close an RTP connection based solely on ICMP packets.
	m_isRunningReceive = false;
	logger.LogWarning("Socket error {SocketErrorCode} in UdpReceiver.BeginReceiveFrom. {Message}", sockExcp.SocketErrorCode, sockExcp.Message);
	//Close(sockExcp.Message);
	}

There are also some notes under EndReceiveFrom. I can't seem to replicate the problem to derive a working solution. But I'd imagine you would differentiate the self-close exception and ICMP reset exception. If you (or anyone) could verify and polish this rough idea, please send a pull request.

sipsorcery/src/net/RTP/UdpReceiver.cs

Lines 213 to 230 in 4a5cf6f

	catch (SocketException resetSockExcp) when (resetSockExcp.SocketErrorCode == SocketError.ConnectionReset)
	{
	// Thrown when close is called on a socket
	m_isClosing = true;
	}
	catch (SocketException sockExcp)
	{
	// Socket errors do not trigger a close. The reason being that there are genuine situations that can cause them during
	// normal RTP operation. For example:
	// - the RTP connection may start sending before the remote socket starts listening,
	// - an on hold, transfer, etc. operation can change the RTP end point which could result in socket errors from the old
	// or new socket during the transition.
	// It also seems that once a UDP socket pair have exchanged packets and the remote party closes the socket exception will occur
	// in the BeginReceive method (very handy). Follow-up, this doesn't seem to be the case, the socket exception can occur in
	// BeginReceive before any packets have been exchanged. This means it's not safe to close if BeginReceive gets an ICMP
	// error since the remote party may not have initialised their socket yet.
	logger.LogWarning(sockExcp, "SocketException UdpReceiver.EndReceiveFrom ({SocketErrorCode}). {ErrorMessage}", sockExcp.SocketErrorCode, sockExcp.Message);
	}