[Freeswitch-users] 200 OK not forwarded

Thu Mar 2 18:04:13 MSK 2017

Hello Guys,

I'm using FreeSWITCH (Version 1.9.0 git f3b7105 2016-11-15 01:50:51Z 64bit)
is ready

And i'm seeing the issue where the 200OK is not being forwarded from FS to
the client.

I'm attaching FS Log and sip trace.

1.1.1.1 = Client (Grandstream GXP1165)
9.9.9.9 = freeSWITCH
10.10.10.10 = Terminating GW (my_gateway)

Been scratching my head for some time...

Appreciate your help!

Regards,

David Villasmil
email: david.villasmil.work at gmail.com
phone: +34669448337
ᐧ
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20170302/ab15ddd1/attachment-0001.html 
-------------- next part --------------
2017/03/02 09:35:55.618841 1.1.1.1:50156 -> 9.9.9.9:5066
INVITE sip:0017708999518 at 9.9.9.9:5066;user=phone SIP/2.0
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1278143718;rport;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 20 INVITE
Contact: <sip:3059001001 at 1.1.1.1:44245;transport=tcp;user=phone>
Max-Forwards: 70
User-Agent: Grandstream GXP1165 1.0.5.23
Privacy: none
P-Preferred-Identity: <sip:3059001001 at 9.9.9.9:5066;user=phone>
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   388

v=0
o=3059001001 8000 8000 IN IP4 1.1.1.1
s=SIP Call
c=IN IP4 1.1.1.1
t=0 0
m=audio 5004 RTP/AVP 18 97 0 8 9 2 101
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:40
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2017/03/02 09:35:55.619316 9.9.9.9:5066 -> 1.1.1.1:50156
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1278143718;rport=50156;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 20 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20161115T015051Z~f3b7105d66~64bit
Content-Length: 0

2017/03/02 09:35:55.620951 9.9.9.9:5066 -> 1.1.1.1:50156
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1278143718;rport=50156;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>;tag=9pBNr4m6trjDB
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 20 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20161115T015051Z~f3b7105d66~64bit
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="9.9.9.9", nonce="a27db99a-ff2b-11e6-8331-1dc743b2963b", algorithm=MD5, qop="auth"
Content-Length: 0

2017/03/02 09:35:55.757383 1.1.1.1:50156 -> 9.9.9.9:5066
ACK sip:0017708999518 at 9.9.9.9:5066;user=phone SIP/2.0
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1278143718;rport;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>;tag=9pBNr4m6trjDB
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 20 ACK
Content-Length: 0

2017/03/02 09:35:55.888940 1.1.1.1:50156 -> 9.9.9.9:5066
INVITE sip:0017708999518 at 9.9.9.9:5066;user=phone SIP/2.0
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1324364852;rport;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 21 INVITE
Contact: <sip:3059001001 at 1.1.1.1:44245;transport=tcp;user=phone>
Proxy-Authorization: Digest username="3059001001", realm="9.9.9.9", nonce="", uri="sip:0017708999518 at 9.9.9.9:5066;user=phone", response="", algorithm=MD5, cnonce="11144919", qop=auth, nc=00000003
Max-Forwards: 70
User-Agent: Grandstream GXP1165 1.0.5.23
Privacy: none
P-Preferred-Identity: <sip:3059001001 at 9.9.9.9:5066;user=phone>
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   388

v=0
o=3059001001 8000 8000 IN IP4 1.1.1.1
s=SIP Call
c=IN IP4 1.1.1.1
t=0 0
m=audio 5004 RTP/AVP 18 97 0 8 9 2 101
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:40
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

2017/03/02 09:35:55.889571 9.9.9.9:5066 -> 1.1.1.1:50156
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1324364852;rport=50156;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 21 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20161115T015051Z~f3b7105d66~64bit
Content-Length: 0

2017/03/02 09:35:55.905515 9.9.9.9:5066 -> 1.1.1.1:50156
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1324364852;rport=50156;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>;tag=a04DtZ59Q18Zp
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 21 INVITE
Contact: <sip:0017708999518 at 9.9.9.9:5066;transport=tcp>
User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20161115T015051Z~f3b7105d66~64bit
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-Length: 0
P-Asserted-Identity: "0017708999518" <sip:0017708999518 at 9.9.9.9>

