Outbound calls drop ACK not received

Status
Not open for further replies.
R

ryanp

New Member
Apr 20, 2019
3
0
1
31
Hi Guys,

I'm using FusionPBX with Twilio as a gateway - inbound calls are working perfectly, however outbound calls are dropping after 30 seconds.
After many hours of searching and frustration I humbly come to ask for some help.
It seems that although the INVITE appears to be being ACK'd to me, it's not detected and the call drops after the bridge thread ends.
Any pointers would be much appreciated! Thanks.

sip_trace:
freeswitch@pbx> sofia global siptrace on
+OK Global siptrace on
recv 1063 bytes from udp/[192.168.1.56]:5060 at 11:37:30.063444:
------------------------------------------------------------------------
INVITE sip:*redacted*@192.168.1.38 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK02a4ed4d
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
Max-Forwards: 70
Date: Wed, 26 Jun 2019 10:37:30 GMT
CSeq: 101 INVITE
User-Agent: Cisco-CP7960G/8.0
Contact: <sip:2000@192.168.1.56:5060;transport=udp>
Expires: 180
Accept: application/sdp
Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE
Remote-Party-ID: "2000" <sip:2000@192.168.1.38>;party=calling;id-type=subscriber;privacy=off;screen=yes
Supported: replaces,join,norefersub
Content-Length: 275
Content-Type: application/sdp
Content-Disposition: session;handling=optional

v=0
o=Cisco-SIPUA 8955 0 IN IP4 192.168.1.56
s=SIP Call
t=0 0
m=audio 23800 RTP/AVP 0 8 18 101
c=IN IP4 192.168.1.56
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=sendrecv
------------------------------------------------------------------------
2019-06-26 11:37:30.044520 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/2000@192.168.1.38 [94f3121b-6da0-4135-88f1-627a1c4b6dcf]
2019-06-26 11:37:30.044520 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2000@192.168.1.38) Running State Change CS_NEW (Cur 1 Tot 3)
2019-06-26 11:37:30.064448 [DEBUG] sofia.c:10092 sofia/internal/2000@192.168.1.38 receiving invite from 192.168.1.56:5060 version: 1.8.5 -6-31281a0bf1 64bit
2019-06-26 11:37:30.064448 [DEBUG] sofia.c:10263 IP 192.168.1.56 Rejected by acl "domains". Falling back to Digest auth.
2019-06-26 11:37:30.064448 [WARNING] sofia_reg.c:1798 SIP auth challenge (INVITE) on sofia profile 'internal' for [*redacted*@192.168.1.38] from ip 192.168.1.56
2019-06-26 11:37:30.064448 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/2000@192.168.1.38) State NEW
send 819 bytes to udp/[192.168.1.56]:5060 at 11:37:30.065297:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK02a4ed4d
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=9trDZaF0yFjcQ
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 101 INVITE
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Proxy-Authenticate: Digest realm="192.168.1.38", nonce="", algorithm=MD5, qop="auth"
Content-Length: 0

------------------------------------------------------------------------
2019-06-26 11:37:30.064448 [DEBUG] sofia.c:2413 detaching session 94f3121b-6da0-4135-88f1-627a1c4b6dcf
recv 369 bytes from udp/[192.168.1.56]:5060 at 11:37:30.156593:
------------------------------------------------------------------------
ACK sip:*redacted*@192.168.1.38 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK02a4ed4d
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=9trDZaF0yFjcQ
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
Date: Wed, 26 Jun 2019 10:37:30 GMT
CSeq: 101 ACK
Content-Length: 0

------------------------------------------------------------------------
recv 1309 bytes from udp/[192.168.1.56]:5060 at 11:37:30.229729:
------------------------------------------------------------------------
INVITE sip:*redacted*@192.168.1.38 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
Max-Forwards: 70
Date: Wed, 26 Jun 2019 10:37:30 GMT
CSeq: 102 INVITE
User-Agent: Cisco-CP7960G/8.0
Contact: <sip:2000@192.168.1.56:5060;transport=udp>
Proxy-Authorization: Digest username="2000",realm="192.168.1.38",uri="sip:*redacted*@192.168.1.38",response="",nonce="",cnonce="",qop=auth,nc=00000001,algorithm=MD5
Expires: 180
Accept: application/sdp
Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE
Remote-Party-ID: "2000" <sip:2000@192.168.1.38>;party=calling;id-type=subscriber;privacy=off;screen=yes
Supported: replaces,join,norefersub
Content-Length: 275
Content-Type: application/sdp
Content-Disposition: session;handling=optional

v=0
o=Cisco-SIPUA 8955 0 IN IP4 192.168.1.56
s=SIP Call
t=0 0
m=audio 23800 RTP/AVP 0 8 18 101
c=IN IP4 192.168.1.56
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=sendrecv
------------------------------------------------------------------------
2019-06-26 11:37:30.224519 [DEBUG] sofia.c:2522 Re-attaching to session 94f3121b-6da0-4135-88f1-627a1c4b6dcf
2019-06-26 11:37:30.244517 [DEBUG] sofia.c:10092 sofia/internal/2000@192.168.1.38 receiving invite from 192.168.1.56:5060 version: 1.8.5 -6-31281a0bf1 64bit
2019-06-26 11:37:30.244517 [DEBUG] sofia.c:10263 IP 192.168.1.56 Rejected by acl "domains". Falling back to Digest auth.
2019-06-26 11:37:30.244517 [DEBUG] sofia.c:7291 Channel sofia/internal/2000@192.168.1.38 entering state [received][100]
2019-06-26 11:37:30.244517 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=Cisco-SIPUA 8955 0 IN IP4 192.168.1.56
s=SIP Call
t=0 0
m=audio 23800 RTP/AVP 0 8 18 101
c=IN IP4 192.168.1.56
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

