search

drachtio / drachtio-siprec-recording-server

SIPREC recording server based on drachtio and rtpengine
MIT License
81 stars 31 forks source link

Truncated UDP message #49

Closed rafaltelaczynski closed 2 years ago

rafaltelaczynski commented 2 years ago

Hello,

We are facing an issue trying to integrate SIPREC recording server with BroadWorks SBC with truncated UDP message(SIP INVITE with large message body).

This is how it looks in Wireshark: Selection_042

Drachtio log(IP addresses hidden):

2021-09-07 07:36:14.784517 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x55ead080f0f0): events IN
2021-09-07 07:36:14.784625 tport.c:2892 tport_recv_event() tport_recv_event(0x55ead080f0f0)
2021-09-07 07:36:14.784665 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55ead080f0f0) msg 0x55ead081a8e0 from (udp/DRACHTIO:15060) has 3714 bytes, veclen = 1
2021-09-07 07:36:14.784843 recv 1003 bytes from udp/[BW_SBC]:5060 at 07:36:14.784706:
INVITE sip:DRACHTIO:15060 SIP/2.0
Via: SIP/2.0/UDP BW_SBC:5060;branch=z9hG4bKn2plec301op06ks5q6g1.1
From: <sip:+42191215@sip.vvn.telekom.sk;user=phone>;tag=ygeCIg
To: <sip:sip.vvn.telekom.sk:15060;transport=udp;user=phone>
Call-ID: swYuBcswZ68SL6TWz8RJPQ
CSeq: 404439 INVITE
Max-Forwards: 68
Contact: <sip:+42191215@BW_SBC:5060;transport=udp>;src
Recv-Info: 
Accept: application/media_control+xml, application/sdp
MIME-Version: 1.0
Content-Type: multipart/mixed;boundary=UniqueBroadWorksBoundary
Content-Length: 449

--UniqueBroadWorksBoundary
Content-Type:application/rs-metadata+xml
Content-Disposition:recording-session
Content-Length:2493

<?xml version="1.0" encoding="UTF-8"?>
<recording_metadata xmlns="urn:ietf:params:xml:ns:siprec">
<dataMode>complete</dataMode>
<recording id="urn:uuid:e9755e57-aaf0-40fe-b3e3-9b54cfbfacc3">
<requestor>SRC</requestor>
<type>selective</type>
</recording>
<group id="urn:uuid:eb76d96b 
2021-09-07 07:36:14.784896 tport.c:3051 tport_deliver() tport_deliver(0x55ead080f0f0): msg 0x55ead081a8e0 (1003 bytes) from udp/BW_SBC:15060 next=(nil)
2021-09-07 07:36:14.784917 nta.c:3039 agent_recv_request() nta: received INVITE sip:SIPREC-Jtendo:15060 SIP/2.0 (CSeq 404439)
2021-09-07 07:36:14.784949 nta.c:3254 agent_recv_request() nta: INVITE (404439) to message callback
2021-09-07 07:36:14.784966 processMessageStatelessly - incoming message with call-id swYuBcswZ68SL6TWz8RJPQ does not match an existing call leg, processed in thread 140125602142016
2021-09-07 07:36:14.785014 tport.c:3285 tport_tsend() tport_tsend(0x55ead080f0f0) tpn = UDP/195.146.137.250:5060
2021-09-07 07:36:14.785051 tport.c:4085 tport_resolve() tport_resolve addrinfo = BW_SBC:5060
2021-09-07 07:36:14.785129 tport.c:3531 tport_send_msg() tport_vsend returned 307
2021-09-07 07:36:14.785178 send 307 bytes to udp/[BW_SBC]:5060 at 07:36:14.785081:
SIP/2.0 100 Trying

Important thing to highlight are these two lines: 2021-09-07 07:36:14.784665 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x55ead080f0f0) msg 0x55ead081a8e0 from (udp/DRACHTIO:15060) has 3714 bytes, veclen = 1 2021-09-07 07:36:14.784843 recv 1003 bytes from udp/[BW_SBC]:5060 at 07:36:14.784706:

I analysed previous issues with similar problem and the byte values in both lines like above are the same - this is not the case here. Have you faced such an issue before? Do you have any idea what might be causing it? More details below.

  1. udp-mtu is set to 4096(higher than message size which is 3714 bytes(we tried with even 10x higher values - no change, anyway going by configuration description isn't it used only for outgoing messages?) 
    2021-09-07 07:33:27.424308 SipTransport::logTransports - udp/[::1]:15060 (sip:*:15060, external-ip: , loca
l-net: ), mtu size: 4096
  2. We tried temporarily switching to TCP protocol(it is not feasibly as a final solution anyway as something between our server and BW_SBC does not support it, just for the testing purpose) but the issue is still the same
  3. We noticed that the value in recv log(second line from the two) is always few bytes more than 1000 bytes - not sure if that indicates anything.
  4. MTU for network interface responsible for receiving the message is set to default 1500(as seen in trace image when message gets fragmented)
  5. Below is complete INVITE, taken by Follow UDP Stream option 
    
INVITE sip:DRACHTIO:15060 SIP/2.0
Via: SIP/2.0/UDP BW_SBC:5060;branch=z9hG4bKn2plec301op06ks5q6g1.1
From: <sip:+42191215@sip.vvn.telekom.sk;user=phone>;tag=ygeCIg
To: <sip:sip.vvn.telekom.sk:15060;transport=udp;user=phone>
Call-ID: swYuBcswZ68SL6TWz8RJPQ
CSeq: 404439 INVITE
Max-Forwards: 68
Contact: <sip:+42191215@BW_SBC:5060;transport=udp>;src
Recv-Info: 
Accept: application/media_control+xml, application/sdp
MIME-Version: 1.0
Content-Type: multipart/mixed;boundary=UniqueBroadWorksBoundary
Content-Length: 449

--UniqueBroadWorksBoundary Content-Type:application/rs-metadata+xml Content-Disposition:recording-session Content-Length:2493

<?xml version="1.0" encoding="UTF-8"?>

complete SRC selective sip:+42191215@A_IP;user=phone 2021-09-07T09:36:14+02:00 sip:+42191215@A_IP;user=phone urn:uuid:c48fc5cd-d40e-4bac-a76c-661d53a59250 sip:+48511325595@B_IP;user=phone urn:uuid:f12c1e7c-cf4a-4ebb-8a96-caf32951c5ea separate separate 8e71e709-9795-49cd-adf4-2e3f5696f485 JTENDOXXE1 JTENDOE1G1_grp 42191215 zaxLnjq6iRWVp3gWirrN_g sip:+42191215@A_IP;user=phone sip:+48511325595@B_IP;user=phone on

--UniqueBroadWorksBoundary Content-Type: application/sdp Content-Length: 417

v=0 o=- 426088 426088 IN IP4 BW_SBC s=media server session b=AS:80 t=0 0 m=audio 23696 RTP/AVP 8 c=IN IP4 BW_SBC b=AS:80 b=RR:6000 b=RS:2000 a=rtpmap:8 PCMA/8000 a=rtcp-xr a=ptime:20 a=maxptime:80 a=sendonly a=label:1 m=audio 21080 RTP/AVP 8 c=IN IP4 BW_SBC b=AS:80 b=RR:6000 b=RS:2000 a=rtpmap:8 PCMA/8000 a=rtcp-xr a=ptime:20 a=maxptime:80 a=sendonly a=label:2

--UniqueBroadWorksBoundary--



Version used:
OS: Debian GNU/Linux 9 (stretch)
Drachtio: v0.8.8
davehorton commented 2 years ago

can you try sending a similar/same message using SIPp on your network and see if it does the same thing? Here is a link to a sipp uac.xml file

https://gist.github.com/davehorton/58a688983ecff065d8e4a2f227c586b9

rafaltelaczynski commented 2 years ago

Thanks for the response. I can see that it has Content-Length header removed. It was spot-on as the UDP message was parsed correctly without that header.

Issue can be regarded as closed.

davehorton commented 2 years ago

So the problem was this?

Content-Length: 449

Was that a Broadsoft bug?

rafaltelaczynski commented 2 years ago

Yes, the value itself was problematic.

We are in the process of debugging it, but as of now it appears as a bug in BW SBC or some other endpoint along the way. The endpoint initiating the INVITE procedure(=the one constructing INVITE with CR SDP) is sending right value of Content-Length, but for some reason it gets overwritten somewhere along the way. We even tried removing it when constructing initial INVITE(meaning INVITE leaves initiating endpoint without that header, at all), but it's still getting populated by some endpoint with corrupted value.