2017/03/02 09:36:00.472432 9.9.9.9:5066 -> 1.1.1.1:50156
SIP/2.0 183 Session Progress
Via: SIP/2.0/TCP 1.1.1.1:44245;branch=z9hG4bK1324364852;rport=50156;alias
From: <sip:3059001001 at 9.9.9.9:5066;user=phone>;tag=1741650402
To: <sip:0017708999518 at 9.9.9.9:5066;user=phone>;tag=a04DtZ59Q18Zp
Call-ID: 954599984-5066-3 at CAA.FJ.BII.BCC
CSeq: 21 INVITE
Contact: <sip:0017708999518 at 9.9.9.9:5066;transport=tcp>
User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20161115T015051Z~f3b7105d66~64bit
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: 247
P-Asserted-Identity: "Outbound Call" <sip:17708999518 at 9.9.9.9>

v=0
o=FreeSWITCH 1488425630 1488425631 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21730 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40

2017/03/02 09:35:55.910356 9.9.9.9:5060 -> 10.10.10.10:5060
INVITE sip:17708999518 at 10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9;rport;branch=z9hG4bKU42462NpNt3Nr
Max-Forwards: 69
From: "13059001001" <sip:13059001001 at 9.9.9.9>;tag=1Q59Z4g51y35K
To: <sip:17708999518 at 10.10.10.10:5060>
Call-ID: 7a083341-79ce-1235-cb81-be187db6d1b8
CSeq: 103887613 INVITE
Contact: <sip:gw+creacomm at 9.9.9.9:5060;transport=udp;gw=creacomm>
User-Agent: FreeSWITCH-mod_sofia/1.9.0+git~20161115T015051Z~f3b7105d66~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: 295
X-cid: 954599984-5066-3 at CAA.FJ.BII.BCC
X-FS-Support: update_display,send_info
Remote-Party-ID: "13059001001" <sip:13059001001 at 9.9.9.9>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1488425749 1488425750 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21606 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40

2017/03/02 09:35:55.911731 10.10.10.10:5060 -> 9.9.9.9:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 9.9.9.9;rport=5060;received=9.9.9.9;branch=z9hG4bKU42462NpNt3Nr
From: "13059001001" <sip:13059001001 at 9.9.9.9>;tag=1Q59Z4g51y35K
To: <sip:17708999518 at 10.10.10.10:5060>
Call-ID: 7a083341-79ce-1235-cb81-be187db6d1b8
CSeq: 103887613 INVITE
Content-Length: 0

2017/03/02 09:36:00.449081 10.10.10.10:5060 -> 9.9.9.9:5060
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 9.9.9.9;rport=5060;received=9.9.9.9;branch=z9hG4bKU42462NpNt3Nr
To: <sip:17708999518 at 10.10.10.10:5060>;tag=3697454212-983492
From: "13059001001" <sip:13059001001 at 9.9.9.9>;tag=1Q59Z4g51y35K
Call-ID: 7a083341-79ce-1235-cb81-be187db6d1b8
CSeq: 103887613 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:17708999518 at 10.10.10.10:5060>
Call-Info: <sip:10.10.10.10>;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 155

v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 15906 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

2017/03/02 09:36:05.849242 10.10.10.10:5060 -> 9.9.9.9:5060
SIP/2.0 200 OK
Session-Expires: 3600;refresher=uas
Require: timer
Via: SIP/2.0/UDP 9.9.9.9;rport=5060;received=9.9.9.9;branch=z9hG4bKU42462NpNt3Nr
To: <sip:17708999518 at 10.10.10.10:5060>;tag=3697454212-983492
From: "13059001001" <sip:13059001001 at 9.9.9.9>;tag=1Q59Z4g51y35K
Call-ID: 7a083341-79ce-1235-cb81-be187db6d1b8
CSeq: 103887613 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE
Contact: <sip:17708999518 at 10.10.10.10:5060>
Call-Info: <sip:10.10.10.10>;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 155

v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 15906 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