2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/2000@192.168.1.38 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-06-26 11:37:30.244517 [DEBUG] switch_core_codec.c:111 sofia/internal/2000@192.168.1.38 Original read codec set to PCMU:0
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
2019-06-26 11:37:30.244517 [DEBUG] switch_core_media.c:5795 sofia/internal/2000@192.168.1.38 Set 2833 dtmf send payload to 101 recv payload to 101
2019-06-26 11:37:30.244517 [DEBUG] sofia.c:7716 (sofia/internal/2000@192.168.1.38) State Change CS_NEW -> CS_INIT
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2000@192.168.1.38) Running State Change CS_INIT (Cur 1 Tot 3)
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/2000@192.168.1.38) State INIT
2019-06-26 11:37:30.244517 [DEBUG] mod_sofia.c:93 sofia/internal/2000@192.168.1.38 SOFIA INIT
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:40 sofia/internal/2000@192.168.1.38 Standard INIT
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/2000@192.168.1.38) State Change CS_INIT -> CS_ROUTING
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/2000@192.168.1.38) State INIT going to sleep
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2000@192.168.1.38) Running State Change CS_ROUTING (Cur 1 Tot 3)
2019-06-26 11:37:30.244517 [DEBUG] switch_channel.c:2249 (sofia/internal/2000@192.168.1.38) Callstate Change DOWN -> RINGING
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/2000@192.168.1.38) State ROUTING
2019-06-26 11:37:30.244517 [DEBUG] mod_sofia.c:154 sofia/internal/2000@192.168.1.38 SOFIA ROUTING
2019-06-26 11:37:30.244517 [DEBUG] switch_core_state_machine.c:236 sofia/internal/2000@192.168.1.38 Standard ROUTING
2019-06-26 11:37:30.244517 [INFO] mod_dialplan_xml.c:637 Processing 2000 <2000>->*redacted* in context 192.168.1.38
send 316 bytes to udp/[192.168.1.56]:5060 at 11:37:30.259508:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
User-Agent: FreeSWITCH
Content-Length: 0

