Remote Extensions behind NAT - Registering but no audio

Hi All,

I am looking to achieve the following setup:
Phone (local net 192.168.1.0) <-> NAT Router A <-> Internet <-> NAT Router B <-> Fusion PBX (local net 192.168.0.0)

Using dynamic DNS for NAT Router B and opening SIP+RTP ports in routers+firewalls I am managing to register the phone to Fusion PBX but there is no audio.

Checking the logs, the problem is that FusionPBX after RTP port is assigned is trying to connect to the local IP address of the phone 192.168.1.x with apparently no luck.
I have followed instructions about changing sip profile settings to external_rtp_ip to auto-nat and have restarted freeswitch, but this had no effect.
Interesting enough, in fs_cli, when running sofia status profile internal there is no external_rtp_ip variable defined.

Could anyone point to some thread or provide a hint, please, as I have been trying various tweaks and searching the forums with no luck?

Many Thanks for any feedback,

Vangelis
 
Sure, please find below a redacted one.

Setup is:
IP Phone (local 192.168.1.20) <-> NAT Router A <-> Internet <-> NAT Router B <-> Fusion PBX (local IP 192.168.0.10)

Many Thanks for any help!




=================================================================================================
Name internal
Domain Name N/A
Auto-NAT false
DBName sofia_reg_internal
Pres Hosts
Dialplan XML
Context public
Challenge Realm auto_to
RTP-IP 192.168.0.10
SIP-IP 192.168.0.10
URL sip:mod_sofia@192.168.0.10:5060
BIND-URL sip:mod_sofia@192.168.0.10:5060;transport=udp,tcp
HOLD-MUSIC local_stream://default
OUTBOUND-PROXY N/A
CODECS IN G7221@32000h,G7221@16000h,G722,PCMU,PCMA,GSM
CODECS OUT G7221@32000h,G7221@16000h,G722,PCMU,PCMA,GSM
TEL-EVENT 101
DTMF-MODE rfc2833
CNG 13
SESSION-TO 0
MAX-DIALOG 0
NOMEDIA false
LATE-NEG false
PROXY-MEDIA false
ZRTP-PASSTHRU false
AGGRESSIVENAT true
CALLS-IN 210
FAILED-CALLS-IN 28
CALLS-OUT 230
FAILED-CALLS-OUT 140
REGISTRATIONS 5

2018-04-24 03:54:36.149366 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'internal' for [120@192.168.0.10] from ip <<remote.ip.domain>>

2018-04-24 03:55:06.649354 [DEBUG] sofia.c:9873 sofia/internal/120@192.168.0.10:5060 receiving invite from <<remote.ip.domain>>:12406 version: 1.6.20 -37-987c9b9 64bit
2018-04-24 03:55:06.649354 [DEBUG] sofia.c:10044 IP <<remote.ip.domain>> Rejected by acl "domains". Falling back to Digest auth.
2018-04-24 03:55:06.649354 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [<<Tel called>>@192.168.0.10] from ip <<remote.ip.domain>>
2018-04-24 03:55:06.649354 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/120@192.168.0.10:5060) State NEW
2018-04-24 03:55:06.649354 [DEBUG] sofia.c:2334 detaching session a118a857-9cb7-4260-bd54-3d8d7d3656a6
2018-04-24 03:55:06.709253 [DEBUG] sofia.c:2442 Re-attaching to session a118a857-9cb7-4260-bd54-3d8d7d3656a6
2018-04-24 03:55:06.729304 [DEBUG] sofia.c:9873 sofia/internal/120@192.168.0.10:5060 receiving invite from <<remote.ip.domain>>:12406 version: 1.6.20 -37-987c9b9 64bit
2018-04-24 03:55:06.729304 [DEBUG] sofia.c:10044 IP <<remote.ip.domain>> Rejected by acl "domains". Falling back to Digest auth.
2018-04-24 03:55:06.729304 [DEBUG] sofia.c:11168 Setting NAT mode based on via received
2018-04-24 03:55:06.729304 [DEBUG] sofia.c:7084 Channel sofia/internal/120@192.168.0.10:5060 entering state [received][100]
2018-04-24 03:55:06.729304 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=- 20055 20055 IN IP4 192.168.1.20
s=SDP data
c=IN IP4 192.168.1.20
t=0 0
m=audio 21878 RTP/AVP 107 9 0 8 18 101
a=rtpmap:107 opus/48000/2
a=fmtp:107 sprop-maxcapturerate=16000; maxaveragebitrate=20000; maxplaybackrate=48000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2018-04-24 03:55:06.729304 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [opus:107:48000:20:0:2]/[G722:9:8000:20:64000:1]