2017/03/02 09:36:05.853144 9.9.9.9:5060 -> 10.10.10.10:5060
ACK sip:17708999518 at 10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 9.9.9.9;rport;branch=z9hG4bKZ877DFS49Xv0p
Max-Forwards: 70
From: "13059001001" <sip:13059001001 at 9.9.9.9>;tag=1Q59Z4g51y35K
To: <sip:17708999518 at 10.10.10.10:5060>;tag=3697454212-983492
Call-ID: 7a083341-79ce-1235-cb81-be187db6d1b8
CSeq: 103887613 ACK
Contact: <sip:gw+creacomm at 9.9.9.9:5060;transport=udp;gw=creacomm>
Content-Length: 0
-------------- next part --------------
2017-03-02 09:35:55.610892 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/3059001001 at 9.9.9.9:5066 [a27da540-ff2b-11e6-8330-1dc743b2963b]
2017-03-02 09:35:55.610892 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_NEW (Cur 5 Tot 796)
2017-03-02 09:35:55.610892 [DEBUG] sofia.c:9831 sofia/internal/3059001001 at 9.9.9.9:5066 receiving invite from 1.1.1.1:50156 version: 1.9.0 git f3b7105 2016-11-15 01:50:51Z 64bit
2017-03-02 09:35:55.610892 [DEBUG] sofia.c:9998 IP 1.1.1.1 Rejected by acl "domain". Falling back to Digest auth.
2017-03-02 09:35:55.610892 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'internal' for [0017708999518 at 9.9.9.9] from ip 1.1.1.1
2017-03-02 09:35:55.610892 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/3059001001 at 9.9.9.9:5066) State NEW
2017-03-02 09:35:55.610892 [DEBUG] sofia.c:2339 detaching session a27da540-ff2b-11e6-8330-1dc743b2963b
2017-03-02 09:35:55.870882 [DEBUG] sofia.c:2448 Re-attaching to session a27da540-ff2b-11e6-8330-1dc743b2963b
2017-03-02 09:35:55.890882 [DEBUG] sofia.c:9831 sofia/internal/3059001001 at 9.9.9.9:5066 receiving invite from 1.1.1.1:50156 version: 1.9.0 git f3b7105 2016-11-15 01:50:51Z 64bit
2017-03-02 09:35:55.890882 [DEBUG] sofia.c:9998 IP 1.1.1.1 Rejected by acl "domain". Falling back to Digest auth.
2017-03-02 09:35:55.890882 [DEBUG] sofia.c:11133 Setting NAT mode based on via port
2017-03-02 09:35:55.890882 [DEBUG] sofia.c:7107 Channel sofia/internal/3059001001 at 9.9.9.9:5066 entering state [received][100]
2017-03-02 09:35:55.890882 [DEBUG] sofia.c:7117 Remote SDP:
v=0
o=3059001001 8000 8000 IN IP4 1.1.1.1
s=SIP Call
c=IN IP4 1.1.1.1
t=0 0
m=audio 5004 RTP/AVP 18 97 0 8 9 2 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:40