------------------------------------------------------------------------
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->user_exists] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_exists] () =~ // break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(user_exists=false)
2019-06-26 11:37:30.284453 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [user_exists]=[false]
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->caller-details] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [caller-details] ${caller_destination}() =~ /^$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Action set(caller_destination=${destination_number}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(caller_destination=*redacted*)
2019-06-26 11:37:30.284453 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [caller_destination]=[*redacted*]
Dialplan: sofia/internal/2000@192.168.1.38 Action set(caller_id_name=${caller_id_name}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(caller_id_name=2000)
2019-06-26 11:37:30.284453 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [caller_id_name]=[2000]
Dialplan: sofia/internal/2000@192.168.1.38 Action set(caller_id_number=${caller_id_number}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(caller_id_number=2000)
2019-06-26 11:37:30.284453 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [caller_id_number]=[2000]
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->variables] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [variables] () =~ // break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 Action export(origination_callee_id_name=${destination_number})
Dialplan: sofia/internal/2000@192.168.1.38 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->call-direction] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 ANTI-Action export(call_direction=local)
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->user_record] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_record] () =~ // break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 Action set(user_record=${user_data ${destination_number}@${domain_name} var user_record}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(user_record=)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [user_record]=[UNDEF]
Dialplan: sofia/internal/2000@192.168.1.38 Action set(from_user_exists=${user_exists id ${sip_from_user} ${sip_from_host}}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(from_user_exists=true)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [from_user_exists]=[true]
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_exists}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Action set(from_user_record=${user_data ${sip_from_user}@${sip_from_host} var user_record}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(from_user_record=)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [from_user_record]=[UNDEF]
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${from_user_record}() =~ /^all$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${call_direction}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${from_user_record}() =~ /^inbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${call_direction}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${from_user_record}() =~ /^outbound$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [user_record] ${from_user_exists}(true) =~ /^true$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${call_direction}() =~ /^local$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${from_user_record}() =~ /^local$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [user_record] ${record_session}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->redial] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [redial] destination_number(*redacted*) =~ /^(redial|\*870)$/ break=on-true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [redial] () =~ // break=never
Dialplan: sofia/internal/2000@192.168.1.38 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->speed_dial] continue=false
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [speed_dial] destination_number(*redacted*) =~ /^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->default_caller_id] continue=true
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [default_caller_id] ${emergency_caller_id_number}() =~ /^$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 Action set(emergency_caller_id_name=${default_emergency_caller_id_name}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(emergency_caller_id_name=)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [emergency_caller_id_name]=[UNDEF]
Dialplan: sofia/internal/2000@192.168.1.38 Action set(emergency_caller_id_number=${default_emergency_caller_id_number}) INLINE
EXECUTE sofia/internal/2000@192.168.1.38 set(emergency_caller_id_number=)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [emergency_caller_id_number]=[UNDEF]
Dialplan: sofia/internal/2000@192.168.1.38 Regex (FAIL) [default_caller_id] ${outbound_caller_id_number}(+441202001908) =~ /^$/ break=never
Dialplan: sofia/internal/2000@192.168.1.38 parsing [192.168.1.38->Twilio.0019d9] continue=false
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [Twilio.0019d9] ${user_exists}(false) =~ /false/ break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 Regex (PASS) [Twilio.0019d9] destination_number(*redacted*) =~ /^(?:00|\+)([1-9]\d{9,})$/ break=on-false
Dialplan: sofia/internal/2000@192.168.1.38 Action set(sip_h_X-accountcode=${accountcode})
Dialplan: sofia/internal/2000@192.168.1.38 Action export(call_direction=outbound)
Dialplan: sofia/internal/2000@192.168.1.38 Action unset(call_timeout)
Dialplan: sofia/internal/2000@192.168.1.38 Action set(hangup_after_bridge=false)
Dialplan: sofia/internal/2000@192.168.1.38 Action set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/2000@192.168.1.38 Action set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/2000@192.168.1.38 Action set(inherit_codec=true)
Dialplan: sofia/internal/2000@192.168.1.38 Action set(ignore_display_updates=true)
Dialplan: sofia/internal/2000@192.168.1.38 Action set(callee_id_number=*redacted*)
Dialplan: sofia/internal/2000@192.168.1.38 Action set(continue_on_fail=true)
Dialplan: sofia/internal/2000@192.168.1.38 Action bridge(sofia/gateway/20be6af9-1c24-4e02-9282-6f574b836910/*redacted*)
2019-06-26 11:37:30.304449 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/2000@192.168.1.38) State Change CS_ROUTING -> CS_EXECUTE
2019-06-26 11:37:30.304449 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/2000@192.168.1.38) State ROUTING going to sleep
2019-06-26 11:37:30.304449 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2000@192.168.1.38) Running State Change CS_EXECUTE (Cur 1 Tot 3)
2019-06-26 11:37:30.304449 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/2000@192.168.1.38) State EXECUTE
2019-06-26 11:37:30.304449 [DEBUG] mod_sofia.c:209 sofia/internal/2000@192.168.1.38 SOFIA EXECUTE
2019-06-26 11:37:30.304449 [DEBUG] switch_core_state_machine.c:328 sofia/internal/2000@192.168.1.38 Standard EXECUTE
EXECUTE sofia/internal/2000@192.168.1.38 export(origination_callee_id_name=*redacted*)
2019-06-26 11:37:30.304449 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [origination_callee_id_name]=[*redacted*]
EXECUTE sofia/internal/2000@192.168.1.38 set(RFC2822_DATE=Wed, 26 Jun 2019 11:37:30 +0100)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [RFC2822_DATE]=[Wed, 26 Jun 2019 11:37:30 +0100]
EXECUTE sofia/internal/2000@192.168.1.38 export(call_direction=local)
2019-06-26 11:37:30.304449 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[local]
EXECUTE sofia/internal/2000@192.168.1.38 hash(insert/192.168.1.38-last_dial/2000/*redacted*)
EXECUTE sofia/internal/2000@192.168.1.38 set(sip_h_X-accountcode=)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [sip_h_X-accountcode]=[UNDEF]
EXECUTE sofia/internal/2000@192.168.1.38 export(call_direction=outbound)
2019-06-26 11:37:30.304449 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_direction]=[outbound]
EXECUTE sofia/internal/2000@192.168.1.38 unset(call_timeout)
2019-06-26 11:37:30.304449 [DEBUG] mod_dptools.c:1743 UNSET [call_timeout]
EXECUTE sofia/internal/2000@192.168.1.38 set(hangup_after_bridge=false)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [hangup_after_bridge]=[false]
EXECUTE sofia/internal/2000@192.168.1.38 set(effective_caller_id_name=Uncubed Technology)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [effective_caller_id_name]=[Uncubed Technology]
EXECUTE sofia/internal/2000@192.168.1.38 set(effective_caller_id_number=+441202001908)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [effective_caller_id_number]=[+441202001908]
EXECUTE sofia/internal/2000@192.168.1.38 set(inherit_codec=true)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [inherit_codec]=[true]
EXECUTE sofia/internal/2000@192.168.1.38 set(ignore_display_updates=true)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [ignore_display_updates]=[true]
EXECUTE sofia/internal/2000@192.168.1.38 set(callee_id_number=*redacted*)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [callee_id_number]=[*redacted*]
EXECUTE sofia/internal/2000@192.168.1.38 set(continue_on_fail=true)
2019-06-26 11:37:30.324450 [DEBUG] mod_dptools.c:1598 SET sofia/internal/2000@192.168.1.38 [continue_on_fail]=[true]
EXECUTE sofia/internal/2000@192.168.1.38 bridge(sofia/gateway/20be6af9-1c24-4e02-9282-6f574b836910/*redacted*)
2019-06-26 11:37:30.324450 [DEBUG] switch_channel.c:1250 sofia/internal/2000@192.168.1.38 EXPORTING[export_vars] [domain_name]=[192.168.1.38] to event
2019-06-26 11:37:30.324450 [DEBUG] switch_channel.c:1250 sofia/internal/2000@192.168.1.38 EXPORTING[export_vars] [origination_callee_id_name]=[*redacted*] to event
2019-06-26 11:37:30.324450 [DEBUG] switch_channel.c:1250 sofia/internal/2000@192.168.1.38 EXPORTING[export_vars] [call_direction]=[outbound] to event
2019-06-26 11:37:30.324450 [DEBUG] switch_channel.c:1250 sofia/internal/2000@192.168.1.38 EXPORTING[export_vars] [call_direction]=[outbound] to event
2019-06-26 11:37:30.324450 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
2019-06-26 11:37:30.324450 [NOTICE] switch_channel.c:1104 New Channel sofia/external/*redacted* [59f27d82-79ff-40f5-ab59-13327a6e4fa2]
2019-06-26 11:37:30.324450 [DEBUG] mod_sofia.c:5019 (sofia/external/*redacted*) State Change CS_NEW -> CS_INIT
2019-06-26 11:37:30.324450 [DEBUG] switch_core_state_machine.c:584 (sofia/external/*redacted*) Running State Change CS_INIT (Cur 2 Tot 4)
2019-06-26 11:37:30.324450 [DEBUG] switch_core_state_machine.c:627 (sofia/external/*redacted*) State INIT
2019-06-26 11:37:30.324450 [DEBUG] mod_sofia.c:93 sofia/external/*redacted* SOFIA INIT
2019-06-26 11:37:30.384519 [DEBUG] switch_core_media.c:7963 STUN Success [*redacted-extip*]:[19870]
2019-06-26 11:37:30.384519 [DEBUG] sofia_glue.c:1302 sofia/external/*redacted* sending invite version: 1.8.5 -6-31281a0bf1 64bit
Local SDP:
v=0
o=FreeSWITCH 1561525580 1561525581 IN IP4 *redacted-extip*
s=FreeSWITCH
c=IN IP4 *redacted-extip*
t=0 0
m=audio 19870 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:40 sofia/external/*redacted* Standard INIT
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:48 (sofia/external/*redacted*) State Change CS_INIT -> CS_ROUTING
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:627 (sofia/external/*redacted*) State INIT going to sleep
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:584 (sofia/external/*redacted*) Running State Change CS_ROUTING (Cur 2 Tot 4)
send 1150 bytes to udp/[54.172.60.3]:5060 at 11:37:30.390738:
------------------------------------------------------------------------
INVITE sip:*redacted*@uncubed.pstn.twilio.com SIP/2.0
Via: SIP/2.0/UDP *redacted-extip*:5080;rport;branch=z9hG4bKSrNQKKBg3ZjZc
Max-Forwards: 69
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
CSeq: 6218933 INVITE
Contact: <sip:gw+20be6af9-1c24-4e02-9282-6f574b836910@*redacted-extip*:5080;transport=udp;gw=20be6af9-1c24-4e02-9282-6f574b836910>
User-Agent: FreeSWITCH
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: 242
X-FS-Support: update_display,send_info
Remote-Party-ID: "Uncubed Technology" <sip:+441202001908@uncubed.pstn.twilio.com>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1561525580 1561525581 IN IP4 *redacted-extip*
s=FreeSWITCH
c=IN IP4 *redacted-extip*
t=0 0
m=audio 19870 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:643 (sofia/external/*redacted*) State ROUTING
2019-06-26 11:37:30.384519 [DEBUG] mod_sofia.c:154 sofia/external/*redacted* SOFIA ROUTING
2019-06-26 11:37:30.384519 [DEBUG] switch_ivr_originate.c:67 (sofia/external/*redacted*) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:643 (sofia/external/*redacted*) State ROUTING going to sleep
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:584 (sofia/external/*redacted*) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 4)
2019-06-26 11:37:30.384519 [DEBUG] sofia.c:7291 Channel sofia/external/*redacted* entering state [calling][0]
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:662 (sofia/external/*redacted*) State CONSUME_MEDIA
2019-06-26 11:37:30.384519 [DEBUG] switch_core_state_machine.c:662 (sofia/external/*redacted*) State CONSUME_MEDIA going to sleep
recv 365 bytes from udp/[54.172.60.3]:5060 at 11:37:30.502776:
------------------------------------------------------------------------
SIP/2.0 100 Giving a try
Via: SIP/2.0/UDP *redacted-extip*:5080;received=*redacted-extip*;rport=5080;branch=z9hG4bKSrNQKKBg3ZjZc
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
CSeq: 6218933 INVITE
Server: Twilio Gateway
Content-Length: 0

------------------------------------------------------------------------
recv 628 bytes from udp/[54.172.60.3]:5060 at 11:37:30.510570:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication required
CSeq: 6218933 INVITE
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=44565634_6772d868_fd70390a-98a1-43b8-b328-99139dec5349
Via: SIP/2.0/UDP *redacted-extip*:5080;received=*redacted-extip*;rport=5080;branch=z9hG4bKSrNQKKBg3ZjZc
Server: Twilio
Contact: <sip:172.18.53.96:5060>
Proxy-Authenticate: Digest realm="sip.twilio.com",qop="auth",nonce="",opaque=""
Content-Length: 0

------------------------------------------------------------------------
send 418 bytes to udp/[54.172.60.3]:5060 at 11:37:30.510762:
------------------------------------------------------------------------
ACK sip:*redacted*@uncubed.pstn.twilio.com SIP/2.0
Via: SIP/2.0/UDP *redacted-extip*:5080;rport;branch=z9hG4bKSrNQKKBg3ZjZc
Max-Forwards: 69
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=44565634_6772d868_fd70390a-98a1-43b8-b328-99139dec5349
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
CSeq: 6218933 ACK
Content-Length: 0

------------------------------------------------------------------------
send 1485 bytes to udp/[54.172.60.3]:5060 at 11:37:30.511242:
------------------------------------------------------------------------
INVITE sip:*redacted*@uncubed.pstn.twilio.com SIP/2.0
Via: SIP/2.0/UDP *redacted-extip*:5080;rport;branch=z9hG4bKt1egNevK088Hr
Max-Forwards: 69
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
CSeq: 6218934 INVITE
Contact: <sip:gw+20be6af9-1c24-4e02-9282-6f574b836910@*redacted-extip*:5080;transport=udp;gw=20be6af9-1c24-4e02-9282-6f574b836910>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Proxy-Authorization: Digest username="pbx2", realm="sip.twilio.com", nonce="", cnonce="", opaque="", algorithm=MD5, uri="sip:*redacted*@uncubed.pstn.twilio.com", response="d77457a34de66325b76e18ad8efc217c", qop=auth, nc=00000001
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 242
X-FS-Support: update_display,send_info
Remote-Party-ID: "Uncubed Technology" <sip:+441202001908@uncubed.pstn.twilio.com>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1561525580 1561525581 IN IP4 *redacted-extip*
s=FreeSWITCH
c=IN IP4 *redacted-extip*
t=0 0
m=audio 19870 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
------------------------------------------------------------------------
2019-06-26 11:37:30.504455 [DEBUG] sofia.c:7291 Channel sofia/external/*redacted* entering state [calling][0]
recv 365 bytes from udp/[54.172.60.3]:5060 at 11:37:30.626125:
------------------------------------------------------------------------
SIP/2.0 100 Giving a try
Via: SIP/2.0/UDP *redacted-extip*:5080;received=*redacted-extip*;rport=5080;branch=z9hG4bKt1egNevK088Hr
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
CSeq: 6218934 INVITE
Server: Twilio Gateway
Content-Length: 0

------------------------------------------------------------------------
recv 839 bytes from udp/[54.172.60.3]:5060 at 11:37:33.684795:
------------------------------------------------------------------------
SIP/2.0 183 Session progress
CSeq: 6218934 INVITE
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=83024956_6772d868_8a4ef98e-eb31-413d-9cef-b6c53ef44f5a
Via: SIP/2.0/UDP *redacted-extip*:5080;received=*redacted-extip*;rport=5080;branch=z9hG4bKt1egNevK088Hr
Record-Route: <sip:54.172.60.3:5060;lr;ftag=pQFKt2aZ75cjB>
Server: Twilio
Contact: <sip:172.18.44.98:5060>
Content-Type: application/sdp
X-Twilio-CallSid: *redacted-sid*
Content-Length: 238

v=0
o=root 844042140 844042140 IN IP4 34.203.250.204
s=Twilio Media Gateway
c=IN IP4 34.203.250.204
t=0 0
m=audio 15720 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
2019-06-26 11:37:33.684526 [DEBUG] sofia.c:7291 Channel sofia/external/*redacted* entering state [proceeding][183]
2019-06-26 11:37:33.684526 [DEBUG] sofia.c:7301 Remote SDP:
v=0
o=root 844042140 844042140 IN IP4 34.203.250.204
s=Twilio Media Gateway
c=IN IP4 34.203.250.204
t=0 0
m=audio 15720 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2019-06-26 11:37:33.684526 [NOTICE] sofia.c:7304 Pre-Answer sofia/external/*redacted*!
2019-06-26 11:37:33.684526 [DEBUG] switch_channel.c:3482 (sofia/external/*redacted*) Callstate Change DOWN -> EARLY
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:3781 Set Codec sofia/external/*redacted* PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2019-06-26 11:37:33.684526 [DEBUG] switch_core_codec.c:111 sofia/external/*redacted* Original read codec set to PCMU:0
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:5737 Set telephone-event payload to 101@8000
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:5795 sofia/external/*redacted* Set 2833 dtmf send payload to 101 recv payload to 101
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/external/*redacted*] 192.168.1.38 port 19870 -> 34.203.250.204 port 15720 codec: 0 ms: 20
2019-06-26 11:37:33.684526 [INFO] switch_ivr_originate.c:3747 Sending early media
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/2000@192.168.1.38] 192.168.1.38 port 27616 -> 192.168.1.56 port 23800 codec: 0 ms: 20
2019-06-26 11:37:33.684526 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
2019-06-26 11:37:33.684526 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 160 bytes per 20ms
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8815 sofia/external/*redacted* Set 2833 dtmf send payload to 101
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8822 sofia/external/*redacted* Set 2833 dtmf receive payload to 101
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8845 sofia/external/*redacted* Set rtp dtmf delay to 40
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8815 sofia/internal/2000@192.168.1.38 Set 2833 dtmf send payload to 101
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8822 sofia/internal/2000@192.168.1.38 Set 2833 dtmf receive payload to 101
2019-06-26 11:37:33.684526 [DEBUG] switch_core_media.c:8845 sofia/internal/2000@192.168.1.38 Set rtp dtmf delay to 40
2019-06-26 11:37:33.684526 [DEBUG] mod_sofia.c:2505 Ring SDP:
v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2019-06-26 11:37:33.684526 [NOTICE] mod_sofia.c:2508 Pre-Answer sofia/internal/2000@192.168.1.38!
2019-06-26 11:37:33.684526 [DEBUG] switch_channel.c:3482 (sofia/internal/2000@192.168.1.38) Callstate Change RINGING -> EARLY
2019-06-26 11:37:33.684526 [DEBUG] switch_ivr_originate.c:3798 Originate Resulted in Success: [sofia/external/*redacted*]
send 1186 bytes to udp/[192.168.1.56]:5060 at 11:37:33.691644:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-06-26 11:37:33.684526 [DEBUG] sofia.c:7291 Channel sofia/internal/2000@192.168.1.38 entering state [early][183]
2019-06-26 11:37:33.684526 [DEBUG] switch_ivr_bridge.c:1782 (sofia/external/*redacted*) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2019-06-26 11:37:33.684526 [DEBUG] switch_core_state_machine.c:584 (sofia/external/*redacted*) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 4)
2019-06-26 11:37:33.684526 [DEBUG] switch_core_state_machine.c:653 (sofia/external/*redacted*) State EXCHANGE_MEDIA
2019-06-26 11:37:33.684526 [DEBUG] mod_sofia.c:646 SOFIA EXCHANGE_MEDIA
2019-06-26 11:37:33.844509 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
2019-06-26 11:37:34.624525 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
recv 876 bytes from udp/[54.172.60.3]:5060 at 11:37:37.078313:
------------------------------------------------------------------------
SIP/2.0 200 OK
CSeq: 6218934 INVITE
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=83024956_6772d868_8a4ef98e-eb31-413d-9cef-b6c53ef44f5a
Via: SIP/2.0/UDP *redacted-extip*:5080;received=*redacted-extip*;rport=5080;branch=z9hG4bKt1egNevK088Hr
Record-Route: <sip:54.172.60.3:5060;lr;ftag=pQFKt2aZ75cjB>
Server: Twilio
Contact: <sip:172.18.44.98:5060>
Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REFER,NOTIFY
Content-Type: application/sdp
X-Twilio-CallSid: *redacted-sid*
Content-Length: 238

v=0
o=root 844042140 844042140 IN IP4 34.203.250.204
s=Twilio Media Gateway
c=IN IP4 34.203.250.204
t=0 0
m=audio 15720 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
------------------------------------------------------------------------
2019-06-26 11:37:37.084456 [DEBUG] sofia.c:7291 Channel sofia/external/*redacted* entering state [completing][200]
2019-06-26 11:37:37.084456 [DEBUG] sofia.c:7298 Duplicate SDP
v=0
o=root 844042140 844042140 IN IP4 34.203.250.204
s=Twilio Media Gateway
c=IN IP4 34.203.250.204
t=0 0
m=audio 15720 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

send 913 bytes to udp/[54.172.60.3]:5060 at 11:37:37.089489:
------------------------------------------------------------------------
ACK sip:172.18.44.98:5060 SIP/2.0
Via: SIP/2.0/UDP *redacted-extip*:5080;rport;branch=z9hG4bKUa88p9cQXHZ4K
Route: <sip:54.172.60.3:5060;lr;ftag=pQFKt2aZ75cjB>
Max-Forwards: 70
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=83024956_6772d868_8a4ef98e-eb31-413d-9cef-b6c53ef44f5a
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
CSeq: 6218934 ACK
Contact: <sip:gw+20be6af9-1c24-4e02-9282-6f574b836910@*redacted-extip*:5080;transport=udp;gw=20be6af9-1c24-4e02-9282-6f574b836910>
Proxy-Authorization: Digest username="pbx2", realm="sip.twilio.com", nonce="", cnonce="", opaque="", algorithm=MD5, uri="sip:*redacted*@uncubed.pstn.twilio.com", response="d77457a34de66325b76e18ad8efc217c", qop=auth, nc=00000001
Content-Length: 0

------------------------------------------------------------------------
2019-06-26 11:37:37.104453 [DEBUG] sofia.c:7291 Channel sofia/external/*redacted* entering state [ready][200]
2019-06-26 11:37:37.104453 [NOTICE] sofia.c:8370 Channel [sofia/external/*redacted*] has been answered
2019-06-26 11:37:37.104453 [DEBUG] switch_channel.c:3781 (sofia/external/*redacted*) Callstate Change EARLY -> ACTIVE
2019-06-26 11:37:37.124474 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/internal/2000@192.168.1.38.
2019-06-26 11:37:37.124474 [DEBUG] mod_sofia.c:882 Local SDP sofia/internal/2000@192.168.1.38:
v=0
o=FreeSWITCH 1561517837 1561517839 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2019-06-26 11:37:37.124474 [NOTICE] switch_ivr_bridge.c:736 Channel [sofia/internal/2000@192.168.1.38] has been answered
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:37.129301:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2019-06-26 11:37:37.124474 [DEBUG] switch_channel.c:3781 (sofia/internal/2000@192.168.1.38) Callstate Change EARLY -> ACTIVE
2019-06-26 11:37:37.124474 [DEBUG] sofia.c:7291 Channel sofia/internal/2000@192.168.1.38 entering state [completed][200]
2019-06-26 11:37:37.144451 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
2019-06-26 11:37:37.184533 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:37.629533:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:38.629527:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:40.629530:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:44.629529:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:48.629549:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:52.629534:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:37:56.630095:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:38:00.630097:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:38:04.630097:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 1147 bytes to udp/[192.168.1.56]:5060 at 11:38:08.630099:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.56:5060;branch=z9hG4bK59e20c0e
From: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
To: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 102 INVITE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-Twilio-CallSid: *redacted-sid*
Remote-Party-ID: "*redacted*" <sip:*redacted*@192.168.1.38>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1561517837 1561517838 IN IP4 192.168.1.38
s=FreeSWITCH
c=IN IP4 192.168.1.38
t=0 0
m=audio 27616 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
send 640 bytes to udp/[192.168.1.56]:5060 at 11:38:09.131543:
------------------------------------------------------------------------
BYE sip:2000@192.168.1.56:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP *redacted-extip*;rport;branch=z9hG4bK4Nt1NrgjUcaNj
Max-Forwards: 70
From: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
To: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
CSeq: 6218952 BYE
Contact: <sip:*redacted*@*redacted-extip*:5060;transport=udp>
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Reason: SIP;cause=408;text="ACK Timeout"
Content-Length: 0

------------------------------------------------------------------------
2019-06-26 11:38:09.144490 [DEBUG] sofia.c:7291 Channel sofia/internal/2000@192.168.1.38 entering state [terminating][0]
2019-06-26 11:38:09.144490 [NOTICE] sofia.c:8484 Hangup sofia/internal/2000@192.168.1.38 [CS_EXECUTE] [NORMAL_UNSPECIFIED]
2019-06-26 11:38:09.144490 [DEBUG] switch_ivr_bridge.c:831 sofia/internal/2000@192.168.1.38 ending bridge by request from read function
2019-06-26 11:38:09.144490 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/internal/2000@192.168.1.38]
2019-06-26 11:38:09.164460 [DEBUG] switch_ivr_bridge.c:825 sofia/internal/2000@192.168.1.38 ending bridge by request from write function
2019-06-26 11:38:09.164460 [DEBUG] switch_ivr_bridge.c:917 BRIDGE THREAD DONE [sofia/external/*redacted*]
2019-06-26 11:38:09.164460 [NOTICE] switch_ivr_bridge.c:1034 Hangup sofia/external/*redacted* [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:653 (sofia/external/*redacted*) State EXCHANGE_MEDIA going to sleep
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:584 (sofia/external/*redacted*) Running State Change CS_HANGUP (Cur 2 Tot 4)
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:847 (sofia/external/*redacted*) Callstate Change ACTIVE -> HANGUP
2019-06-26 11:38:09.164460 [DEBUG] switch_ivr_bridge.c:1881 sofia/external/*redacted* skip receive message [UNBRIDGE] (channel is hungup already)
2019-06-26 11:38:09.164460 [DEBUG] switch_ivr_bridge.c:1884 sofia/internal/2000@192.168.1.38 skip receive message [UNBRIDGE] (channel is hungup already)
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:849 (sofia/external/*redacted*) State HANGUP
2019-06-26 11:38:09.164460 [DEBUG] mod_sofia.c:449 Channel sofia/external/*redacted* hanging up, cause: NORMAL_CLEARING
2019-06-26 11:38:09.164460 [DEBUG] mod_sofia.c:502 Sending BYE to sofia/external/*redacted*
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:60 sofia/external/*redacted* Standard HANGUP, cause: NORMAL_CLEARING
2019-06-26 11:38:09.164460 [DEBUG] switch_core_session.c:2887 sofia/internal/2000@192.168.1.38 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:849 (sofia/external/*redacted*) State HANGUP going to sleep
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/2000@192.168.1.38) State EXECUTE going to sleep
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2000@192.168.1.38) Running State Change CS_HANGUP (Cur 2 Tot 4)
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:619 (sofia/external/*redacted*) State Change CS_HANGUP -> CS_REPORTING
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:584 (sofia/external/*redacted*) Running State Change CS_REPORTING (Cur 2 Tot 4)
send 961 bytes to udp/[54.172.60.3]:5060 at 11:38:09.169324:
------------------------------------------------------------------------
BYE sip:172.18.44.98:5060 SIP/2.0
Via: SIP/2.0/UDP *redacted-extip*:5080;rport;branch=z9hG4bKvK11r4XtttNQF
Route: <sip:54.172.60.3:5060;lr;ftag=pQFKt2aZ75cjB>
Max-Forwards: 70
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=83024956_6772d868_8a4ef98e-eb31-413d-9cef-b6c53ef44f5a
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:935 (sofia/external/*redacted*) State REPORTING
CSeq: 6218935 BYE
User-Agent: FreeSWITCH
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:174 sofia/external/*redacted* Standard REPORTING, cause: NORMAL_CLEARING
Supported: timer, path, replaces
Proxy-Authorization: Digest username="pbx2", realm="sip.twilio.com", nonce="", cnonce="", opaque="", algorithm=MD5, uri="sip:172.18.44.98:5060", response="3ab84f49e0ad252f6619c8f48ecd8d22", qop=auth, nc=00000002
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0

2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:935 (sofia/external/*redacted*) State REPORTING going to sleep
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/2000@192.168.1.38) Callstate Change ACTIVE -> HANGUP
------------------------------------------------------------------------
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/2000@192.168.1.38) State HANGUP
2019-06-26 11:38:09.164460 [DEBUG] mod_sofia.c:449 Channel sofia/internal/2000@192.168.1.38 hanging up, cause: NORMAL_UNSPECIFIED
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:610 (sofia/external/*redacted*) State Change CS_REPORTING -> CS_DESTROY
2019-06-26 11:38:09.164460 [DEBUG] switch_core_session.c:1715 Session 4 (sofia/external/*redacted*) Locked, Waiting on external entities
2019-06-26 11:38:09.164460 [NOTICE] switch_core_session.c:1733 Session 4 (sofia/external/*redacted*) Ended
2019-06-26 11:38:09.164460 [NOTICE] switch_core_session.c:1737 Close Channel sofia/external/*redacted* [CS_DESTROY]
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:738 (sofia/external/*redacted*) Running State Change CS_DESTROY (Cur 1 Tot 4)
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:748 (sofia/external/*redacted*) State DESTROY
2019-06-26 11:38:09.164460 [DEBUG] mod_sofia.c:354 sofia/external/*redacted* SOFIA DESTROY
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:181 sofia/external/*redacted* Standard DESTROY
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:748 (sofia/external/*redacted*) State DESTROY going to sleep
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:60 sofia/internal/2000@192.168.1.38 Standard HANGUP, cause: NORMAL_UNSPECIFIED
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/2000@192.168.1.38) State HANGUP going to sleep
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/2000@192.168.1.38) State Change CS_HANGUP -> CS_REPORTING
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/2000@192.168.1.38) Running State Change CS_REPORTING (Cur 1 Tot 4)
2019-06-26 11:38:09.164460 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/2000@192.168.1.38) State REPORTING
recv 398 bytes from udp/[192.168.1.56]:5060 at 11:38:09.218355:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP *redacted-extip*;rport;branch=z9hG4bK4Nt1NrgjUcaNj;received=192.168.1.38
From: <sip:*redacted*@192.168.1.38>;tag=a4H605Z3Ur8yj
To: "2000" <sip:2000@192.168.1.38>;tag=001bd40b86d622f45ec1f892-0c759aea
Call-ID: 001bd40b-86d60018-2aa15860-4f12abf2@192.168.1.56
Date: Wed, 26 Jun 2019 10:38:09 GMT
CSeq: 6218952 BYE
Server: Cisco-CP7960G/8.0
Content-Length: 0

------------------------------------------------------------------------
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:174 sofia/internal/2000@192.168.1.38 Standard REPORTING, cause: NORMAL_UNSPECIFIED
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/2000@192.168.1.38) State REPORTING going to sleep
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/2000@192.168.1.38) State Change CS_REPORTING -> CS_DESTROY
2019-06-26 11:38:09.224469 [DEBUG] switch_core_session.c:1715 Session 3 (sofia/internal/2000@192.168.1.38) Locked, Waiting on external entities
2019-06-26 11:38:09.224469 [NOTICE] switch_core_session.c:1733 Session 3 (sofia/internal/2000@192.168.1.38) Ended
2019-06-26 11:38:09.224469 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/2000@192.168.1.38 [CS_DESTROY]
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/2000@192.168.1.38) Running State Change CS_DESTROY (Cur 0 Tot 4)
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/2000@192.168.1.38) State DESTROY
2019-06-26 11:38:09.224469 [DEBUG] mod_sofia.c:354 sofia/internal/2000@192.168.1.38 SOFIA DESTROY
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:181 sofia/internal/2000@192.168.1.38 Standard DESTROY
2019-06-26 11:38:09.224469 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/2000@192.168.1.38) State DESTROY going to sleep
recv 548 bytes from udp/[54.172.60.3]:5060 at 11:38:09.308839:
------------------------------------------------------------------------
SIP/2.0 200 OK
CSeq: 6218935 BYE
Call-ID: 3d95ab93-12a1-1238-b384-000c29bfc21f
From: "Uncubed Technology" <sip:pbx2@uncubed.pstn.twilio.com>;tag=pQFKt2aZ75cjB
To: <sip:*redacted*@uncubed.pstn.twilio.com>;tag=83024956_6772d868_8a4ef98e-eb31-413d-9cef-b6c53ef44f5a
Via: SIP/2.0/UDP *redacted-extip*:5080;received=*redacted-extip*;rport=5080;branch=z9hG4bKvK11r4XtttNQF
Server: Twilio
X-Twilio-RecordingSid: RE5c28adf52643134b12ea5ba8a850ed60
X-Twilio-RecordingDuration: 36
X-Twilio-CallSid: *redacted-sid*
Content-Length: 0

------------------------------------------------------------------------
 
Last edited:
bcmike

bcmike

Active Member
Jun 7, 2018
337
58
28
54
I fought with something similar for a long time. The 30 second time out means as you've stated you're not getting the ACK, which means its probably a NAT issue. In my case I was using an ASTPP box as a mediator and was trying to do both external (to carriers) and internal (to fusion PBX) calls through the same profile. Splitting these functions into 2 profiles, internal and external with external having the proper NAT settings solved my issue as the SIP headers got normalized and the internal profile provided the ACK.

Hopefully I explained that correctly, but 30 second timeout is always NAT related.
 
R

ryanp

New Member
Apr 20, 2019
3
0
1
31
Hey bcmike, thank you for your reply. I'm behind a Zentyal server, I have the appropriate ports forwarded to the PBX machine, but I am at a loss for what to enable for the NAT issue described. I don't wish to use uPnP as it opens up other security risks on the network. Do you have any suggestions on what I can do please?
 
R

ryanp

New Member
Apr 20, 2019
3
0
1
31
Hi all,

Got this sorted.
In my internal profile I changed:
aggressive-nat-detection true true
ext-rtp-ip auto-nat true
ext-sip-ip auto-nat true
inbound-bypass-media false true
inbound-proxy-media true true

Restarted freeswitch and now the RTP stream doesn't drop. Thanks!
 
ex733.ago

ex733.ago

New Member
Apr 29, 2021
1
0
1
34
ryanp said:
Hi all,

Got this sorted.
In my internal profile I changed:
aggressive-nat-detection true true
ext-rtp-ip auto-nat true
ext-sip-ip auto-nat true
inbound-bypass-media false true
inbound-proxy-media true true

Restarted freeswitch and now the RTP stream doesn't drop. Thanks!
Click to expand...

I confirm that I had similar issue with softphones - they all dropped any call in ~30s, although physical CISCO phones worked just fine.
Further investigation with SNGREP showed that freeswitch never received an ACK method (once the call is established and freeswitch replies with 200) from the softphone.

Both my softphone and freeswitch are on my local network, so I changed only inbound-bypass-media and inbound-proxy-media

This change to my internal SIP config fixed the issue.
 
Status
Not open for further replies.
Top Bottom