2018-04-24 03:55:06.729304 [DEBUG] sofia.c:7507 (sofia/internal/120@192.168.0.10:5060) State Change CS_NEW -> CS_INIT
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/120@192.168.0.10:5060) Running State Change CS_INIT (Cur 1 Tot 371)
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/120@192.168.0.10:5060) State INIT
2018-04-24 03:55:06.729304 [DEBUG] mod_sofia.c:90 sofia/internal/120@192.168.0.10:5060 SOFIA INIT
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:40 sofia/internal/120@192.168.0.10:5060 Standard INIT
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/120@192.168.0.10:5060) State Change CS_INIT -> CS_ROUTING
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/120@192.168.0.10:5060) State INIT going to sleep
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/120@192.168.0.10:5060) Running State Change CS_ROUTING (Cur 1 Tot 371)
2018-04-24 03:55:06.729304 [DEBUG] switch_channel.c:2249 (sofia/internal/120@192.168.0.10:5060) Callstate Change DOWN -> RINGING
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/120@192.168.0.10:5060) State ROUTING
2018-04-24 03:55:06.729304 [DEBUG] mod_sofia.c:143 sofia/internal/120@192.168.0.10:5060 SOFIA ROUTING
2018-04-24 03:55:06.729304 [DEBUG] switch_core_state_machine.c:236 sofia/internal/120@192.168.0.10:5060 Standard ROUTING
2018-04-24 03:55:06.729304 [INFO] mod_dialplan_xml.c:637 Processing Office <120>-><<Tel called>> in context 192.168.0.10
Dialplan: sofia/internal/120@192.168.0.10:5060 parsing [192.168.0.10->user_exists] continue=true
Dialplan: sofia/internal/120@192.168.0.10:5060 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
2018-04-24 03:55:06.749245 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f3388052760 Connected.
2018-04-24 03:55:06.749245 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f3388052760 released.
EXECUTE sofia/internal/120@192.168.0.10:5060 set(user_exists=false)
2018-04-24 03:55:06.749245 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [user_exists]=[false]
Dialplan: sofia/internal/120@192.168.0.10:5060 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/120@192.168.0.10:5060 parsing [192.168.0.10->call-direction] continue=true
Dialplan: sofia/internal/120@192.168.0.10:5060 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/120@192.168.0.10:5060 ANTI-Action set(call_direction=local)
Dialplan: sofia/internal/120@192.168.0.10:5060 parsing [192.168.0.10->variables] continue=true
Dialplan: sofia/internal/120@192.168.0.10:5060 Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/120@192.168.0.10:5060 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/120@192.168.0.10:5060 parsing [192.168.0.10->user_record] continue=true
Dialplan: sofia/internal/120@192.168.0.10:5060 Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
2018-04-24 03:55:06.749245 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f3388052760 Connected.
2018-04-24 03:55:06.749245 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f3388052760 released.
2018-04-24 03:55:06.749245 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f3388052760 Connected.
2018-04-24 03:55:06.749245 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f3388052760 released.
EXECUTE sofia/internal/120@192.168.0.10:5060 set(user_record=)
2018-04-24 03:55:06.749245 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [user_record]=[UNDEF]
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE sofia/internal/120@192.168.0.10:5060 set(from_user_exists=true)
2018-04-24 03:55:06.749245 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [from_user_exists]=[true]

Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(call_direction=outbound)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action unset(call_timeout)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(inherit_codec=true)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(ignore_display_updates=true)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(callee_id_number=<<Tel called>>)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action set(continue_on_fail=true)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action bridge(sofia/gateway/a2a13654-dd66-438d-b7bd-a2a4ba6873de/<<Tel called>>)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action bridge(sofia/gateway/edcc66a3-3889-49e4-8ae6-13a23e391b9a/<<Tel called>>)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action bridge(sofia/gateway/34ca4d63-125b-40e5-b1df-d15e238a3b50/<<Tel called>>)
Dialplan: sofia/internal/120@192.168.0.10:5060 Action bridge(sofia/gateway/75e1d59f-974f-4378-8092-1129c0765937/<<Tel called>>)
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/120@192.168.0.10:5060) State Change CS_ROUTING -> CS_EXECUTE
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/120@192.168.0.10:5060) State ROUTING going to sleep
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/120@192.168.0.10:5060) Running State Change CS_EXECUTE (Cur 1 Tot 371)
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/120@192.168.0.10:5060) State EXECUTE
2018-04-24 03:55:06.769243 [DEBUG] mod_sofia.c:198 sofia/internal/120@192.168.0.10:5060 SOFIA EXECUTE
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:328 sofia/internal/120@192.168.0.10:5060 Standard EXECUTE
EXECUTE sofia/internal/120@192.168.0.10:5060 set(call_direction=local)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [call_direction]=[local]
EXECUTE sofia/internal/120@192.168.0.10:5060 export(origination_callee_id_name=<<Tel called>>)
2018-04-24 03:55:06.769243 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[<<Tel called>>]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(RFC2822_DATE=Tue, 24 Apr 2018 03:55:06 -0400)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [RFC2822_DATE]=[Tue, 24 Apr 2018 03:55:06 -0400]
EXECUTE sofia/internal/120@192.168.0.10:5060 hash(insert/192.168.0.10-last_dial/120/<<Tel called>>)
EXECUTE sofia/internal/120@192.168.0.10:5060 set(sip_h_X-accountcode=192.168.0.10)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [sip_h_X-accountcode]=[192.168.0.10]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(call_direction=outbound)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [call_direction]=[outbound]
EXECUTE sofia/internal/120@192.168.0.10:5060 unset(call_timeout)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1693 UNSET [call_timeout]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(hangup_after_bridge=true)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(effective_caller_id_name=)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(effective_caller_id_number=)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [effective_caller_id_number]=[UNDEF]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(inherit_codec=true)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [inherit_codec]=[true]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(ignore_display_updates=true)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [ignore_display_updates]=[true]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(callee_id_number=<<Tel called>>)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [callee_id_number]=[<<Tel called>>]
EXECUTE sofia/internal/120@192.168.0.10:5060 set(continue_on_fail=true)
2018-04-24 03:55:06.769243 [DEBUG] mod_dptools.c:1548 SET sofia/internal/120@192.168.0.10:5060 [continue_on_fail]=[true]
EXECUTE sofia/internal/120@192.168.0.10:5060 bridge(sofia/gateway/a2a13654-dd66-438d-b7bd-a2a4ba6873de/<<Tel called>>)
2018-04-24 03:55:06.769243 [DEBUG] switch_channel.c:1250 sofia/internal/120@192.168.0.10:5060 EXPORTING[export_vars] [domain_name]=[192.168.0.10] to event
2018-04-24 03:55:06.769243 [DEBUG] switch_channel.c:1250 sofia/internal/120@192.168.0.10:5060 EXPORTING[export_vars] [origination_callee_id_name]=[<<Tel called>>] to event
2018-04-24 03:55:06.769243 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2018-04-24 03:55:06.769243 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/<<Tel called>> [a701f96b-fce0-45b2-a6ea-28a8083b4ff8]
2018-04-24 03:55:06.769243 [DEBUG] mod_sofia.c:4819 (sofia/internal/<<Tel called>>) State Change CS_NEW -> CS_INIT
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/<<Tel called>>) Running State Change CS_INIT (Cur 2 Tot 372)
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/<<Tel called>>) State INIT
2018-04-24 03:55:06.769243 [DEBUG] mod_sofia.c:90 sofia/internal/<<Tel called>> SOFIA INIT
2018-04-24 03:55:06.769243 [DEBUG] sofia_glue.c:1295 sofia/internal/<<Tel called>> sending invite version: 1.6.20 -37-987c9b9 64bit
Local SDP:
v=0
o=FreeSWITCH 1524531412 1524531413 IN IP4 192.168.0.10
s=FreeSWITCH
c=IN IP4 192.168.0.10
t=0 0
m=audio 25094 RTP/AVP 9 0 8 3 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:40 sofia/internal/<<Tel called>> Standard INIT
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/<<Tel called>>) State Change CS_INIT -> CS_ROUTING
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/<<Tel called>>) State INIT going to sleep
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/<<Tel called>>) Running State Change CS_ROUTING (Cur 2 Tot 372)
2018-04-24 03:55:06.769243 [DEBUG] sofia.c:7084 Channel sofia/internal/<<Tel called>> entering state [calling][0]
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/<<Tel called>>) State ROUTING
2018-04-24 03:55:06.769243 [DEBUG] mod_sofia.c:143 sofia/internal/<<Tel called>> SOFIA ROUTING
2018-04-24 03:55:06.769243 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/<<Tel called>>) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/<<Tel called>>) State ROUTING going to sleep
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/<<Tel called>>) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 372)
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/<<Tel called>>) State CONSUME_MEDIA
2018-04-24 03:55:06.769243 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/<<Tel called>>) State CONSUME_MEDIA going to sleep
2018-04-24 03:55:09.669430 [DEBUG] sofia.c:7084 Channel sofia/internal/<<Tel called>> entering state [proceeding][180]
2018-04-24 03:55:09.669430 [NOTICE] sofia.c:7192 Ring-Ready sofia/internal/<<Tel called>>!
2018-04-24 03:55:09.669430 [DEBUG] switch_channel.c:3346 (sofia/internal/<<Tel called>>) Callstate Change DOWN -> RINGING
2018-04-24 03:55:09.689251 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/internal/120@192.168.0.10:5060!
2018-04-24 03:55:09.689251 [DEBUG] sofia.c:7084 Channel sofia/internal/120@192.168.0.10:5060 entering state [early][180]
2018-04-24 03:55:09.689251 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/120@192.168.0.10:5060!
2018-04-24 03:55:23.409341 [DEBUG] sofia.c:7084 Channel sofia/internal/<<Tel called>> entering state [completing][200]
2018-04-24 03:55:23.409341 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=40196 8001 8000 IN IP4 192.168.0.11
s=SIP Call
c=IN IP4 192.168.0.11
t=0 0
m=audio 5008 RTP/AVP 0 8 4 18 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
a=ptime:20