2017-03-02 09:35:55.890882 [DEBUG] sofia.c:7485 (sofia/internal/3059001001 at 9.9.9.9:5066) State Change CS_NEW -> CS_INIT
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_INIT (Cur 5 Tot 796)
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3059001001 at 9.9.9.9:5066) State INIT
2017-03-02 09:35:55.890882 [DEBUG] mod_sofia.c:92 sofia/internal/3059001001 at 9.9.9.9:5066 SOFIA INIT
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:40 sofia/internal/3059001001 at 9.9.9.9:5066 Standard INIT
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/3059001001 at 9.9.9.9:5066) State Change CS_INIT -> CS_ROUTING
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/3059001001 at 9.9.9.9:5066) State INIT going to sleep
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_ROUTING (Cur 5 Tot 796)
2017-03-02 09:35:55.890882 [DEBUG] switch_channel.c:2249 (sofia/internal/3059001001 at 9.9.9.9:5066) Callstate Change DOWN -> RINGING
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3059001001 at 9.9.9.9:5066) State ROUTING
2017-03-02 09:35:55.890882 [DEBUG] mod_sofia.c:145 sofia/internal/3059001001 at 9.9.9.9:5066 SOFIA ROUTING
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:236 sofia/internal/3059001001 at 9.9.9.9:5066 Standard ROUTING
2017-03-02 09:35:55.890882 [INFO] mod_dialplan_xml.c:637 Processing 3059001001 <3059001001>->0017708999518 in context default
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 parsing [default->unloop] continue=false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 parsing [default->Add_Internal_UUID] continue=true
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (PASS) [Add_Internal_UUID] destination_number(0017708999518) =~ /^.*$/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action session_loglevel(debug)
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action log(ERR Call-ID: [${sip_call_id}])
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action set(sip_h_X-cid=${sip_call_id})
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 parsing [default->local.example.com] continue=false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (PASS) [local.example.com] ${toll_allow}(domestic,international,local) =~ /local/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (FAIL) [local.example.com] destination_number(0017708999518) =~ /^(305900100[0-9])$/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 parsing [default->david_test] continue=false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (FAIL) [david_test] destination_number(0017708999518) =~ /^(9999999)$/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 parsing [default->domestic] continue=false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Regex (PASS) [domestic] destination_number(0017708999518) =~ /^00(1[2-9][0-9]{2}[2-9][0-9]{6}$)/ break=on-false
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action ring_ready()
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action set(effective_caller_id_number=1${caller_id_number})
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action set(effective_caller_id_name=1${caller_id_number})
Dialplan: sofia/internal/3059001001 at 9.9.9.9:5066 Action bridge(sofia/gateway/my_gatewaym/17708999518)
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/3059001001 at 9.9.9.9:5066) State Change CS_ROUTING -> CS_EXECUTE
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/3059001001 at 9.9.9.9:5066) State ROUTING going to sleep
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_EXECUTE (Cur 5 Tot 796)
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3059001001 at 9.9.9.9:5066) State EXECUTE
2017-03-02 09:35:55.890882 [DEBUG] mod_sofia.c:200 sofia/internal/3059001001 at 9.9.9.9:5066 SOFIA EXECUTE
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:328 sofia/internal/3059001001 at 9.9.9.9:5066 Standard EXECUTE
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 session_loglevel(debug)
2017-03-02 09:35:55.890882 [DEBUG] mod_dptools.c:4549 Setting log level "DEBUG" on session
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 log(ERR Call-ID: [954599984-5066-3 at CAA.FJ.BII.BCC])
2017-03-02 09:35:55.890882 [ERR] mod_dptools.c:1756 Call-ID: [954599984-5066-3 at CAA.FJ.BII.BCC]
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 set(sip_h_X-cid=954599984-5066-3 at CAA.FJ.BII.BCC)
2017-03-02 09:35:55.890882 [DEBUG] mod_dptools.c:1562 SET sofia/internal/3059001001 at 9.9.9.9:5066 [sip_h_X-cid]=[954599984-5066-3 at CAA.FJ.BII.BCC]
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 ring_ready()
2017-03-02 09:35:55.890882 [NOTICE] mod_sofia.c:2306 Ring-Ready sofia/internal/3059001001 at 9.9.9.9:5066!
2017-03-02 09:35:55.890882 [DEBUG] sofia.c:7107 Channel sofia/internal/3059001001 at 9.9.9.9:5066 entering state [early][180]
2017-03-02 09:35:55.890882 [NOTICE] mod_dptools.c:1060 Ring Ready sofia/internal/3059001001 at 9.9.9.9:5066!
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 set(effective_caller_id_number=13059001001)
2017-03-02 09:35:55.890882 [DEBUG] mod_dptools.c:1562 SET sofia/internal/3059001001 at 9.9.9.9:5066 [effective_caller_id_number]=[13059001001]
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 set(effective_caller_id_name=13059001001)
2017-03-02 09:35:55.890882 [DEBUG] mod_dptools.c:1562 SET sofia/internal/3059001001 at 9.9.9.9:5066 [effective_caller_id_name]=[13059001001]
EXECUTE sofia/internal/3059001001 at 9.9.9.9:5066 bridge(sofia/gateway/my_gatewaym/17708999518)
2017-03-02 09:35:55.890882 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
2017-03-02 09:35:55.890882 [NOTICE] switch_channel.c:1104 New Channel sofia/external/17708999518 [a2a9ca80-ff2b-11e6-833d-1dc743b2963b]
2017-03-02 09:35:55.890882 [DEBUG] mod_sofia.c:4881 (sofia/external/17708999518) State Change CS_NEW -> CS_INIT
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17708999518) Running State Change CS_INIT (Cur 6 Tot 797)
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:627 (sofia/external/17708999518) State INIT
2017-03-02 09:35:55.890882 [DEBUG] mod_sofia.c:92 sofia/external/17708999518 SOFIA INIT
2017-03-02 09:35:55.890882 [DEBUG] sofia_glue.c:1285 sofia/external/17708999518 sending invite version: 1.9.0 git f3b7105 2016-11-15 01:50:51Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1488425749 1488425750 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21606 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv

2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:40 sofia/external/17708999518 Standard INIT
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:48 (sofia/external/17708999518) State Change CS_INIT -> CS_ROUTING
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:627 (sofia/external/17708999518) State INIT going to sleep
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17708999518) Running State Change CS_ROUTING (Cur 6 Tot 797)
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:643 (sofia/external/17708999518) State ROUTING
2017-03-02 09:35:55.890882 [DEBUG] mod_sofia.c:145 sofia/external/17708999518 SOFIA ROUTING
2017-03-02 09:35:55.890882 [DEBUG] switch_ivr_originate.c:67 (sofia/external/17708999518) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:643 (sofia/external/17708999518) State ROUTING going to sleep
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17708999518) Running State Change CS_CONSUME_MEDIA (Cur 6 Tot 797)
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:662 (sofia/external/17708999518) State CONSUME_MEDIA
2017-03-02 09:35:55.890882 [DEBUG] switch_core_state_machine.c:662 (sofia/external/17708999518) State CONSUME_MEDIA going to sleep
2017-03-02 09:35:55.910883 [DEBUG] sofia.c:7107 Channel sofia/external/17708999518 entering state [calling][0]
2017-03-02 09:36:00.430891 [DEBUG] sofia.c:7107 Channel sofia/external/17708999518 entering state [proceeding][183]
2017-03-02 09:36:00.430891 [DEBUG] sofia.c:7117 Remote SDP:
v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 15906 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

