Hi everyone,
I'm using Kamailio (Ver 5.5.1, Public IP X.X.X.11, Private IP 172.18.0.20) + RTPEngine (Ver 9.4.1.1, Public IP X.X.X.7, Private IP 172.18.0.50) alongside Freeswitch (Private IP 172.18.0.40) in my backend and delivering calls to a mobile application (call flow is Freeswitch -> Kamailio + RTPEngine -> Applicaiton). While calls made to NATted destination generally works fine - from time to time, we've experiencing one-sided audio due to the rtpengine sending the media stream to the remote end's private IP instead of his public one. For instance, in the attached logs - media was sent towards 192.168.1.93 instead of 79.179.1.2, which is the expected destination. Problem appears almost randomly; I can make 20 fine calls in a row for the same destination until experiencing it, and I didn't find any difference as it comes to the SIP invite exchange between the two. Has anyone ever experienced the same behavior and can share some general instructions on how to troubleshoot it?
Relevant Kamailio config section is attached.
Invite Kamailio->Device
INVITE sip:972587102881@79.179.1.2:56308;transport=TLS;ob SIP/2.0 Record-Route: sip:X.X.X.11:443;transport=tls;r2=on;lr=on;ftag=cvcHy5UcS9pjj Record-Route: sip:172.18.0.20:5099;r2=on;lr=on;ftag=cvcHy5UcS9pjj Via: SIP/2.0/TLS X.X.X.11:443;branch=z9hG4bK24bf.52b1dd68e26010ba103bd8d6fdb53cf4.0 Via: SIP/2.0/UDP 172.18.0.40;received=172.18.0.40;rport=5060;branch=z9hG4bKH234Q58HpHNKK Max-Forwards: 66 From: "972522149596" sip:FreeSWITCH@172.18.0.20:5099;tag=cvcHy5UcS9pjj To: sip:972587102881@172.18.0.20:5099 Call-ID: be55bd1e-537d-123a-65a9-0242ac120028 CSeq: 37932220 INVITE Contact: sip:gw+kam-in@172.18.0.40:5060;transport=udp;gw=kam-in;alias=172.18.0.40~5060~1 User-Agent: FreeSWITCH-mod_sofia/1.10.6-release+git~20210325T131609Z~1ff9d0a60e~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 567 X-SESSION-ID: 721533765 X-INCOMING: PSTN X-from-freeswitch: +972522149596 X-FS-Support: update_display,send_info Remote-Party-ID: "972522149596" sip:972522149596@172.18.0.20:5099;party=calling;screen=yes;privacy=off
v=0 o=FreeSWITCH 1624937621 1624937622 IN IP4 X.X.X.7 s=FreeSWITCH c=IN IP4 X.X.X.7 t=0 0 m=audio 30018 RTP/AVP 102 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:101 telephone-event/48000 a=fmtp:101 0-16 a=sendrecv a=rtcp:30019 a=ptime:20 a=ice-ufrag:bKPZt0dW a=ice-pwd:H4qyL7mPUOvoiAjosiLasXAdzj a=candidate:41sXGEsTafxHi8ms 1 UDP 2130706431 X.X.X.7 30018 typ host a=candidate:41sXGEsTafxHi8ms 2 UDP 2130706430 X.X.X.7 30019 typ host
Response Device->Kamailio
SIP/2.0 200 OK Via: SIP/2.0/TLS X.X.X.11:443;received=X.X.X.11;branch=z9hG4bK24bf.52b1dd68e26010ba103bd8d6fdb53cf4.0 Via: SIP/2.0/UDP 172.18.0.40;rport=5060;received=172.18.0.40;branch=z9hG4bKH234Q58HpHNKK Record-Route: sip:X.X.X.11:443;transport=tls;lr;r2=on;ftag=cvcHy5UcS9pjj Record-Route: sip:172.18.0.20:5099;lr;r2=on;ftag=cvcHy5UcS9pjj Call-ID: be55bd1e-537d-123a-65a9-0242ac120028 From: "972522149596" sip:FreeSWITCH@172.18.0.20;tag=cvcHy5UcS9pjj To: sip:972587102881@172.18.0.20;tag=5f75877e-58c2-44f3-a5b3-43f8786c42a1 CSeq: 37932220 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Contact: sip:972587102881@79.179.1.2:56308;transport=TLS;ob Supported: replaces, 100rel, timer, norefersub Content-Type: application/sdp Content-Length: 348
v=0 o=- 3833960833 3833960834 IN IP4 192.168.1.93 s=pjmedia b=AS:117 t=0 0 a=X-nat:0 m=audio 4002 RTP/AVP 96 120 c=IN IP4 192.168.1.93 b=TIAS:96000 a=rtcp:4003 IN IP4 192.168.1.93 a=sendrecv a=rtpmap:96 opus/48000/2 a=fmtp:96 useinbandfec=1 a=rtpmap:120 telephone-event/48000 a=fmtp:120 0-16 a=ssrc:816694098 cname:72cdb5f53fc2e8fb
Kamailio NAT Detect/Manage Routes
# Caller NAT detection
route[NATDETECT] { #!ifdef WITH_NAT xinfo("NATDETECT: Adding the rport parameter to the first Via header of the received message\n"); force_rport(); xinfo("NATDETECT: Trying to guess if client's request originated behind a nat. Testing 19.\n"); if (nat_uac_test("19")) { if (is_method("REGISTER")) { xinfo("NATDETECT: REGISTER request. Creating a URI consisting of the source IP, port, and protocol and storing the URI in an Attribute-Value-Pair.\n"); fix_nated_register(); } else { if(is_first_hop()) { xinfo("NATDETECT: Adding an ;alias=ip~port~transport parameter to the contact URI containing the received ip, port, and transport protocol.\n"); set_contact_alias(); } } xinfo("NATDETECT: Setting flag FLT_NATS.\n"); setflag(FLT_NATS); } else { xinfo("NATDETECT: Didn't detect natted request by any of the given heuristics\n"); } #!endif return; }
# RTPProxy control and signaling updates for NAT traversal route[NATMANAGE] { #!ifdef WITH_NAT if (is_request()) { if(has_totag()) { if(check_route_param("nat=yes")) { xinfo("NATMANAGE: This is a request with to-tag that has 'nat=yes', setting branch flag FLB_NATB.\n"); setbflag(FLB_NATB); } } }
if (!(isflagset(FLT_NATS) || isbflagset(FLB_NATB))) { xinfo("NATMANAGE: No NAT flag detected for this request\n"); return; } else { xinfo("NATMANAGE: NAT flag detected for this request\n"); }
if(!is_present_hf("x-purpose")) { xinfo("NATMANAGE: x-purpose header does not appear in this request, SDP is searched for occurrence of RFC1918 or RFC6598 addresses.\n"); if(nat_uac_test("8")) { xinfo("NATMANAGE: Found occurrence of RFC1918 or RFC6598 addresses. Checking if there is a match of source address or uri with an address in the group of the dispatcher-list.\n"); if(ds_is_from_list()) { xinfo("NATMANAGE: There is a match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin direction=priv direction=pub"); } else { xinfo("NATMANAGE: No match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin direction=pub direction=priv"); } } else { xinfo("NATMANAGE: No occurrence of RFC1918 or RFC6598 addresses. Checking if there is a match of source address or uri with an address in the group of the dispatcher-list.\n"); if(ds_is_from_list()) { xinfo("NATMANAGE: There is a match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin trust-address direction=priv direction=pub"); } else { xinfo("NATMANAGE: No match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin trust-address direction=pub direction=priv"); } } }
if (is_request()) { if (!has_totag()) { if(t_is_branch_route()) { xinfo("NATMANAGE: This is a request without to-tag and top-executed route block is branch_route, adding record route param ;nat=yes.\n"); add_rr_param(";nat=yes"); } } }
if (is_reply()) { if(isbflagset(FLB_NATB)) { if(is_first_hop()) { xinfo("NATMANAGE: Adding an ;alias=ip~port~transport parameter to the contact URI containing the received ip, port, and transport protocol.\n"); set_contact_alias(); } } } #!endif return; }
RTPEngine Logs
2021-06-29T13:07:05.440658779Z [1624972025.439547] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Received command 'offer' from 172.18.0.20:53880 2021-06-29T13:07:05.440690853Z [1624972025.439641] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Dump for 'offer' from 172.18.0.20:53880: { "supports": [ "load limit" ], "sdp": "v=0 2021-06-29T13:07:05.440695330Z o=FreeSWITCH 1624937621 1624937622 IN IP4 172.18.0.40 2021-06-29T13:07:05.440698353Z s=FreeSWITCH 2021-06-29T13:07:05.440700926Z c=IN IP4 172.18.0.40 2021-06-29T13:07:05.440703539Z t=0 0 2021-06-29T13:07:05.440706179Z m=audio 34404 RTP/AVP 102 101 2021-06-29T13:07:05.440708722Z a=rtpmap:102 opus/48000/2 2021-06-29T13:07:05.440711294Z a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 2021-06-29T13:07:05.440714053Z a=rtpmap:101 telephone-event/48000 2021-06-29T13:07:05.440716746Z a=fmtp:101 0-16 2021-06-29T13:07:05.440719258Z a=ptime:20 2021-06-29T13:07:05.440721823Z ", "ICE": "force", "direction": [ "priv", "pub" ], "replace": [ "session-connection", "origin" ], "call-id": "be55bd1e-537d-123a-65a9-0242ac120028", "received-from": [ "IP4", "172.18.0.40" ], "from-tag": "cvcHy5UcS9pjj", "command": "offer" } 2021-06-29T13:07:05.441069790Z [1624972025.439694] NOTICE: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] Creating new call 2021-06-29T13:07:05.441088698Z [1624972025.439809] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Default sink codec is opus/48000/2 2021-06-29T13:07:05.441091829Z [1624972025.439815] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Output DTMF payload type is 101 2021-06-29T13:07:05.441094966Z [1624972025.439821] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for opus/48000/2 2021-06-29T13:07:05.441097777Z [1624972025.439828] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec opus/48000/2 2021-06-29T13:07:05.441100540Z [1624972025.439833] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for opus/48000/2 2021-06-29T13:07:05.441103390Z [1624972025.439839] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for telephone-event/48000 2021-06-29T13:07:05.441106153Z [1624972025.439844] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec telephone-event/48000 2021-06-29T13:07:05.441108913Z [1624972025.439849] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for telephone-event/48000 2021-06-29T13:07:05.441111679Z [1624972025.440116] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 172.18.0.40:34404 2021-06-29T13:07:05.441124990Z [1624972025.440124] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 172.18.0.40:34405 2021-06-29T13:07:05.441663481Z [1624972025.441074] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Replying to 'offer' from 172.18.0.20:53880 (elapsed time 0.001414 sec) 2021-06-29T13:07:05.441694377Z [1624972025.441103] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Response dump for 'offer' to 172.18.0.20:53880: { "sdp": "v=0 2021-06-29T13:07:05.441701068Z o=FreeSWITCH 1624937621 1624937622 IN IP4 X.X.X.7 2021-06-29T13:07:05.441706421Z s=FreeSWITCH 2021-06-29T13:07:05.441711414Z c=IN IP4 X.X.X.7 2021-06-29T13:07:05.441716274Z t=0 0 2021-06-29T13:07:05.441721177Z m=audio 30018 RTP/AVP 102 101 2021-06-29T13:07:05.441726204Z a=rtpmap:102 opus/48000/2 2021-06-29T13:07:05.441731246Z a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 2021-06-29T13:07:05.441736873Z a=rtpmap:101 telephone-event/48000 2021-06-29T13:07:05.441742017Z a=fmtp:101 0-16 2021-06-29T13:07:05.441827012Z a=sendrecv 2021-06-29T13:07:05.441844744Z a=rtcp:30019 2021-06-29T13:07:05.441848881Z a=ptime:20 2021-06-29T13:07:05.441852444Z a=ice-ufrag:bKPZt0dW 2021-06-29T13:07:05.441856394Z a=ice-pwd:H4qyL7mPUOvoiAjosiLasXAdzj 2021-06-29T13:07:05.441860642Z a=candidate:41sXGEsTafxHi8ms 1 UDP 2130706431 X.X.X.7 30018 typ host 2021-06-29T13:07:05.441864955Z a=candidate:41sXGEsTafxHi8ms 2 UDP 2130706430 X.X.X.7 30019 typ host 2021-06-29T13:07:05.441868967Z ", "result": "ok" } 2021-06-29T13:07:07.001082810Z [1624972027.000176] DEBUG: [core] timer run time = 0.000029 sec 2021-06-29T13:07:07.817899628Z [1624972027.816949] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] >>> in_ssrc changed for: :0 new: 30adc352 2021-06-29T13:07:07.817932021Z [1624972027.816987] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] >>> out_ssrc changed for 172.18.0.40:34405 new: 30adc352 2021-06-29T13:07:07.817936388Z [1624972027.816998] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 201 2021-06-29T13:07:07.817939853Z [1624972027.817025] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] RR from 30adc352 about 0: FL 0 TL 0 HSR 0 J 0 LSR 0 DLSR 0 2021-06-29T13:07:07.817942689Z [1624972027.817030] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] No payload type known for RTCP RR, discarding 2021-06-29T13:07:07.817945696Z [1624972027.817036] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 202 2021-06-29T13:07:07.817948500Z [1624972027.817124] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] Forward to sink endpoint: 172.18.0.40:34405 2021-06-29T13:07:07.818762433Z [1624972027.817995] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 201 2021-06-29T13:07:07.818790347Z [1624972027.818031] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] RR from 30adc352 about 0: FL 0 TL 0 HSR 0 J 0 LSR 0 DLSR 0 2021-06-29T13:07:07.818794422Z [1624972027.818035] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] No payload type known for RTCP RR, discarding 2021-06-29T13:07:07.818797834Z [1624972027.818042] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 202 2021-06-29T13:07:07.818801095Z [1624972027.818122] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] Forward to sink endpoint: 172.18.0.40:34405 2021-06-29T13:07:07.847992398Z [1624972027.846284] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Received command 'answer' from 172.18.0.20:47817 2021-06-29T13:07:07.848048472Z [1624972027.846325] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Dump for 'answer' from 172.18.0.20:47817: { "supports": [ "load limit" ], "sdp": "v=0 2021-06-29T13:07:07.848058346Z o=- 3833960833 3833960834 IN IP4 192.168.1.93 2021-06-29T13:07:07.848063378Z s=pjmedia 2021-06-29T13:07:07.848067785Z b=AS:117 2021-06-29T13:07:07.848071736Z t=0 0 2021-06-29T13:07:07.848075782Z a=X-nat:0 2021-06-29T13:07:07.848079588Z m=audio 4002 RTP/AVP 96 120 2021-06-29T13:07:07.848084210Z c=IN IP4 192.168.1.93 2021-06-29T13:07:07.848089110Z b=TIAS:96000 2021-06-29T13:07:07.848092756Z a=rtcp:4003 IN IP4 192.168.1.93 2021-06-29T13:07:07.848096578Z a=sendrecv 2021-06-29T13:07:07.848100173Z a=rtpmap:96 opus/48000/2 2021-06-29T13:07:07.848104153Z a=fmtp:96 useinbandfec=1 2021-06-29T13:07:07.848108660Z a=rtpmap:120 telephone-event/48000 2021-06-29T13:07:07.848112776Z a=fmtp:120 0-16 2021-06-29T13:07:07.848116856Z a=ssrc:816694098 cname:72cdb5f53fc2e8fb 2021-06-29T13:07:07.848120776Z ", "ICE": "force", "direction": [ "pub", "priv" ], "replace": [ "session-connection", "origin" ], "call-id": "be55bd1e-537d-123a-65a9-0242ac120028", "received-from": [ "IP4", "79.179.1.2" ], "from-tag": "cvcHy5UcS9pjj", "to-tag": "5f75877e-58c2-44f3-a5b3-43f8786c42a1", "command": "answer" } 2021-06-29T13:07:07.848128079Z [1624972027.846411] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Default sink codec is opus/48000/2 2021-06-29T13:07:07.848132255Z [1624972027.846418] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Output DTMF payload type is 120 2021-06-29T13:07:07.848136164Z [1624972027.846424] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for opus/48000/2 2021-06-29T13:07:07.848139819Z [1624972027.846429] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec opus/48000/2 2021-06-29T13:07:07.848143930Z [1624972027.846434] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for opus/48000/2 2021-06-29T13:07:07.848169208Z [1624972027.846441] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for telephone-event/48000 2021-06-29T13:07:07.848174300Z [1624972027.846445] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec telephone-event/48000 2021-06-29T13:07:07.848178752Z [1624972027.846449] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for telephone-event/48000 2021-06-29T13:07:07.848183460Z [1624972027.846586] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 192.168.1.93:4002 2021-06-29T13:07:07.848188805Z [1624972027.846593] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 192.168.1.93:4003 2021-06-29T13:07:07.848193111Z [1624972027.846597] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [ice] Shutting down ICE agent (nothing to do) 2021-06-29T13:07:07.848197042Z [1624972027.847228] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Replying to 'answer' from 172.18.0.20:47817 (elapsed time 0.000890 sec) 2021-06-29T13:07:07.848201623Z [1624972027.847243] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Response dump for 'answer' to 172.18.0.20:47817: { "sdp": "v=0 2021-06-29T13:07:07.848205754Z o=- 3833960833 3833960834 IN IP4 172.18.0.50 2021-06-29T13:07:07.848209696Z s=pjmedia 2021-06-29T13:07:07.848213446Z b=AS:117 2021-06-29T13:07:07.848217361Z t=0 0 2021-06-29T13:07:07.848220816Z a=X-nat:0 2021-06-29T13:07:07.848224363Z m=audio 30018 RTP/AVP 96 120 2021-06-29T13:07:07.848228432Z c=IN IP4 172.18.0.50 2021-06-29T13:07:07.848232603Z b=TIAS:96000 2021-06-29T13:07:07.848235992Z a=ssrc:816694098 cname:72cdb5f53fc2e8fb 2021-06-29T13:07:07.848240381Z a=rtpmap:96 opus/48000/2 2021-06-29T13:07:07.848243923Z a=fmtp:96 useinbandfec=1 2021-06-29T13:07:07.848247725Z a=rtpmap:120 telephone-event/48000 2021-06-29T13:07:07.848386453Z a=fmtp:120 0-16 2021-06-29T13:07:07.848395759Z a=sendrecv 2021-06-29T13:07:07.848399822Z a=rtcp:30019 2021-06-29T13:07:07.848403748Z a=ptime:20 2021-06-29T13:07:07.848407203Z a=ice-ufrag:4Q9H38CE 2021-06-29T13:07:07.848410827Z a=ice-pwd:OR8EfUn5dCLbhZqyiwsTUOyUdW 2021-06-29T13:07:07.848414680Z a=candidate:f75EKiqnFiVfQdoZ 1 UDP 2130706431 172.18.0.50 30018 typ host 2021-06-29T13:07:07.848419247Z a=candidate:f75EKiqnFiVfQdoZ 2 UDP 2130706430 172.18.0.50 30019 typ host 2021-06-29T13:07:07.848432370Z ", "result": "ok" } 2021-06-29T13:07:07.872251466Z [1624972027.871342] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] Created candidate pair f75EKiqnFiVfQdoZ:33d9f4832b3cc9a0:1 between 172.18.0.50 and 172.18.0.40:34404, type prflx 2021-06-29T13:07:07.872276197Z [1624972027.871381] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] Triggering check for f75EKiqnFiVfQdoZ:33d9f4832b3cc9a0:1 2021-06-29T13:07:07.872286600Z [1624972027.871396] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] ICE pair f75EKiqnFiVfQdoZ:33d9f4832b3cc9a0:1 has been nominated by peer 2021-06-29T13:07:07.872289762Z [1624972027.871401] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] ICE not completed yet and no usable candidates 2021-06-29T13:07:07.872292668Z [1624972027.871407] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Successful STUN binding request from 172.18.0.40:34404 2021-06-29T13:07:07.919668940Z [1624972027.918862] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] >>> in_ssrc changed for: 172.18.0.40:34404 new: 70f328c1 2021-06-29T13:07:07.919698433Z [1624972027.918897] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] >>> out_ssrc changed for 192.168.1.93:4002 new: 70f328c1 2021-06-29T13:07:07.919703321Z [1624972027.918911] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64423 TS 2880) 2021-06-29T13:07:07.939554198Z [1624972027.938733] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64424 TS 3840) 2021-06-29T13:07:07.959769679Z [1624972027.959017] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64425 TS 4800) 2021-06-29T13:07:07.979861917Z [1624972027.979067] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64426 TS 5760) 2021-06-29T13:07:07.999566603Z [1624972027.998777] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64427 TS 6720) 2021-06-29T13:07:08.019668998Z [1624972028.018802] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64428 TS 7680) 2021-06-29T13:07:08.040856248Z [1624972028.039663] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64429 TS 8640) 2021-06-29T13:07:08.061133612Z [1624972028.059847] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64430 TS 9600)
Edward
Hi everyone,
I'm using Kamailio (Ver 5.5.1, Public IP X.X.X.11, Private IP 172.18.0.20) + RTPEngine (Ver 9.4.1.1, Public IP X.X.X.7, Private IP 172.18.0.50) alongside Freeswitch (Private IP 172.18.0.40) in my backend and delivering calls to a mobile application (call flow is Freeswitch -> Kamailio + RTPEngine -> Applicaiton). While calls made to NATted destination generally works fine - from time to time, we've experiencing one-sided audio due to the rtpengine sending the media stream to the remote end's private IP instead of his public one. For instance, in the attached logs - media was sent towards 192.168.1.93 instead of 79.179.1.2, which is the expected destination. Problem appears almost randomly; I can make 20 fine calls in a row for the same destination until experiencing it, and I didn't find any difference as it comes to the SIP invite exchange between the two. Has anyone ever experienced the same behavior and can share some general instructions on how to troubleshoot it?
Relevant Kamailio config section is attached.
Invite Kamailio->Device
INVITE sip:972587102881@79.179.1.2:56308;transport=TLS;ob SIP/2.0 Record-Route: sip:X.X.X.11:443;transport=tls;r2=on;lr=on;ftag=cvcHy5UcS9pjj Record-Route: sip:172.18.0.20:5099;r2=on;lr=on;ftag=cvcHy5UcS9pjj Via: SIP/2.0/TLS X.X.X.11:443;branch=z9hG4bK24bf.52b1dd68e26010ba103bd8d6fdb53cf4.0 Via: SIP/2.0/UDP 172.18.0.40;received=172.18.0.40;rport=5060;branch=z9hG4bKH234Q58HpHNKK Max-Forwards: 66 From: "972522149596" sip:FreeSWITCH@172.18.0.20:5099;tag=cvcHy5UcS9pjj To: sip:972587102881@172.18.0.20:5099 Call-ID: be55bd1e-537d-123a-65a9-0242ac120028 CSeq: 37932220 INVITE Contact: sip:gw+kam-in@172.18.0.40:5060;transport=udp;gw=kam-in;alias=172.18.0.40~5060~1 User-Agent: FreeSWITCH-mod_sofia/1.10.6-release+git~20210325T131609Z~1ff9d0a60e~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 567 X-SESSION-ID: 721533765 X-INCOMING: PSTN X-from-freeswitch: +972522149596 X-FS-Support: update_display,send_info Remote-Party-ID: "972522149596" sip:972522149596@172.18.0.20:5099;party=calling;screen=yes;privacy=off
v=0 o=FreeSWITCH 1624937621 1624937622 IN IP4 X.X.X.7 s=FreeSWITCH c=IN IP4 X.X.X.7 t=0 0 m=audio 30018 RTP/AVP 102 101 a=rtpmap:102 opus/48000/2 a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 a=rtpmap:101 telephone-event/48000 a=fmtp:101 0-16 a=sendrecv a=rtcp:30019 a=ptime:20 a=ice-ufrag:bKPZt0dW a=ice-pwd:H4qyL7mPUOvoiAjosiLasXAdzj a=candidate:41sXGEsTafxHi8ms 1 UDP 2130706431 X.X.X.7 30018 typ host a=candidate:41sXGEsTafxHi8ms 2 UDP 2130706430 X.X.X.7 30019 typ host
Response Device->Kamailio
SIP/2.0 200 OK Via: SIP/2.0/TLS X.X.X.11:443;received=X.X.X.11;branch=z9hG4bK24bf.52b1dd68e26010ba103bd8d6fdb53cf4.0 Via: SIP/2.0/UDP 172.18.0.40;rport=5060;received=172.18.0.40;branch=z9hG4bKH234Q58HpHNKK Record-Route: sip:X.X.X.11:443;transport=tls;lr;r2=on;ftag=cvcHy5UcS9pjj Record-Route: sip:172.18.0.20:5099;lr;r2=on;ftag=cvcHy5UcS9pjj Call-ID: be55bd1e-537d-123a-65a9-0242ac120028 From: "972522149596" sip:FreeSWITCH@172.18.0.20;tag=cvcHy5UcS9pjj To: sip:972587102881@172.18.0.20;tag=5f75877e-58c2-44f3-a5b3-43f8786c42a1 CSeq: 37932220 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Contact: sip:972587102881@79.179.1.2:56308;transport=TLS;ob Supported: replaces, 100rel, timer, norefersub Content-Type: application/sdp Content-Length: 348
v=0 o=- 3833960833 3833960834 IN IP4 192.168.1.93 s=pjmedia b=AS:117 t=0 0 a=X-nat:0 m=audio 4002 RTP/AVP 96 120 c=IN IP4 192.168.1.93 b=TIAS:96000 a=rtcp:4003 IN IP4 192.168.1.93 a=sendrecv a=rtpmap:96 opus/48000/2 a=fmtp:96 useinbandfec=1 a=rtpmap:120 telephone-event/48000 a=fmtp:120 0-16 a=ssrc:816694098 cname:72cdb5f53fc2e8fb
Kamailio NAT Detect/Manage Routes
# Caller NAT detection
route[NATDETECT] { #!ifdef WITH_NAT xinfo("NATDETECT: Adding the rport parameter to the first Via header of the received message\n"); force_rport(); xinfo("NATDETECT: Trying to guess if client's request originated behind a nat. Testing 19.\n"); if (nat_uac_test("19")) { if (is_method("REGISTER")) { xinfo("NATDETECT: REGISTER request. Creating a URI consisting of the source IP, port, and protocol and storing the URI in an Attribute-Value-Pair.\n"); fix_nated_register(); } else { if(is_first_hop()) { xinfo("NATDETECT: Adding an ;alias=ip~port~transport parameter to the contact URI containing the received ip, port, and transport protocol.\n"); set_contact_alias(); } } xinfo("NATDETECT: Setting flag FLT_NATS.\n"); setflag(FLT_NATS); } else { xinfo("NATDETECT: Didn't detect natted request by any of the given heuristics\n"); } #!endif return; }
# RTPProxy control and signaling updates for NAT traversal route[NATMANAGE] { #!ifdef WITH_NAT if (is_request()) { if(has_totag()) { if(check_route_param("nat=yes")) { xinfo("NATMANAGE: This is a request with to-tag that has 'nat=yes', setting branch flag FLB_NATB.\n"); setbflag(FLB_NATB); } } }
if (!(isflagset(FLT_NATS) || isbflagset(FLB_NATB))) { xinfo("NATMANAGE: No NAT flag detected for this request\n"); return; } else { xinfo("NATMANAGE: NAT flag detected for this request\n"); }
if(!is_present_hf("x-purpose")) { xinfo("NATMANAGE: x-purpose header does not appear in this request, SDP is searched for occurrence of RFC1918 or RFC6598 addresses.\n"); if(nat_uac_test("8")) { xinfo("NATMANAGE: Found occurrence of RFC1918 or RFC6598 addresses. Checking if there is a match of source address or uri with an address in the group of the dispatcher-list.\n"); if(ds_is_from_list()) { xinfo("NATMANAGE: There is a match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin direction=priv direction=pub"); } else { xinfo("NATMANAGE: No match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin direction=pub direction=priv"); } } else { xinfo("NATMANAGE: No occurrence of RFC1918 or RFC6598 addresses. Checking if there is a match of source address or uri with an address in the group of the dispatcher-list.\n"); if(ds_is_from_list()) { xinfo("NATMANAGE: There is a match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin trust-address direction=priv direction=pub"); } else { xinfo("NATMANAGE: No match with an address in the group of the dispatcher-list.\n"); rtpengine_manage("ICE=force replace-session-connection replace-origin trust-address direction=pub direction=priv"); } } }
if (is_request()) { if (!has_totag()) { if(t_is_branch_route()) { xinfo("NATMANAGE: This is a request without to-tag and top-executed route block is branch_route, adding record route param ;nat=yes.\n"); add_rr_param(";nat=yes"); } } }
if (is_reply()) { if(isbflagset(FLB_NATB)) { if(is_first_hop()) { xinfo("NATMANAGE: Adding an ;alias=ip~port~transport parameter to the contact URI containing the received ip, port, and transport protocol.\n"); set_contact_alias(); } } } #!endif return; }
RTPEngine Logs
2021-06-29T13:07:05.440658779Z [1624972025.439547] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Received command 'offer' from 172.18.0.20:53880 2021-06-29T13:07:05.440690853Z [1624972025.439641] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Dump for 'offer' from 172.18.0.20:53880: { "supports": [ "load limit" ], "sdp": "v=0 2021-06-29T13:07:05.440695330Z o=FreeSWITCH 1624937621 1624937622 IN IP4 172.18.0.40 2021-06-29T13:07:05.440698353Z s=FreeSWITCH 2021-06-29T13:07:05.440700926Z c=IN IP4 172.18.0.40 2021-06-29T13:07:05.440703539Z t=0 0 2021-06-29T13:07:05.440706179Z m=audio 34404 RTP/AVP 102 101 2021-06-29T13:07:05.440708722Z a=rtpmap:102 opus/48000/2 2021-06-29T13:07:05.440711294Z a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 2021-06-29T13:07:05.440714053Z a=rtpmap:101 telephone-event/48000 2021-06-29T13:07:05.440716746Z a=fmtp:101 0-16 2021-06-29T13:07:05.440719258Z a=ptime:20 2021-06-29T13:07:05.440721823Z ", "ICE": "force", "direction": [ "priv", "pub" ], "replace": [ "session-connection", "origin" ], "call-id": "be55bd1e-537d-123a-65a9-0242ac120028", "received-from": [ "IP4", "172.18.0.40" ], "from-tag": "cvcHy5UcS9pjj", "command": "offer" } 2021-06-29T13:07:05.441069790Z [1624972025.439694] NOTICE: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] Creating new call 2021-06-29T13:07:05.441088698Z [1624972025.439809] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Default sink codec is opus/48000/2 2021-06-29T13:07:05.441091829Z [1624972025.439815] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Output DTMF payload type is 101 2021-06-29T13:07:05.441094966Z [1624972025.439821] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for opus/48000/2 2021-06-29T13:07:05.441097777Z [1624972025.439828] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec opus/48000/2 2021-06-29T13:07:05.441100540Z [1624972025.439833] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for opus/48000/2 2021-06-29T13:07:05.441103390Z [1624972025.439839] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for telephone-event/48000 2021-06-29T13:07:05.441106153Z [1624972025.439844] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec telephone-event/48000 2021-06-29T13:07:05.441108913Z [1624972025.439849] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for telephone-event/48000 2021-06-29T13:07:05.441111679Z [1624972025.440116] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 172.18.0.40:34404 2021-06-29T13:07:05.441124990Z [1624972025.440124] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 172.18.0.40:34405 2021-06-29T13:07:05.441663481Z [1624972025.441074] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Replying to 'offer' from 172.18.0.20:53880 (elapsed time 0.001414 sec) 2021-06-29T13:07:05.441694377Z [1624972025.441103] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Response dump for 'offer' to 172.18.0.20:53880: { "sdp": "v=0 2021-06-29T13:07:05.441701068Z o=FreeSWITCH 1624937621 1624937622 IN IP4 X.X.X.7 2021-06-29T13:07:05.441706421Z s=FreeSWITCH 2021-06-29T13:07:05.441711414Z c=IN IP4 X.X.X.7 2021-06-29T13:07:05.441716274Z t=0 0 2021-06-29T13:07:05.441721177Z m=audio 30018 RTP/AVP 102 101 2021-06-29T13:07:05.441726204Z a=rtpmap:102 opus/48000/2 2021-06-29T13:07:05.441731246Z a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40 2021-06-29T13:07:05.441736873Z a=rtpmap:101 telephone-event/48000 2021-06-29T13:07:05.441742017Z a=fmtp:101 0-16 2021-06-29T13:07:05.441827012Z a=sendrecv 2021-06-29T13:07:05.441844744Z a=rtcp:30019 2021-06-29T13:07:05.441848881Z a=ptime:20 2021-06-29T13:07:05.441852444Z a=ice-ufrag:bKPZt0dW 2021-06-29T13:07:05.441856394Z a=ice-pwd:H4qyL7mPUOvoiAjosiLasXAdzj 2021-06-29T13:07:05.441860642Z a=candidate:41sXGEsTafxHi8ms 1 UDP 2130706431 X.X.X.7 30018 typ host 2021-06-29T13:07:05.441864955Z a=candidate:41sXGEsTafxHi8ms 2 UDP 2130706430 X.X.X.7 30019 typ host 2021-06-29T13:07:05.441868967Z ", "result": "ok" } 2021-06-29T13:07:07.001082810Z [1624972027.000176] DEBUG: [core] timer run time = 0.000029 sec 2021-06-29T13:07:07.817899628Z [1624972027.816949] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] >>> in_ssrc changed for: :0 new: 30adc352 2021-06-29T13:07:07.817932021Z [1624972027.816987] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] >>> out_ssrc changed for 172.18.0.40:34405 new: 30adc352 2021-06-29T13:07:07.817936388Z [1624972027.816998] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 201 2021-06-29T13:07:07.817939853Z [1624972027.817025] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] RR from 30adc352 about 0: FL 0 TL 0 HSR 0 J 0 LSR 0 DLSR 0 2021-06-29T13:07:07.817942689Z [1624972027.817030] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] No payload type known for RTCP RR, discarding 2021-06-29T13:07:07.817945696Z [1624972027.817036] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 202 2021-06-29T13:07:07.817948500Z [1624972027.817124] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] Forward to sink endpoint: 172.18.0.40:34405 2021-06-29T13:07:07.818762433Z [1624972027.817995] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 201 2021-06-29T13:07:07.818790347Z [1624972027.818031] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] RR from 30adc352 about 0: FL 0 TL 0 HSR 0 J 0 LSR 0 DLSR 0 2021-06-29T13:07:07.818794422Z [1624972027.818035] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] No payload type known for RTCP RR, discarding 2021-06-29T13:07:07.818797834Z [1624972027.818042] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [rtcp] Calling handler for RTCP packet type 202 2021-06-29T13:07:07.818801095Z [1624972027.818122] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30019]: [core] Forward to sink endpoint: 172.18.0.40:34405 2021-06-29T13:07:07.847992398Z [1624972027.846284] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Received command 'answer' from 172.18.0.20:47817 2021-06-29T13:07:07.848048472Z [1624972027.846325] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Dump for 'answer' from 172.18.0.20:47817: { "supports": [ "load limit" ], "sdp": "v=0 2021-06-29T13:07:07.848058346Z o=- 3833960833 3833960834 IN IP4 192.168.1.93 2021-06-29T13:07:07.848063378Z s=pjmedia 2021-06-29T13:07:07.848067785Z b=AS:117 2021-06-29T13:07:07.848071736Z t=0 0 2021-06-29T13:07:07.848075782Z a=X-nat:0 2021-06-29T13:07:07.848079588Z m=audio 4002 RTP/AVP 96 120 2021-06-29T13:07:07.848084210Z c=IN IP4 192.168.1.93 2021-06-29T13:07:07.848089110Z b=TIAS:96000 2021-06-29T13:07:07.848092756Z a=rtcp:4003 IN IP4 192.168.1.93 2021-06-29T13:07:07.848096578Z a=sendrecv 2021-06-29T13:07:07.848100173Z a=rtpmap:96 opus/48000/2 2021-06-29T13:07:07.848104153Z a=fmtp:96 useinbandfec=1 2021-06-29T13:07:07.848108660Z a=rtpmap:120 telephone-event/48000 2021-06-29T13:07:07.848112776Z a=fmtp:120 0-16 2021-06-29T13:07:07.848116856Z a=ssrc:816694098 cname:72cdb5f53fc2e8fb 2021-06-29T13:07:07.848120776Z ", "ICE": "force", "direction": [ "pub", "priv" ], "replace": [ "session-connection", "origin" ], "call-id": "be55bd1e-537d-123a-65a9-0242ac120028", "received-from": [ "IP4", "79.179.1.2" ], "from-tag": "cvcHy5UcS9pjj", "to-tag": "5f75877e-58c2-44f3-a5b3-43f8786c42a1", "command": "answer" } 2021-06-29T13:07:07.848128079Z [1624972027.846411] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Default sink codec is opus/48000/2 2021-06-29T13:07:07.848132255Z [1624972027.846418] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Output DTMF payload type is 120 2021-06-29T13:07:07.848136164Z [1624972027.846424] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for opus/48000/2 2021-06-29T13:07:07.848139819Z [1624972027.846429] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec opus/48000/2 2021-06-29T13:07:07.848143930Z [1624972027.846434] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for opus/48000/2 2021-06-29T13:07:07.848169208Z [1624972027.846441] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Creating codec handler for telephone-event/48000 2021-06-29T13:07:07.848174300Z [1624972027.846445] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Sink supports codec telephone-event/48000 2021-06-29T13:07:07.848178752Z [1624972027.846449] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [codec] Using passthrough handler for telephone-event/48000 2021-06-29T13:07:07.848183460Z [1624972027.846586] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 192.168.1.93:4002 2021-06-29T13:07:07.848188805Z [1624972027.846593] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [core] set FILLED flag for stream 192.168.1.93:4003 2021-06-29T13:07:07.848193111Z [1624972027.846597] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [ice] Shutting down ICE agent (nothing to do) 2021-06-29T13:07:07.848197042Z [1624972027.847228] INFO: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Replying to 'answer' from 172.18.0.20:47817 (elapsed time 0.000890 sec) 2021-06-29T13:07:07.848201623Z [1624972027.847243] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028]: [control] Response dump for 'answer' to 172.18.0.20:47817: { "sdp": "v=0 2021-06-29T13:07:07.848205754Z o=- 3833960833 3833960834 IN IP4 172.18.0.50 2021-06-29T13:07:07.848209696Z s=pjmedia 2021-06-29T13:07:07.848213446Z b=AS:117 2021-06-29T13:07:07.848217361Z t=0 0 2021-06-29T13:07:07.848220816Z a=X-nat:0 2021-06-29T13:07:07.848224363Z m=audio 30018 RTP/AVP 96 120 2021-06-29T13:07:07.848228432Z c=IN IP4 172.18.0.50 2021-06-29T13:07:07.848232603Z b=TIAS:96000 2021-06-29T13:07:07.848235992Z a=ssrc:816694098 cname:72cdb5f53fc2e8fb 2021-06-29T13:07:07.848240381Z a=rtpmap:96 opus/48000/2 2021-06-29T13:07:07.848243923Z a=fmtp:96 useinbandfec=1 2021-06-29T13:07:07.848247725Z a=rtpmap:120 telephone-event/48000 2021-06-29T13:07:07.848386453Z a=fmtp:120 0-16 2021-06-29T13:07:07.848395759Z a=sendrecv 2021-06-29T13:07:07.848399822Z a=rtcp:30019 2021-06-29T13:07:07.848403748Z a=ptime:20 2021-06-29T13:07:07.848407203Z a=ice-ufrag:4Q9H38CE 2021-06-29T13:07:07.848410827Z a=ice-pwd:OR8EfUn5dCLbhZqyiwsTUOyUdW 2021-06-29T13:07:07.848414680Z a=candidate:f75EKiqnFiVfQdoZ 1 UDP 2130706431 172.18.0.50 30018 typ host 2021-06-29T13:07:07.848419247Z a=candidate:f75EKiqnFiVfQdoZ 2 UDP 2130706430 172.18.0.50 30019 typ host 2021-06-29T13:07:07.848432370Z ", "result": "ok" } 2021-06-29T13:07:07.872251466Z [1624972027.871342] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] Created candidate pair f75EKiqnFiVfQdoZ:33d9f4832b3cc9a0:1 between 172.18.0.50 and 172.18.0.40:34404, type prflx 2021-06-29T13:07:07.872276197Z [1624972027.871381] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] Triggering check for f75EKiqnFiVfQdoZ:33d9f4832b3cc9a0:1 2021-06-29T13:07:07.872286600Z [1624972027.871396] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] ICE pair f75EKiqnFiVfQdoZ:33d9f4832b3cc9a0:1 has been nominated by peer 2021-06-29T13:07:07.872289762Z [1624972027.871401] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [ice] ICE not completed yet and no usable candidates 2021-06-29T13:07:07.872292668Z [1624972027.871407] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Successful STUN binding request from 172.18.0.40:34404 2021-06-29T13:07:07.919668940Z [1624972027.918862] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] >>> in_ssrc changed for: 172.18.0.40:34404 new: 70f328c1 2021-06-29T13:07:07.919698433Z [1624972027.918897] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] >>> out_ssrc changed for 192.168.1.93:4002 new: 70f328c1 2021-06-29T13:07:07.919703321Z [1624972027.918911] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64423 TS 2880) 2021-06-29T13:07:07.939554198Z [1624972027.938733] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64424 TS 3840) 2021-06-29T13:07:07.959769679Z [1624972027.959017] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64425 TS 4800) 2021-06-29T13:07:07.979861917Z [1624972027.979067] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64426 TS 5760) 2021-06-29T13:07:07.999566603Z [1624972027.998777] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64427 TS 6720) 2021-06-29T13:07:08.019668998Z [1624972028.018802] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64428 TS 7680) 2021-06-29T13:07:08.040856248Z [1624972028.039663] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64429 TS 8640) 2021-06-29T13:07:08.061133612Z [1624972028.059847] DEBUG: [be55bd1e-537d-123a-65a9-0242ac120028 port 30018]: [core] Forward to sink endpoint: 192.168.1.93:4002 (RTP seq 64430 TS 9600)
Edward