2018-04-24 03:55:23.409341 [DEBUG] sofia.c:7084 Channel sofia/internal/<<Tel called>> entering state [ready][200]

2018-04-24 03:55:23.409341 [DEBUG] switch_core_media.c:7210 sofia/internal/<<Tel called>> Set rtp dtmf delay to 40
2018-04-24 03:55:23.409341 [NOTICE] sofia.c:8218 Channel [sofia/internal/<<Tel called>>] has been answered
2018-04-24 03:55:23.409341 [DEBUG] switch_channel.c:3773 (sofia/internal/<<Tel called>>) Callstate Change RINGING -> ACTIVE
2018-04-24 03:55:23.429254 [DEBUG] switch_ivr_originate.c:410 Setting codec string on sofia/internal/120@192.168.0.10:5060 to PCMU@8000h@20i
2018-04-24 03:55:23.429254 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/internal/120@192.168.0.10:5060] 192.168.0.10 port 23012 -> 192.168.1.20 port 21878 codec: 9 ms: 20

2018-04-24 03:55:23.429254 [DEBUG] mod_sofia.c:850 Local SDP sofia/internal/120@192.168.0.10:5060:
v=0
o=FreeSWITCH 1524533511 1524533512 IN IP4 192.168.0.10
s=FreeSWITCH
c=IN IP4 192.168.0.10
t=0 0
m=audio 23012 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2018-04-24 03:55:23.429254 [NOTICE] switch_ivr_originate.c:3647 Channel [sofia/internal/120@192.168.0.10:5060] has been answered
2018-04-24 03:55:23.429254 [DEBUG] switch_channel.c:3773 (sofia/internal/120@192.168.0.10:5060) Callstate Change RINGING -> ACTIVE
2018-04-24 03:55:23.429254 [DEBUG] sofia.c:7084 Channel sofia/internal/120@192.168.0.10:5060 entering state [completed][200]
2018-04-24 03:55:23.429254 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/internal/<<Tel called>>]
2018-04-24 03:55:23.429254 [DEBUG] switch_ivr_bridge.c:1614 (sofia/internal/<<Tel called>>) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2018-04-24 03:55:23.429254 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/<<Tel called>>) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 372)
2018-04-24 03:55:23.429254 [DEBUG] switch_core_state_machine.c:653 (sofia/internal/<<Tel called>>) State EXCHANGE_MEDIA
2018-04-24 03:55:23.429254 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2018-04-24 03:55:23.469243 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2018-04-24 03:55:23.469243 [NOTICE] switch_core_io.c:1202 Activating write resampler

2018-04-24 03:55:28.769407 [DEBUG] switch_ivr_bridge.c:706 sofia/internal/120@192.168.0.10:5060 ending bridge by request from write function

2018-04-24 03:55:28.769407 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/<<Tel called>>) State REPORTING going to sleep
2018-04-24 03:55:28.769407 [DEBUG] switch_core_state_machine.c:60 sofia/internal/120@192.168.0.10:5060 Standard HANGUP, cause: NORMAL_CLEARING