2017-03-02 09:36:00.430891 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:40:8000:1]
2017-03-02 09:36:00.430891 [DEBUG] switch_core_media.c:4843 Audio Codec Compare [G729:18:8000:40:8000:1] ++++ is saved as a match
2017-03-02 09:36:00.430891 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:40:64000:1]
2017-03-02 09:36:00.430891 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:40:64000:1]
2017-03-02 09:36:00.430891 [DEBUG] switch_core_media.c:3385 Set Codec sofia/external/17708999518 G729/8000 40 ms 320 samples 8000 bits 1 channels
2017-03-02 09:36:00.430891 [DEBUG] switch_core_codec.c:111 sofia/external/17708999518 Original read codec set to G729:18
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:5077 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:5106 sofia/external/17708999518 Set 2833 dtmf send payload to 101 recv payload to 101
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7655 AUDIO RTP [sofia/external/17708999518] 9.9.9.9 port 21606 -> 173.230.226.241 port 15906 codec: 18 ms: 40
2017-03-02 09:36:00.450877 [DEBUG] switch_rtp.c:3885 Starting timer [soft] 320 bytes per 40ms
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7963 sofia/external/17708999518 Set 2833 dtmf send payload to 101
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7970 sofia/external/17708999518 Set 2833 dtmf receive payload to 101
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7993 sofia/external/17708999518 Set rtp dtmf delay to 40
2017-03-02 09:36:00.450877 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/17708999518!
2017-03-02 09:36:00.450877 [DEBUG] switch_channel.c:3471 (sofia/external/17708999518) Callstate Change DOWN -> EARLY
2017-03-02 09:36:00.450877 [INFO] switch_ivr_originate.c:3640 Sending early media
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G729:18:8000:40:8000:1]/[G729:18:8000:20:8000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4824 Audio Codec Compare [G729:18:8000:20:8000:1] is saved as a near-match
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G729:18:8000:40:8000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G729:18:8000:40:8000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [iLBC:97:8000:40:0:1]/[G729:18:8000:20:8000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [iLBC:97:8000:40:0:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [iLBC:97:8000:40:0:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[G729:18:8000:20:8000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [PCMU:0:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4824 Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a near-match
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[G729:18:8000:20:8000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4824 Audio Codec Compare [PCMA:8:8000:20:64000:1] is saved as a near-match
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [PCMA:8:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G722:9:8000:40:64000:1]/[G729:18:8000:20:8000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G722:9:8000:40:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G722:9:8000:40:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G726-32:2:8000:40:0:1]/[G729:18:8000:20:8000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G726-32:2:8000:40:0:1]/[PCMA:8:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4788 Audio Codec Compare [G726-32:2:8000:40:0:1]/[PCMU:0:8000:20:64000:1]
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4704 Set telephone-event payload to 101 at 8000
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:4895 Substituting codec G729 at 40i@8000h at 1c
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:3385 Set Codec sofia/internal/3059001001 at 9.9.9.9:5066 G729/8000 40 ms 320 samples 8000 bits 1 channels
2017-03-02 09:36:00.450877 [DEBUG] switch_core_codec.c:111 sofia/internal/3059001001 at 9.9.9.9:5066 Original read codec set to G729:18
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:5047 Set telephone-event payload to 101 at 8000
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:5106 sofia/internal/3059001001 at 9.9.9.9:5066 Set 2833 dtmf send payload to 101 recv payload to 101
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7655 AUDIO RTP [sofia/internal/3059001001 at 9.9.9.9:5066] 9.9.9.9 port 21730 -> 1.1.1.1 port 5004 codec: 18 ms: 40
2017-03-02 09:36:00.450877 [DEBUG] switch_rtp.c:3885 Starting timer [soft] 320 bytes per 40ms
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7963 sofia/internal/3059001001 at 9.9.9.9:5066 Set 2833 dtmf send payload to 101
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7970 sofia/internal/3059001001 at 9.9.9.9:5066 Set 2833 dtmf receive payload to 101
2017-03-02 09:36:00.450877 [DEBUG] switch_core_media.c:7993 sofia/internal/3059001001 at 9.9.9.9:5066 Set rtp dtmf delay to 40
2017-03-02 09:36:00.450877 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/3059001001 at 9.9.9.9:5066!
2017-03-02 09:36:00.470867 [DEBUG] switch_channel.c:3471 (sofia/internal/3059001001 at 9.9.9.9:5066) Callstate Change RINGING -> EARLY
2017-03-02 09:36:00.470867 [DEBUG] switch_core_media.c:7638 Audio params are unchanged for sofia/internal/3059001001 at 9.9.9.9:5066.
2017-03-02 09:36:00.470867 [DEBUG] mod_sofia.c:2397 Ring SDP:
v=0
o=FreeSWITCH 1488425630 1488425631 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21730 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv

2017-03-02 09:36:00.470867 [DEBUG] switch_ivr_originate.c:3691 Originate Resulted in Success: [sofia/external/17708999518]
2017-03-02 09:36:00.470867 [DEBUG] sofia.c:7107 Channel sofia/internal/3059001001 at 9.9.9.9:5066 entering state [early][183]
2017-03-02 09:36:00.470867 [DEBUG] switch_ivr_bridge.c:1696 (sofia/external/17708999518) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-03-02 09:36:00.470867 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17708999518) Running State Change CS_EXCHANGE_MEDIA (Cur 4 Tot 797)
2017-03-02 09:36:00.470867 [DEBUG] switch_core_state_machine.c:653 (sofia/external/17708999518) State EXCHANGE_MEDIA
2017-03-02 09:36:00.470867 [DEBUG] mod_sofia.c:635 SOFIA EXCHANGE_MEDIA
2017-03-02 09:36:00.570897 [DEBUG] switch_rtp.c:6991 Correct audio ip/port confirmed.
2017-03-02 09:36:00.850880 [WARNING] switch_core_media.c:2748 [CBR]: Asynchronous PTIME not supported, changing our end from 40 to 20
2017-03-02 09:36:00.890879 [DEBUG] switch_core_media.c:3283 Changing Codec from G729 at 40ms@8000hz to G729 at 20ms@8000hz
2017-03-02 09:36:00.970881 [DEBUG] switch_rtp.c:3763 RE-Starting timer [soft] 160 bytes per 20ms
2017-03-02 09:36:00.970881 [DEBUG] switch_core_media.c:3385 Set Codec sofia/external/17708999518 G729/8000 20 ms 160 samples 8000 bits 1 channels
2017-03-02 09:36:00.970881 [DEBUG] switch_core_codec.c:123 sofia/external/17708999518 Original read codec replaced with G729:18
2017-03-02 09:36:01.010874 [DEBUG] switch_core_media.c:14735 Engaging Write Buffer at 640 bytes to accommodate 320->640
2017-03-02 09:36:01.010874 [DEBUG] switch_core_media.c:6336 sofia/external/17708999518 Starting Audio write thread
2017-03-02 09:36:01.010874 [DEBUG] switch_core_media.c:14735 Engaging Write Buffer at 320 bytes to accommodate 640->320
2017-03-02 09:36:01.290895 [INFO] switch_rtp.c:6951 Auto Changing audio port from 1.1.1.1:5004 to 1.1.1.1:1024
2017-03-02 09:36:05.850897 [DEBUG] sofia.c:7107 Channel sofia/external/17708999518 entering state [completing][200]
2017-03-02 09:36:05.850897 [DEBUG] sofia.c:7114 Duplicate SDP
v=0
o=msw1 0 0 IN IP4 10.10.10.10
s=sip call
c=IN IP4 173.230.226.241
t=0 0
m=audio 15906 RTP/AVP 18
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

2017-03-02 09:36:05.870885 [DEBUG] sofia.c:7107 Channel sofia/external/17708999518 entering state [ready][200]
2017-03-02 09:36:05.870885 [NOTICE] sofia.c:8113 Channel [sofia/external/17708999518] has been answered
2017-03-02 09:36:05.870885 [DEBUG] switch_channel.c:3770 (sofia/external/17708999518) Callstate Change EARLY -> ACTIVE
2017-03-02 09:36:05.910876 [DEBUG] switch_core_media.c:7638 Audio params are unchanged for sofia/internal/3059001001 at 9.9.9.9:5066.
2017-03-02 09:36:05.910876 [DEBUG] mod_sofia.c:826 Local SDP sofia/internal/3059001001 at 9.9.9.9:5066:
v=0
o=FreeSWITCH 1488425630 1488425632 IN IP4 9.9.9.9
s=FreeSWITCH
c=IN IP4 9.9.9.9
t=0 0
m=audio 21730 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:40
a=sendrecv

2017-03-02 09:36:05.910876 [NOTICE] switch_ivr_bridge.c:703 Channel [sofia/internal/3059001001 at 9.9.9.9:5066] has been answered
2017-03-02 09:36:05.910876 [DEBUG] switch_rtp.c:6991 Correct audio ip/port confirmed.
2017-03-02 09:36:05.910876 [DEBUG] switch_channel.c:3770 (sofia/internal/3059001001 at 9.9.9.9:5066) Callstate Change EARLY -> ACTIVE
2017-03-02 09:36:05.910876 [DEBUG] sofia.c:7107 Channel sofia/internal/3059001001 at 9.9.9.9:5066 entering state [completed][200]
2017-03-02 09:36:06.010890 [DEBUG] switch_rtp.c:6991 Correct audio ip/port confirmed.
2017-03-02 09:36:37.930899 [DEBUG] sofia.c:7107 Channel sofia/internal/3059001001 at 9.9.9.9:5066 entering state [terminating][0]
2017-03-02 09:36:37.930899 [NOTICE] sofia.c:8227 Hangup sofia/internal/3059001001 at 9.9.9.9:5066 [CS_EXECUTE] [NORMAL_UNSPECIFIED]
2017-03-02 09:36:37.950865 [DEBUG] switch_ivr_bridge.c:798 sofia/internal/3059001001 at 9.9.9.9:5066 ending bridge by request from read function
2017-03-02 09:36:37.950865 [DEBUG] switch_ivr_bridge.c:882 BRIDGE THREAD DONE [sofia/internal/3059001001 at 9.9.9.9:5066]
2017-03-02 09:36:37.950865 [DEBUG] switch_ivr_bridge.c:792 sofia/internal/3059001001 at 9.9.9.9:5066 ending bridge by request from write function
2017-03-02 09:36:37.950865 [DEBUG] switch_ivr_bridge.c:882 BRIDGE THREAD DONE [sofia/external/17708999518]
2017-03-02 09:36:37.950865 [NOTICE] switch_ivr_bridge.c:986 Hangup sofia/external/17708999518 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:653 (sofia/external/17708999518) State EXCHANGE_MEDIA going to sleep
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17708999518) Running State Change CS_HANGUP (Cur 6 Tot 799)
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:850 (sofia/external/17708999518) Callstate Change ACTIVE -> HANGUP
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:852 (sofia/external/17708999518) State HANGUP
2017-03-02 09:36:37.950865 [DEBUG] mod_sofia.c:440 Channel sofia/external/17708999518 hanging up, cause: NORMAL_CLEARING
2017-03-02 09:36:37.950865 [DEBUG] mod_sofia.c:493 Sending BYE to sofia/external/17708999518
2017-03-02 09:36:37.950865 [DEBUG] switch_ivr_bridge.c:1795 sofia/external/17708999518 skip receive message [UNBRIDGE] (channel is hungup already)
2017-03-02 09:36:37.950865 [DEBUG] switch_ivr_bridge.c:1798 sofia/internal/3059001001 at 9.9.9.9:5066 skip receive message [UNBRIDGE] (channel is hungup already)
2017-03-02 09:36:37.950865 [DEBUG] switch_core_session.c:2867 sofia/internal/3059001001 at 9.9.9.9:5066 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/3059001001 at 9.9.9.9:5066) State EXECUTE going to sleep
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_HANGUP (Cur 6 Tot 799)
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:60 sofia/external/17708999518 Standard HANGUP, cause: NORMAL_CLEARING
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:852 (sofia/external/17708999518) State HANGUP going to sleep
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:619 (sofia/external/17708999518) State Change CS_HANGUP -> CS_REPORTING
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:584 (sofia/external/17708999518) Running State Change CS_REPORTING (Cur 6 Tot 799)
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:938 (sofia/external/17708999518) State REPORTING
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:174 sofia/external/17708999518 Standard REPORTING, cause: NORMAL_CLEARING
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:938 (sofia/external/17708999518) State REPORTING going to sleep
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/3059001001 at 9.9.9.9:5066) Callstate Change ACTIVE -> HANGUP
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3059001001 at 9.9.9.9:5066) State HANGUP
2017-03-02 09:36:37.950865 [DEBUG] mod_sofia.c:440 Channel sofia/internal/3059001001 at 9.9.9.9:5066 hanging up, cause: NORMAL_UNSPECIFIED
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:610 (sofia/external/17708999518) State Change CS_REPORTING -> CS_DESTROY
2017-03-02 09:36:37.950865 [DEBUG] switch_core_session.c:1695 Session 797 (sofia/external/17708999518) Locked, Waiting on external entities
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:60 sofia/internal/3059001001 at 9.9.9.9:5066 Standard HANGUP, cause: NORMAL_UNSPECIFIED
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/3059001001 at 9.9.9.9:5066) State HANGUP going to sleep
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/3059001001 at 9.9.9.9:5066) State Change CS_HANGUP -> CS_REPORTING
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_REPORTING (Cur 6 Tot 799)
2017-03-02 09:36:37.950865 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3059001001 at 9.9.9.9:5066) State REPORTING
2017-03-02 09:36:37.970919 [NOTICE] switch_core_session.c:1713 Session 797 (sofia/external/17708999518) Ended
2017-03-02 09:36:37.970919 [NOTICE] switch_core_session.c:1717 Close Channel sofia/external/17708999518 [CS_DESTROY]
2017-03-02 09:36:37.970919 [DEBUG] switch_core_state_machine.c:741 (sofia/external/17708999518) Running State Change CS_DESTROY (Cur 5 Tot 799)
2017-03-02 09:36:37.970919 [DEBUG] switch_core_state_machine.c:751 (sofia/external/17708999518) State DESTROY
2017-03-02 09:36:37.970919 [DEBUG] mod_sofia.c:345 sofia/external/17708999518 SOFIA DESTROY
2017-03-02 09:36:37.970919 [DEBUG] switch_core_state_machine.c:181 sofia/external/17708999518 Standard DESTROY
2017-03-02 09:36:37.970919 [DEBUG] switch_core_state_machine.c:751 (sofia/external/17708999518) State DESTROY going to sleep
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:174 sofia/internal/3059001001 at 9.9.9.9:5066 Standard REPORTING, cause: NORMAL_UNSPECIFIED
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/3059001001 at 9.9.9.9:5066) State REPORTING going to sleep
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/3059001001 at 9.9.9.9:5066) State Change CS_REPORTING -> CS_DESTROY
2017-03-02 09:36:37.990965 [DEBUG] switch_core_session.c:1695 Session 796 (sofia/internal/3059001001 at 9.9.9.9:5066) Locked, Waiting on external entities
2017-03-02 09:36:37.990965 [NOTICE] switch_core_session.c:1713 Session 796 (sofia/internal/3059001001 at 9.9.9.9:5066) Ended
2017-03-02 09:36:37.990965 [NOTICE] switch_core_session.c:1717 Close Channel sofia/internal/3059001001 at 9.9.9.9:5066 [CS_DESTROY]
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/3059001001 at 9.9.9.9:5066) Running State Change CS_DESTROY (Cur 4 Tot 799)
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3059001001 at 9.9.9.9:5066) State DESTROY
2017-03-02 09:36:37.990965 [DEBUG] mod_sofia.c:345 sofia/internal/3059001001 at 9.9.9.9:5066 SOFIA DESTROY
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:181 sofia/internal/3059001001 at 9.9.9.9:5066 Standard DESTROY
2017-03-02 09:36:37.990965 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/3059001001 at 9.9.9.9:5066) State DESTROY going to sleep