[Freeswitch-users] FreeSWITCH not sending BYE
Kamrul Khan
dodul at live.com
Thu Sep 18 03:06:08 MSD 2014
Hi,
Im using freeswitch version 1.4.6. Its not sending back any BYE message. So the caller side thinks call is still alive. The scenario is like the below:
Alice(10.1.1.1) ---> Freeswitch(172.16.0.150)--->Bob(10.2.1.1)
If the call is terminated by Bob. Bob sends BYE to Freeswitch. but, Freeswitch simply sends back a 200 OK to BOB and drops the call. Doesnt send back any BYE to Alice. Therefore, Alice thinks the Call is still alive. How to fix this. HELP!!!
Check my My SIP TRACE:
------------------------------------------------------------------------
recv 2234 bytes from udp/[172.16.0.150]:5063 at 16:48:42.959303:
------------------------------------------------------------------------
INVITE sip:+12345678 at fs.mydomain.com SIP/2.0
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK92c.41e977c95ac87d15f0c4b613d3349799.0
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKQ3XukR17yfTyWXoEF01daB399SarZSUQ;rport=64649
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>
Contact: "Alice"<sip:alice at 10.1.1.2:64649;rtcweb-breaker=no;click2call=no;transport=ws>;+g.oma.sip-im;+sip.ice;language="en,fr";received="sip:10.1.1.2:64649;transport=WS"
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10769 INVITE
Content-Type: application/sdp
Content-Length: 1262
Max-Forwards: 69
User-Agent: IM-client/OMA1.0 sipML5-v1.0.0.0
Organization: Dingaling.ca
Path: <sip:172.16.0.150:5063;lr>
v=0
o=Mozilla-SIPUA-31.0 322 1 IN IP4 0.0.0.0
s=Doubango Telecom - firefox
t=0 0
a=ice-ufrag:17e36105
a=ice-pwd:35179857c2c39018fb82455091801d8a
a=fingerprint:sha-256 68:54:EE:EF:A0:BF:93:B9:B6:63:18:0F:C1:A1:BE:5C:6F:49:11:67:1A:88:2D:DC:20:09:80:92:A4:4C:5A:F1
m=audio 60678 UDP/TLS/RTP/SAVPF 109 0 8 101
c=IN IP4 172.16.0.150
a=rtpmap:109 opus/48000/2
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=setup:actpass
a=candidate:0 1 UDP 2128609535 172.16.1.188 54467 typ host
a=candidate:2 1 UDP 1692467199 10.1.1.2 54467 typ srflx raddr 172.16.1.188 rport 54467
a=candidate:5 1 UDP 2128543999 192.168.56.1 54468 typ host
a=candidate:10 1 UDP 2128478463 192.168.232.1 54469 typ host
a=candidate:15 1 UDP 2128412927 192.168.146.1 54470 typ host
a=candidate:0 2 UDP 2128609534 172.16.1.188 54471 typ host
a=candidate:1 2 UDP 1692467198 10.1.1.2 54471 typ srflx raddr 172.16.1.188 rport 54471
a=candidate:5 2 UDP 2128543998 192.168.56.1 54472 typ host
a=candidate:10 2 UDP 2128478462 192.168.232.1 54473 typ host
a=candidate:15 2 UDP 2128412926 192.168.146.1 54474 typ host
a=rtcp-mux
a=nortpproxy:yes
------------------------------------------------------------------------
send 619 bytes to udp/[172.16.0.150]:5063 at 16:48:42.959974:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK92c.41e977c95ac87d15f0c4b613d3349799.0;received=172.16.0.150
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKQ3XukR17yfTyWXoEF01daB399SarZSUQ;rport=64649
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10769 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~64bit
Content-Length: 0
------------------------------------------------------------------------
2014-09-17 16:48:42.945889 [NOTICE] switch_channel.c:1053 New Channel sofia/internal/alice at fs.mydomain.com [76f1d37a-b4c0-4247-9fb2-45cf6eadd969]
2014-09-17 16:48:42.945889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:42.945889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:42.945889 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_NEW
2014-09-17 16:48:42.945889 [DEBUG] sofia.c:8367 sofia/internal/alice at fs.mydomain.com receiving invite from 172.16.0.150:5063 version: 1.4.6 git 9479729 2014-06-03 19:35:16Z 64bit
2014-09-17 16:48:42.945889 [DEBUG] sofia.c:8534 IP 172.16.0.150 Rejected by acl "domains". Falling back to Digest auth.
2014-09-17 16:48:42.945889 [DEBUG] switch_core_state_machine.c:489 (sofia/internal/alice at fs.mydomain.com) State NEW
send 1069 bytes to udp/[172.16.0.150]:5063 at 16:48:42.962202:
------------------------------------------------------------------------
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK92c.41e977c95ac87d15f0c4b613d3349799.0;received=172.16.0.150
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKQ3XukR17yfTyWXoEF01daB399SarZSUQ;rport=64649
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>;tag=80Ny99e7gvpUj
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10769 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~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="fs.mydomain.com", nonce="4c15231c-896a-4131-b7c2-621ab8342e9a", algorithm=MD5, qop="auth"
Content-Length: 0
------------------------------------------------------------------------
2014-09-17 16:48:42.945889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:42.945889 [DEBUG] sofia.c:2033 detaching session 76f1d37a-b4c0-4247-9fb2-45cf6eadd969
recv 615 bytes from udp/[172.16.0.150]:5063 at 16:48:42.998781:
------------------------------------------------------------------------
ACK sip:+12345678 at fs.mydomain.com SIP/2.0
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK92c.41e977c95ac87d15f0c4b613d3349799.0
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKQ3XukR17yfTyWXoEF01daB399SarZSUQ;rport=64649
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>;tag=80Ny99e7gvpUj
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10769 ACK
Content-Length: 0
Max-Forwards: 69
Path: <sip:172.16.0.150:5063;lr>
------------------------------------------------------------------------
recv 2543 bytes from udp/[172.16.0.150]:5063 at 16:48:43.004244:
------------------------------------------------------------------------
INVITE sip:+12345678 at fs.mydomain.com SIP/2.0
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK22c.2784592c8ddaf1dddc7bcb9bbcbecd6a.0
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKJtOEBT8qZTFStRrzMZcGKo1Tq8iXUdFm;rport=64649
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>
Contact: "Alice"<sip:alice at 10.1.1.2:64649;rtcweb-breaker=no;click2call=no;transport=ws>;+g.oma.sip-im;+sip.ice;language="en,fr";received="sip:10.1.1.2:64649;transport=WS"
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10770 INVITE
Content-Type: application/sdp
Content-Length: 1262
Max-Forwards: 69
Proxy-Authorization: Digest username="alice",realm="fs.mydomain.com",nonce="4c15231c-896a-4131-b7c2-621ab8342e9a",uri="sip:+12345678 at fs.mydomain.com",response="3f71cf991c76159a30fe0fbea938cbb9",algorithm=MD5,cnonce="8dabac05b6f0a365d085158868220703",qop=auth,nc=00000001
User-Agent: IM-client/OMA1.0 sipML5-v1.0.0.0
Organization: Dingaling.ca
Path: <sip:172.16.0.150:5063;lr>
v=0
o=Mozilla-SIPUA-31.0 322 1 IN IP4 0.0.0.0
s=Doubango Telecom - firefox
t=0 0
a=ice-ufrag:17e36105
a=ice-pwd:35179857c2c39018fb82455091801d8a
a=fingerprint:sha-256 68:54:EE:EF:A0:BF:93:B9:B6:63:18:0F:C1:A1:BE:5C:6F:49:11:67:1A:88:2D:DC:20:09:80:92:A4:4C:5A:F1
m=audio 38168 UDP/TLS/RTP/SAVPF 109 0 8 101
c=IN IP4 172.16.0.150
a=rtpmap:109 opus/48000/2
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=setup:actpass
a=candidate:0 1 UDP 2128609535 172.16.1.188 54467 typ host
a=candidate:2 1 UDP 1692467199 10.1.1.2 54467 typ srflx raddr 172.16.1.188 rport 54467
a=candidate:5 1 UDP 2128543999 192.168.56.1 54468 typ host
a=candidate:10 1 UDP 2128478463 192.168.232.1 54469 typ host
a=candidate:15 1 UDP 2128412927 192.168.146.1 54470 typ host
a=candidate:0 2 UDP 2128609534 172.16.1.188 54471 typ host
a=candidate:1 2 UDP 1692467198 10.1.1.2 54471 typ srflx raddr 172.16.1.188 rport 54471
a=candidate:5 2 UDP 2128543998 192.168.56.1 54472 typ host
a=candidate:10 2 UDP 2128478462 192.168.232.1 54473 typ host
a=candidate:15 2 UDP 2128412926 192.168.146.1 54474 typ host
a=rtcp-mux
a=nortpproxy:yes
------------------------------------------------------------------------
send 619 bytes to udp/[172.16.0.150]:5063 at 16:48:43.005058:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK22c.2784592c8ddaf1dddc7bcb9bbcbecd6a.0;received=172.16.0.150
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKJtOEBT8qZTFStRrzMZcGKo1Tq8iXUdFm;rport=64649
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10770 INVITE
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~64bit
Content-Length: 0
------------------------------------------------------------------------
2014-09-17 16:48:42.985935 [DEBUG] sofia.c:2138 Re-attaching to session 76f1d37a-b4c0-4247-9fb2-45cf6eadd969
2014-09-17 16:48:42.985935 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:42.985935 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:43.005913 [DEBUG] sofia.c:8367 sofia/internal/alice at fs.mydomain.com receiving invite from 172.16.0.150:5063 version: 1.4.6 git 9479729 2014-06-03 19:35:16Z 64bit
2014-09-17 16:48:43.005913 [DEBUG] sofia.c:8534 IP 172.16.0.150 Rejected by acl "domains". Falling back to Digest auth.
2014-09-17 16:48:43.285898 [DEBUG] sofia.c:6229 Channel sofia/internal/alice at fs.mydomain.com entering state [received][100]
2014-09-17 16:48:43.285898 [DEBUG] sofia.c:6239 Remote SDP:
v=0
o=Mozilla-SIPUA-31.0 322 1 IN IP4 0.0.0.0
s=Doubango Telecom - firefox
t=0 0
a=ice-ufrag:17e36105
a=ice-pwd:35179857c2c39018fb82455091801d8a
a=fingerprint:sha-256 68:54:EE:EF:A0:BF:93:B9:B6:63:18:0F:C1:A1:BE:5C:6F:49:11:67:1A:88:2D:DC:20:09:80:92:A4:4C:5A:F1
m=audio 38168 UDP/TLS/RTP/SAVPF 109 0 8 101
c=IN IP4 172.16.0.150
a=rtpmap:109 opus/48000/2
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=setup:actpass
a=candidate:0 1 UDP 2128609535 172.16.1.188 54467 typ host
a=candidate:2 1 UDP 1692467199 10.1.1.2 54467 typ srflx raddr 172.16.1.188 rport 54467
a=candidate:5 1 UDP 2128543999 192.168.56.1 54468 typ host
a=candidate:10 1 UDP 2128478463 192.168.232.1 54469 typ host
a=candidate:15 1 UDP 2128412927 192.168.146.1 54470 typ host
a=candidate:0 2 UDP 2128609534 172.16.1.188 54471 typ host
a=candidate:1 2 UDP 1692467198 10.1.1.2 54471 typ srflx raddr 172.16.1.188 rport 54471
a=candidate:5 2 UDP 2128543998 192.168.56.1 54472 typ host
a=candidate:10 2 UDP 2128478462 192.168.232.1 54473 typ host
a=candidate:15 2 UDP 2128412926 192.168.146.1 54474 typ host
a=rtcp-mux
a=nortpproxy:yes
2014-09-17 16:48:43.285898 [DEBUG] sofia.c:6494 (sofia/internal/alice at fs.mydomain.com) State Change CS_NEW -> CS_INIT
2014-09-17 16:48:43.285898 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_INIT
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:510 (sofia/internal/alice at fs.mydomain.com) State INIT
2014-09-17 16:48:43.285898 [DEBUG] mod_sofia.c:87 sofia/internal/alice at fs.mydomain.com SOFIA INIT
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:40 sofia/internal/alice at fs.mydomain.com Standard INIT
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/alice at fs.mydomain.com) State Change CS_INIT -> CS_ROUTING
2014-09-17 16:48:43.285898 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:510 (sofia/internal/alice at fs.mydomain.com) State INIT going to sleep
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_ROUTING
2014-09-17 16:48:43.285898 [DEBUG] switch_channel.c:2180 (sofia/internal/alice at fs.mydomain.com) Callstate Change DOWN -> RINGING
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:526 (sofia/internal/alice at fs.mydomain.com) State ROUTING
2014-09-17 16:48:43.285898 [DEBUG] mod_sofia.c:123 sofia/internal/alice at fs.mydomain.com SOFIA ROUTING
2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:164 sofia/internal/alice at fs.mydomain.com Standard ROUTING
2014-09-17 16:48:43.285898 [INFO] mod_dialplan_xml.c:558 Processing Alice <alice>->+12345678 in context dal-ingress
Dialplan: sofia/internal/alice at fs.mydomain.com parsing [dal-ingress->3a05956905ca41e2b43170968d44398e] continue=false
Dialplan: sofia/internal/alice at fs.mydomain.com Absolute Condition [3a05956905ca41e2b43170968d44398e]
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(dal-UUID=3a05956905ca41e2b43170968d44398e)
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(dal-Language=en)
Dialplan: sofia/internal/alice at fs.mydomain.com Action set(effective_caller_id_number=17783315100)
Dialplan: sofia/internal/alice at fs.mydomain.com Action set(effective_caller_id_name=Alice)
Dialplan: sofia/internal/alice at fs.mydomain.com Action set(sip_rh_X-DAL-UUID=3a05956905ca41e2b43170968d44398e)
Dialplan: sofia/internal/alice at fs.mydomain.com Action set(sip_ph_X-DAL-UUID=3a05956905ca41e2b43170968d44398e)
Dialplan: sofia/internal/alice at fs.mydomain.com Action set(sip_bye_h_X-DAL-UUID=3a05956905ca41e2b43170968d44398e)
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(DAL-Time-Limit=118)
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(DAL-Time-Limit-Bye=you-have-reached-the-time-limit-for-this-call)
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(DAL-Time-Limit-Warnings=60 at aleg:you-have-one-minute-remaining,300 at aleg:you-have-five-minutes-remaining-for-this-call)
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(nolocal:execute_on_answer=lua mod_callmgr/on-bridge.lua)
Dialplan: sofia/internal/alice at fs.mydomain.com Action export(DAL-Report-URL=http://todo-kkhan.dlcworldwide.com/index.php/internal/)
Dialplan: sofia/internal/alice at fs.mydomain.com Action event(Event-Subclass=callmgr::call_uuid,Event-Name=CUSTOM)
Dialplan: sofia/internal/alice at fs.mydomain.com Action set(sip_h_Route=<sip:172.16.0.150:5063>)
Dialplan: sofia/internal/alice at fs.mydomain.com Action bridge(sofia/gateway/bobspecial/0000100912345678;fs_path=sip:172.16.0.150:5063|sofia/gateway/bob/12345678;fs_path=sip:172.16.0.150:5063|sofia/gateway/navigata/12345678;fs_path=sip:172.16.0.150:5063|sofia/gateway/lesnet/12345678;fs_path=sip:172.16.0.150:5063)
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:214 (sofia/internal/alice at fs.mydomain.com) State Change CS_ROUTING -> CS_EXECUTE
2014-09-17 16:48:43.705898 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:526 (sofia/internal/alice at fs.mydomain.com) State ROUTING going to sleep
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_EXECUTE
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:533 (sofia/internal/alice at fs.mydomain.com) State EXECUTE
2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:178 sofia/internal/alice at fs.mydomain.com SOFIA EXECUTE
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:256 sofia/internal/alice at fs.mydomain.com Standard EXECUTE
EXECUTE sofia/internal/alice at fs.mydomain.com export(dal-UUID=3a05956905ca41e2b43170968d44398e)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) [dal-UUID]=[3a05956905ca41e2b43170968d44398e]
EXECUTE sofia/internal/alice at fs.mydomain.com export(dal-Language=en)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) [dal-Language]=[en]
EXECUTE sofia/internal/alice at fs.mydomain.com set(effective_caller_id_number=17783315100)
2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice at fs.mydomain.com SET [effective_caller_id_number]=[17783315100]
EXECUTE sofia/internal/alice at fs.mydomain.com set(effective_caller_id_name=Alice)
2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice at fs.mydomain.com SET [effective_caller_id_name]=[Alice]
EXECUTE sofia/internal/alice at fs.mydomain.com set(sip_rh_X-DAL-UUID=3a05956905ca41e2b43170968d44398e)
2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice at fs.mydomain.com SET [sip_rh_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e]
EXECUTE sofia/internal/alice at fs.mydomain.com set(sip_ph_X-DAL-UUID=3a05956905ca41e2b43170968d44398e)
2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice at fs.mydomain.com SET [sip_ph_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e]
EXECUTE sofia/internal/alice at fs.mydomain.com set(sip_bye_h_X-DAL-UUID=3a05956905ca41e2b43170968d44398e)
2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice at fs.mydomain.com SET [sip_bye_h_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e]
EXECUTE sofia/internal/alice at fs.mydomain.com export(DAL-Time-Limit=118)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) [DAL-Time-Limit]=[118]
EXECUTE sofia/internal/alice at fs.mydomain.com export(DAL-Time-Limit-Bye=you-have-reached-the-time-limit-for-this-call)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) [DAL-Time-Limit-Bye]=[you-have-reached-the-time-limit-for-this-call]
EXECUTE sofia/internal/alice at fs.mydomain.com export(DAL-Time-Limit-Warnings=60 at aleg:you-have-one-minute-remaining,300 at aleg:you-have-five-minutes-remaining-for-this-call)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) [DAL-Time-Limit-Warnings]=[60 at aleg:you-have-one-minute-remaining,300 at aleg:you-have-five-minutes-remaining-for-this-call]
EXECUTE sofia/internal/alice at fs.mydomain.com export(nolocal:execute_on_answer=lua mod_callmgr/on-bridge.lua)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) (REMOTE ONLY) [execute_on_answer]=[lua mod_callmgr/on-bridge.lua]
EXECUTE sofia/internal/alice at fs.mydomain.com export(DAL-Report-URL=http://todo-kkhan.dlcworldwide.com/index.php/internal/)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1245 EXPORT (export_vars) [DAL-Report-URL]=[http://todo-kkhan.dlcworldwide.com/index.php/internal/]
EXECUTE sofia/internal/alice at fs.mydomain.com event(Event-Subclass=callmgr::call_uuid,Event-Name=CUSTOM)
EXECUTE sofia/internal/alice at fs.mydomain.com set(sip_h_Route=<sip:172.16.0.150:5063>)
2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice at fs.mydomain.com SET [sip_h_Route]=[<sip:172.16.0.150:5063>]
EXECUTE sofia/internal/alice at fs.mydomain.com bridge(sofia/gateway/bobspecial/0000100912345678;fs_path=sip:172.16.0.150:5063|sofia/gateway/bob/12345678;fs_path=sip:172.16.0.150:5063|sofia/gateway/navigata/12345678;fs_path=sip:172.16.0.150:5063|sofia/gateway/lesnet/12345678;fs_path=sip:172.16.0.150:5063)
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [dal-UUID]=[3a05956905ca41e2b43170968d44398e] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [dal-Language]=[en] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [DAL-Time-Limit]=[118] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [DAL-Time-Limit-Bye]=[you-have-reached-the-time-limit-for-this-call] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [DAL-Time-Limit-Warnings]=[60 at aleg:you-have-one-minute-remaining,300 at aleg:you-have-five-minutes-remaining-for-this-call] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [execute_on_answer]=[lua mod_callmgr/on-bridge.lua] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice at fs.mydomain.com EXPORTING[export_vars] [DAL-Report-URL]=[http://todo-kkhan.dlcworldwide.com/index.php/internal/] to event
2014-09-17 16:48:43.705898 [DEBUG] switch_ivr_originate.c:2078 Parsing global variables
2014-09-17 16:48:43.705898 [NOTICE] switch_channel.c:1053 New Channel sofia/internal/0000100912345678 [3b3c0b87-2c5b-42a0-9a78-90449685f296]
2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:4565 (sofia/internal/0000100912345678) State Change CS_NEW -> CS_INIT
2014-09-17 16:48:43.705898 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:4635 [zrtp_passthru] Setting a-leg inherit_codec=true
2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:4638 [zrtp_passthru] Setting b-leg absolute_codec_string='opus at 48000h@20i,PCMU at 8000h@20i at 64000b,PCMA at 8000h@20i at 64000b'
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/0000100912345678) Running State Change CS_INIT
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:510 (sofia/internal/0000100912345678) State INIT
2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:87 sofia/internal/0000100912345678 SOFIA INIT
2014-09-17 16:48:43.705898 [DEBUG] sofia_glue.c:1197 sip:172.16.0.150:5063 Setting proxy route to sofia/internal/0000100912345678
2014-09-17 16:48:43.705898 [DEBUG] sofia_glue.c:1226 sofia/internal/0000100912345678 sending invite version: 1.4.6 git 9479729 2014-06-03 19:35:16Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1410967571 1410967572 IN IP4 10.1.1.1
s=FreeSWITCH
c=IN IP4 10.1.1.1
t=0 0
m=audio 26552 RTP/AVP 109 0 8 101 13
a=rtpmap:109 opus/48000/2
a=fmtp:109 useinbandfec=1;usedtx=1;maxaveragebitrate=30000;ptime=20;minptime=20;maxptime=20;samplerate=48000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:40 sofia/internal/0000100912345678 Standard INIT
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/0000100912345678) State Change CS_INIT -> CS_ROUTING
2014-09-17 16:48:43.705898 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:510 (sofia/internal/0000100912345678) State INIT going to sleep
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/0000100912345678) Running State Change CS_ROUTING
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:526 (sofia/internal/0000100912345678) State ROUTING
2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:123 sofia/internal/0000100912345678 SOFIA ROUTING
2014-09-17 16:48:43.705898 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/0000100912345678) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2014-09-17 16:48:43.705898 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:526 (sofia/internal/0000100912345678) State ROUTING going to sleep
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/0000100912345678) Running State Change CS_CONSUME_MEDIA
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:545 (sofia/internal/0000100912345678) State CONSUME_MEDIA
2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:545 (sofia/internal/0000100912345678) State CONSUME_MEDIA going to sleep
send 1513 bytes to udp/[172.16.0.150]:5063 at 16:48:43.720773:
------------------------------------------------------------------------
INVITE sip:0000100912345678 at 10.2.1.1 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.150:6090;rport;branch=z9hG4bKDytKNrBp1aDrQ
Route: <sip:172.16.0.150:5063>
Route: <sip:172.16.0.150:5063>
Max-Forwards: 68
From: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
To: <sip:0000100912345678 at 10.2.1.1>
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 65160997 INVITE
Contact: <sip:gw+bobspecial at 172.16.0.150:6090;transport=udp;gw=bobspecial>
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~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: 390
X-FS-Support: update_display,send_info
Remote-Party-ID: "Alice" <sip:17783315100 at 10.2.1.1>;party=calling;screen=yes;privacy=off
v=0
o=FreeSWITCH 1410967571 1410967572 IN IP4 10.1.1.1
s=FreeSWITCH
c=IN IP4 10.1.1.1
t=0 0
m=audio 26552 RTP/AVP 109 0 8 101 13
a=rtpmap:109 opus/48000/2
a=fmtp:109 useinbandfec=1;usedtx=1;maxaveragebitrate=30000;ptime=20;minptime=20;maxptime=20;samplerate=48000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
2014-09-17 16:48:43.705898 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:43.705898 [DEBUG] sofia.c:6229 Channel sofia/internal/0000100912345678 entering state [calling][0]
recv 577 bytes from udp/[172.16.0.150]:5063 at 16:48:43.819920:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.0.150:6090;rport=6090;branch=z9hG4bKDytKNrBp1aDrQ
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
From: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
To: <sip:0000100912345678 at 10.2.1.1>
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 65160997 INVITE
User-Agent: bobPBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0000100912345678 at 10.2.1.1:5060>
Content-Length: 0
------------------------------------------------------------------------
recv 917 bytes from udp/[172.16.0.150]:5063 at 16:48:46.221310:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.16.0.150:6090;rport=6090;branch=z9hG4bKDytKNrBp1aDrQ
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
From: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
To: <sip:0000100912345678 at 10.2.1.1>;tag=as5129a390
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 65160997 INVITE
User-Agent: bobPBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0000100912345678 at 10.2.1.1:5060>
Content-Type: application/sdp
Content-Length: 282
v=0
o=root 27411 27411 IN IP4 172.16.0.150
s=session
c=IN IP4 172.16.0.150
t=0 0
m=audio 49198 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
a=nortpproxy:yes
------------------------------------------------------------------------
2014-09-17 16:48:46.205889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:46.205889 [DEBUG] sofia.c:6229 Channel sofia/internal/0000100912345678 entering state [proceeding][183]
2014-09-17 16:48:46.205889 [DEBUG] sofia.c:6239 Remote SDP:
v=0
o=root 27411 27411 IN IP4 172.16.0.150
s=session
c=IN IP4 172.16.0.150
t=0 0
m=audio 49198 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=nortpproxy:yes
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMU:0:8000:20:64000]/[opus:116:48000:20:0]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3437 Audio Codec Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMA:8:8000:20:64000]/[opus:116:48000:20:0]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3437 Audio Codec Compare [PCMA:8:8000:20:64000] ++++ is saved as a match
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3309 Set telephone-event payload to 101
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:2343 Set Codec sofia/internal/0000100912345678 PCMU/8000 20 ms 160 samples 64000 bits
2014-09-17 16:48:46.205889 [DEBUG] switch_core_codec.c:111 sofia/internal/0000100912345678 Original read codec set to PCMU:0
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:3617 Set 2833 dtmf send payload to 101
2014-09-17 16:48:46.205889 [DEBUG] switch_core_media.c:4842 AUDIO RTP [sofia/internal/0000100912345678] 10.1.1.1 port 26552 -> 172.16.0.150 port 49198 codec: 0 ms: 20
2014-09-17 16:48:46.205889 [DEBUG] switch_rtp.c:3351 Starting timer [soft] 160 bytes per 20ms
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:5189 Set 2833 dtmf send payload to 101
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:5195 Set 2833 dtmf receive payload to 101
2014-09-17 16:48:46.225921 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/0000100912345678!
2014-09-17 16:48:46.225921 [DEBUG] switch_channel.c:3391 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:46.225921 [DEBUG] switch_channel.c:3395 (sofia/internal/0000100912345678) Callstate Change DOWN -> EARLY
2014-09-17 16:48:46.225921 [DEBUG] switch_ivr_originate.c:412 Setting codec string on sofia/internal/alice at fs.mydomain.com to PCMU at 8000h@20i
2014-09-17 16:48:46.225921 [INFO] switch_ivr_originate.c:3500 Sending early media
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [opus:109:48000:20:0]/[PCMU:0:8000:20:64000]
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:3437 Audio Codec Compare [PCMU:0:8000:20:64000] ++++ is saved as a match
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:3383 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:3309 Set telephone-event payload to 101
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2343 Set Codec sofia/internal/alice at fs.mydomain.com PCMU/8000 20 ms 160 samples 64000 bits
2014-09-17 16:48:46.225921 [DEBUG] switch_core_codec.c:111 sofia/internal/alice at fs.mydomain.com Original read codec set to PCMU:0
2014-09-17 16:48:46.225921 [WARNING] switch_core_media.c:2548 NO candidate ACL defined, Defaulting to wan.auto
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 1 proto: UDP type: host addr: 172.16.1.188:54467
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: UDP type: host addr: 172.16.1.188:54467
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 1 proto: UDP type: srflx addr: 10.1.1.2:54467
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2581 Choose audio Candidate cid: 1 proto: UDP type: srflx addr: 10.1.1.2:54467
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 1 proto: UDP type: host addr: 192.168.56.1:54468
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: UDP type: host addr: 192.168.56.1:54468
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 1 proto: UDP type: host addr: 192.168.232.1:54469
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: UDP type: host addr: 192.168.232.1:54469
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 1 proto: UDP type: host addr: 192.168.146.1:54470
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 1 proto: UDP type: host addr: 192.168.146.1:54470
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 2 proto: UDP type: host addr: 172.16.1.188:54471
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 2 proto: UDP type: host addr: 172.16.1.188:54471
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 2 proto: UDP type: srflx addr: 10.1.1.2:54471
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2581 Choose audio Candidate cid: 2 proto: UDP type: srflx addr: 10.1.1.2:54471
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 2 proto: UDP type: host addr: 192.168.56.1:54472
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 2 proto: UDP type: host addr: 192.168.56.1:54472
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 2 proto: UDP type: host addr: 192.168.232.1:54473
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 2 proto: UDP type: host addr: 192.168.232.1:54473
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:2572 Checking Candidate cid: 2 proto: UDP type: host addr: 192.168.146.1:54474
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2586 Save audio Candidate cid: 2 proto: UDP type: host addr: 192.168.146.1:54474
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2710 setting remote audio ice addr to 10.1.1.2:54467 based on candidate
2014-09-17 16:48:46.225921 [NOTICE] switch_core_media.c:2730 setting remote rtcp audio addr to 10.1.1.2:54471 based on candidate
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:3626 Set 2833 dtmf send/recv payload to 101
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:4842 AUDIO RTP [sofia/internal/alice at fs.mydomain.com] 10.1.1.1 port 24858 -> 10.1.1.2 port 54467 codec: 0 ms: 20
2014-09-17 16:48:46.225921 [DEBUG] switch_rtp.c:3351 Starting timer [soft] 160 bytes per 20ms
2014-09-17 16:48:46.225921 [INFO] switch_core_media.c:5011 Activating Audio ICE
2014-09-17 16:48:46.225921 [NOTICE] switch_rtp.c:3792 Activating RTP audio ICE: 17e36105:JMJwWUvXyYRgIAHV 10.1.1.2:54467
2014-09-17 16:48:46.225921 [INFO] switch_core_media.c:5054 Activating RTCP PORT 54471
2014-09-17 16:48:46.225921 [DEBUG] switch_rtp.c:3697 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 54471
2014-09-17 16:48:46.225921 [DEBUG] switch_rtp.c:2170 Setting RTCP remote addr to 10.1.1.2:54471
2014-09-17 16:48:46.225921 [INFO] switch_core_media.c:5064 Activating RTCP ICE
2014-09-17 16:48:46.225921 [NOTICE] switch_rtp.c:3792 Activating RTCP audio ICE: 17e36105:JMJwWUvXyYRgIAHV 10.1.1.2:54471
2014-09-17 16:48:46.225921 [INFO] switch_rtp.c:2895 Activate RTP/RTCP audio DTLS client
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:5189 Set 2833 dtmf send payload to 101
2014-09-17 16:48:46.225921 [DEBUG] switch_core_media.c:5195 Set 2833 dtmf receive payload to 101
2014-09-17 16:48:46.225921 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/alice at fs.mydomain.com!
2014-09-17 16:48:46.225921 [DEBUG] switch_channel.c:3395 (sofia/internal/alice at fs.mydomain.com) Callstate Change RINGING -> EARLY
2014-09-17 16:48:46.225921 [DEBUG] mod_sofia.c:2222 Ring SDP:
v=0
o=FreeSWITCH 1410969268 1410969269 IN IP4 10.1.1.1
s=FreeSWITCH
c=IN IP4 10.1.1.1
t=0 0
a=msid-semantic: WMS RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
m=audio 24858 UDP/TLS/RTP/SAVPF 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=sendrecv
a=fingerprint:sha-256 91:E9:37:67:75:A4:28:C0:E6:DB:6B:2B:B7:A6:5E:5C:B5:2D:99:89:CF:26:44:FA:D0:82:A0:9C:F2:A2:84:94
a=rtcp-mux
a=rtcp:24858 IN IP4 10.1.1.1
a=ssrc:271344810 cname:nx21mWJyvjncyrD8
a=ssrc:271344810 msid:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA a0
a=ssrc:271344810 mslabel:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
a=ssrc:271344810 label:RDPCOY3SmIJZRpeBKriKXkk9aND4STSAa0
a=ice-ufrag:JMJwWUvXyYRgIAHV
a=ice-pwd:XAN9nnyIxMLV4fUDRtZEdlrB
a=candidate:2725252931 1 udp 659136 10.1.1.1 24858 typ host generation 0
2014-09-17 16:48:46.225921 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:46.225921 [DEBUG] switch_ivr_originate.c:3551 Originate Resulted in Success: [sofia/internal/0000100912345678]
2014-09-17 16:48:46.225921 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:46.225921 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:46.225921 [DEBUG] switch_ivr_bridge.c:1460 (sofia/internal/0000100912345678) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2014-09-17 16:48:46.225921 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
send 2056 bytes to udp/[172.16.0.150]:5063 at 16:48:46.238673:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK22c.2784592c8ddaf1dddc7bcb9bbcbecd6a.0;received=172.16.0.150
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKJtOEBT8qZTFStRrzMZcGKo1Tq8iXUdFm;rport=64649
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>;tag=99eQB5Zae5cee
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10770 INVITE
Contact: <sip:+12345678 at 172.16.0.150:6090;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~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-Type: application/sdp
Content-Disposition: session
Content-Length: 799
X-DAL-UUID: 3a05956905ca41e2b43170968d44398e
Remote-Party-ID: "Outbound Call" <sip:5063 at fs.mydomain.com>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1410969268 1410969269 IN IP4 10.1.1.1
s=FreeSWITCH
c=IN IP4 10.1.1.1
t=0 0
a=msid-semantic: WMS RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
m=audio 24858 UDP/TLS/RTP/SAVPF 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=fingerprint:sha-256 91:E9:37:67:75:A4:28:C0:E6:DB:6B:2B:B7:A6:5E:5C:B5:2D:99:89:CF:26:44:FA:D0:82:A0:9C:F2:A2:84:94
a=rtcp-mux
a=rtcp:24858 IN IP4 10.1.1.1
a=ssrc:271344810 cname:nx21mWJyvjncyrD8
a=ssrc:271344810 msid:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA a0
a=ssrc:271344810 mslabel:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
a=ssrc:271344810 label:RDPCOY3SmIJZRpeBKriKXkk9aND4STSAa0
a=ice-ufrag:JMJwWUvXyYRgIAHV
a=ice-pwd:XAN9nnyIxMLV4fUDRtZEdlrB
a=candidate:2725252931 1 udp 659136 10.1.1.1 24858 typ host generation 0
------------------------------------------------------------------------
2014-09-17 16:48:46.225921 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/0000100912345678) Running State Change CS_EXCHANGE_MEDIA
2014-09-17 16:48:46.225921 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:46.225921 [DEBUG] switch_core_state_machine.c:536 (sofia/internal/0000100912345678) State EXCHANGE_MEDIA
2014-09-17 16:48:46.225921 [DEBUG] mod_sofia.c:592 SOFIA EXCHANGE_MEDIA
2014-09-17 16:48:46.225921 [DEBUG] sofia.c:6229 Channel sofia/internal/alice at fs.mydomain.com entering state [early][183]
2014-09-17 16:48:47.305892 [INFO] switch_rtp.c:2718 Changing audio DTLS state from HANDSHAKE to SETUP
2014-09-17 16:48:47.305892 [INFO] switch_rtp.c:2626 audio Fingerprint Verified.
2014-09-17 16:48:47.305892 [INFO] switch_rtp.c:3168 Activating Audio Secure RTP SEND
2014-09-17 16:48:47.305892 [DEBUG] switch_core_sqldb.c:2568 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2014-09-17 16:48:47.305892 [INFO] switch_rtp.c:3146 Activating Audio Secure RTP RECV
2014-09-17 16:48:47.305892 [INFO] switch_rtp.c:2666 Changing audio DTLS state from SETUP to READY
2014-09-17 16:48:47.305892 [DEBUG] switch_core_sqldb.c:2568 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2014-09-17 16:48:47.545899 [INFO] switch_rtp.c:5554 Auto Changing port from 172.16.0.150:49198 to 10.1.1.1:49198
recv 903 bytes from udp/[172.16.0.150]:5063 at 16:48:54.507821:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.16.0.150:6090;rport=6090;branch=z9hG4bKDytKNrBp1aDrQ
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
From: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
To: <sip:0000100912345678 at 10.2.1.1>;tag=as5129a390
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 65160997 INVITE
User-Agent: bobPBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:0000100912345678 at 10.2.1.1:5060>
Content-Type: application/sdp
Content-Length: 282
v=0
o=root 27411 27412 IN IP4 172.16.0.150
s=session
c=IN IP4 172.16.0.150
t=0 0
m=audio 49198 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
a=nortpproxy:yes
------------------------------------------------------------------------
2014-09-17 16:48:54.505900 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:54.505900 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:54.526003 [DEBUG] sofia.c:6229 Channel sofia/internal/0000100912345678 entering state [completing][200]
2014-09-17 16:48:54.526003 [DEBUG] sofia.c:6239 Remote SDP:
v=0
o=root 27411 27412 IN IP4 172.16.0.150
s=session
c=IN IP4 172.16.0.150
t=0 0
m=audio 49198 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=nortpproxy:yes
send 538 bytes to udp/[172.16.0.150]:5063 at 16:48:54.528674:
------------------------------------------------------------------------
ACK sip:0000100912345678 at 10.2.1.1:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.0.150:6090;rport;branch=z9hG4bKe7KcQKvSyK3aK
Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Max-Forwards: 70
From: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
To: <sip:0000100912345678 at 10.2.1.1>;tag=as5129a390
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 65160997 ACK
Contact: <sip:gw+bobspecial at 172.16.0.150:6090;transport=udp;gw=bobspecial>
Content-Length: 0
------------------------------------------------------------------------
2014-09-17 16:48:54.526003 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:54.526003 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:54.526003 [DEBUG] sofia.c:6229 Channel sofia/internal/0000100912345678 entering state [ready][200]
2014-09-17 16:48:54.545977 [DEBUG] switch_channel.c:3631 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:54.545977 [NOTICE] sofia.c:6996 Channel [sofia/internal/0000100912345678] has been answered
EXECUTE sofia/internal/0000100912345678 lua(mod_callmgr/on-bridge.lua)
2014-09-17 16:48:54.545977 [ERR] mod_lua.cpp:203 cannot open /home/kkhan/fsdevel/scripts/mod_callmgr/on-bridge.lua: No such file or directory
2014-09-17 16:48:54.545977 [DEBUG] switch_cpp.cpp:1056 sofia/internal/0000100912345678 destroy/unlink session from object
2014-09-17 16:48:54.545977 [DEBUG] switch_channel.c:3685 (sofia/internal/0000100912345678) Callstate Change EARLY -> ACTIVE
2014-09-17 16:48:54.545977 [DEBUG] mod_sofia.c:778 Local SDP sofia/internal/alice at fs.mydomain.com:
v=0
o=FreeSWITCH 1410969268 1410969270 IN IP4 10.1.1.1
s=FreeSWITCH
c=IN IP4 10.1.1.1
t=0 0
a=msid-semantic: WMS RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
m=audio 24858 UDP/TLS/RTP/SAVPF 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=sendrecv
a=fingerprint:sha-256 91:E9:37:67:75:A4:28:C0:E6:DB:6B:2B:B7:A6:5E:5C:B5:2D:99:89:CF:26:44:FA:D0:82:A0:9C:F2:A2:84:94
a=rtcp-mux
a=rtcp:24858 IN IP4 10.1.1.1
a=ssrc:271344810 cname:nx21mWJyvjncyrD8
a=ssrc:271344810 msid:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA a0
a=ssrc:271344810 mslabel:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
a=ssrc:271344810 label:RDPCOY3SmIJZRpeBKriKXkk9aND4STSAa0
a=ice-ufrag:JMJwWUvXyYRgIAHV
a=ice-pwd:XAN9nnyIxMLV4fUDRtZEdlrB
a=candidate:6961800946 1 udp 659136 10.1.1.1 24858 typ host generation 0
2014-09-17 16:48:54.545977 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:54.545977 [NOTICE] switch_ivr_bridge.c:496 Channel [sofia/internal/alice at fs.mydomain.com] has been answered
send 2017 bytes to udp/[172.16.0.150]:5063 at 16:48:54.553616:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK22c.2784592c8ddaf1dddc7bcb9bbcbecd6a.0;received=172.16.0.150
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKJtOEBT8qZTFStRrzMZcGKo1Tq8iXUdFm;rport=64649
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>;tag=99eQB5Zae5cee
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10770 INVITE
Contact: <sip:+12345678 at 172.16.0.150:6090;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~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: 799
X-DAL-UUID: 3a05956905ca41e2b43170968d44398e
Remote-Party-ID: "Outbound Call" <sip:5063 at fs.mydomain.com>;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1410969268 1410969269 IN IP4 10.1.1.1
s=FreeSWITCH
c=IN IP4 10.1.1.1
t=0 0
a=msid-semantic: WMS RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
m=audio 24858 UDP/TLS/RTP/SAVPF 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=fingerprint:sha-256 91:E9:37:67:75:A4:28:C0:E6:DB:6B:2B:B7:A6:5E:5C:B5:2D:99:89:CF:26:44:FA:D0:82:A0:9C:F2:A2:84:94
a=rtcp-mux
a=rtcp:24858 IN IP4 10.1.1.1
a=ssrc:271344810 cname:nx21mWJyvjncyrD8
a=ssrc:271344810 msid:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA a0
a=ssrc:271344810 mslabel:RDPCOY3SmIJZRpeBKriKXkk9aND4STSA
a=ssrc:271344810 label:RDPCOY3SmIJZRpeBKriKXkk9aND4STSAa0
a=ice-ufrag:JMJwWUvXyYRgIAHV
a=ice-pwd:XAN9nnyIxMLV4fUDRtZEdlrB
a=candidate:2725252931 1 udp 659136 10.1.1.1 24858 typ host generation 0
------------------------------------------------------------------------
2014-09-17 16:48:54.545977 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:54.545977 [DEBUG] switch_channel.c:3685 (sofia/internal/alice at fs.mydomain.com) Callstate Change EARLY -> ACTIVE
2014-09-17 16:48:54.545977 [DEBUG] sofia.c:6229 Channel sofia/internal/alice at fs.mydomain.com entering state [completed][200]
recv 1223 bytes from udp/[172.16.0.150]:5063 at 16:48:54.586519:
------------------------------------------------------------------------
ACK sip:+12345678 at 172.16.0.150:6090;transport=udp SIP/2.0
Record-Route: <sip:10.1.1.1:5063;transport=ws;lr=on>
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK22c.b4fd273e140b6bfb8c10132eb6625886.0
Via: SIP/2.0/WS df7jal23ls0d.invalid;received=10.1.1.2;branch=z9hG4bKsqO0MlTVFcWedViMF5yV;rport=64649
From: "Alice"<sip:alice at fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU
To: <sip:+12345678 at fs.mydomain.com>;tag=99eQB5Zae5cee
Contact: "Alice"<sip:alice at 10.1.1.2:64649;rtcweb-breaker=no;click2call=no;transport=ws>;+g.oma.sip-im;+sip.ice;language="en,fr";received="sip:10.1.1.2:64649;transport=WS"
Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32
CSeq: 10770 ACK
Content-Length: 0
Max-Forwards: 69
Proxy-Authorization: Digest username="alice",realm="fs.mydomain.com",nonce="4c15231c-896a-4131-b7c2-621ab8342e9a",uri="sip:+12345678 at 172.16.0.150:6090;transport=udp",response="975327290415140c922c22a1c4c00f88",algorithm=MD5,cnonce="8dabac05b6f0a365d085158868220703",qop=auth,nc=00000002
User-Agent: IM-client/OMA1.0 sipML5-v1.0.0.0
Organization: Dingaling.ca
Path: <sip:172.16.0.150:5063;lr>
------------------------------------------------------------------------
2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:48:54.585908 [DEBUG] sofia.c:6229 Channel sofia/internal/alice at fs.mydomain.com entering state [ready][200]
2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:969 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:969 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
recv 774 bytes from udp/[172.16.0.150]:5063 at 16:49:00.467309:
------------------------------------------------------------------------
BYE sip:gw+bobspecial at 172.16.0.150:6090;transport=udp;gw=bobspecial SIP/2.0
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Record-Route: <sip:10.1.1.1:5063;transport=udp;lr=on>
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK728.eb6d8a9209ac4e3ce276af87552fe9b7.0
Via: SIP/2.0/UDP 10.1.1.1:5063;rport=5063;branch=z9hG4bK728.5817c2e90986f57eeba11ed14bd3f311.0
Via: SIP/2.0/UDP 10.2.1.1:5060;rport=5060;branch=z9hG4bK11bbf59f
From: <sip:0000100912345678 at 10.2.1.1>;tag=as5129a390
To: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 102 BYE
User-Agent: bobPBX
Max-Forwards: 68
Content-Length: 0
Path: <sip:172.16.0.150:5063;lr>
Path: <sip:172.16.0.150:5063;lr>
------------------------------------------------------------------------
2014-09-17 16:49:00.465894 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:49:00.485939 [NOTICE] sofia.c:926 Hangup sofia/internal/0000100912345678 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2014-09-17 16:49:00.485939 [DEBUG] switch_channel.c:3218 Send signal sofia/internal/0000100912345678 [KILL]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
send 725 bytes to udp/[172.16.0.150]:5063 at 16:49:00.487587:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.1.1.1:5063;branch=z9hG4bK728.eb6d8a9209ac4e3ce276af87552fe9b7.0;received=172.16.0.150
Via: SIP/2.0/UDP 10.1.1.1:5063;rport=5063;branch=z9hG4bK728.5817c2e90986f57eeba11ed14bd3f311.0
Via: SIP/2.0/UDP 10.2.1.1:5060;rport=5060;branch=z9hG4bK11bbf59f
From: <sip:0000100912345678 at 10.2.1.1>;tag=as5129a390
To: "Alice" <sip:bob at 10.2.1.1>;tag=aK8FD0geBe30S
Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2
CSeq: 102 BYE
User-Agent: FreeSWITCH-mod_sofia/1.4.6+git~20140603T193516Z~9479729340~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Content-Length: 0
------------------------------------------------------------------------
2014-09-17 16:49:00.485939 [DEBUG] switch_ivr_bridge.c:659 BRIDGE THREAD DONE [sofia/internal/0000100912345678]
2014-09-17 16:49:00.485939 [DEBUG] switch_ivr_bridge.c:689 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:536 (sofia/internal/0000100912345678) State EXCHANGE_MEDIA going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/0000100912345678) Running State Change CS_HANGUP
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:733 (sofia/internal/0000100912345678) Callstate Change ACTIVE -> HANGUP
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/0000100912345678) State HANGUP
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:413 Channel sofia/internal/0000100912345678 hanging up, cause: NORMAL_CLEARING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:58 sofia/internal/0000100912345678 Standard HANGUP, cause: NORMAL_CLEARING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/0000100912345678) State HANGUP going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:502 (sofia/internal/0000100912345678) State Change CS_HANGUP -> CS_REPORTING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/0000100912345678) Running State Change CS_REPORTING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:821 (sofia/internal/0000100912345678) State REPORTING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:102 sofia/internal/0000100912345678 Standard REPORTING, cause: NORMAL_CLEARING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:821 (sofia/internal/0000100912345678) State REPORTING going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:496 (sofia/internal/0000100912345678) State Change CS_REPORTING -> CS_DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1614 Session 104 (sofia/internal/0000100912345678) Locked, Waiting on external entities
2014-09-17 16:49:00.485939 [DEBUG] switch_ivr_bridge.c:578 sofia/internal/0000100912345678 ending bridge by request from write function
2014-09-17 16:49:00.485939 [DEBUG] switch_ivr_bridge.c:659 BRIDGE THREAD DONE [sofia/internal/alice at fs.mydomain.com]
2014-09-17 16:49:00.485939 [DEBUG] switch_ivr_bridge.c:689 Send signal sofia/internal/0000100912345678 [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:907 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:49:00.485939 [NOTICE] switch_core_session.c:1632 Session 104 (sofia/internal/0000100912345678) Ended
2014-09-17 16:49:00.485939 [NOTICE] switch_core_session.c:1636 Close Channel sofia/internal/0000100912345678 [CS_DESTROY]
2014-09-17 16:49:00.485939 [NOTICE] switch_core_state_machine.c:313 sofia/internal/alice at fs.mydomain.com has executed the last dialplan instruction, hanging up.
2014-09-17 16:49:00.485939 [NOTICE] switch_core_state_machine.c:315 Hangup sofia/internal/alice at fs.mydomain.com [CS_EXECUTE] [NORMAL_CLEARING]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/0000100912345678) Running State Change CS_DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:634 (sofia/internal/0000100912345678) State DESTROY
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:323 sofia/internal/0000100912345678 SOFIA DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_channel.c:3218 Send signal sofia/internal/alice at fs.mydomain.com [KILL]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:109 sofia/internal/0000100912345678 Standard DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:634 (sofia/internal/0000100912345678) State DESTROY going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:533 (sofia/internal/alice at fs.mydomain.com) State EXECUTE going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_HANGUP
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:733 (sofia/internal/alice at fs.mydomain.com) Callstate Change ACTIVE -> HANGUP
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/alice at fs.mydomain.com) State HANGUP
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:407 sofia/internal/alice at fs.mydomain.com Overriding SIP cause 480 with 200 from the other leg
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:413 Channel sofia/internal/alice at fs.mydomain.com hanging up, cause: NORMAL_CLEARING
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/internal/alice at fs.mydomain.com
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:58 sofia/internal/alice at fs.mydomain.com Standard HANGUP, cause: NORMAL_CLEARING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/alice at fs.mydomain.com) State HANGUP going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:502 (sofia/internal/alice at fs.mydomain.com) State Change CS_HANGUP -> CS_REPORTING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_REPORTING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:821 (sofia/internal/alice at fs.mydomain.com) State REPORTING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:102 sofia/internal/alice at fs.mydomain.com Standard REPORTING, cause: NORMAL_CLEARING
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:821 (sofia/internal/alice at fs.mydomain.com) State REPORTING going to sleep
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:496 (sofia/internal/alice at fs.mydomain.com) State Change CS_REPORTING -> CS_DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1387 Send signal sofia/internal/alice at fs.mydomain.com [BREAK]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1614 Session 103 (sofia/internal/alice at fs.mydomain.com) Locked, Waiting on external entities
2014-09-17 16:49:00.485939 [NOTICE] switch_core_session.c:1632 Session 103 (sofia/internal/alice at fs.mydomain.com) Ended
2014-09-17 16:49:00.485939 [NOTICE] switch_core_session.c:1636 Close Channel sofia/internal/alice at fs.mydomain.com [CS_DESTROY]
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/alice at fs.mydomain.com) Running State Change CS_DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:634 (sofia/internal/alice at fs.mydomain.com) State DESTROY
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:323 sofia/internal/alice at fs.mydomain.com SOFIA DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:109 sofia/internal/alice at fs.mydomain.com Standard DESTROY
2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:634 (sofia/internal/alice at fs.mydomain.com) State DESTROY going to sleep
From: freeswitch-users-request at lists.freeswitch.org
Subject: FreeSWITCH-users Digest, Vol 99, Issue 146
To: freeswitch-users at lists.freeswitch.org
Date: Thu, 18 Sep 2014 02:29:41 +0400
Send FreeSWITCH-users mailing list submissions to
freeswitch-users at lists.freeswitch.org
To subscribe or unsubscribe via the World Wide Web, visit
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
or, via email, send a message with subject or body 'help' to
freeswitch-users-request at lists.freeswitch.org
You can reach the person managing the list at
freeswitch-users-owner at lists.freeswitch.org
When replying, please edit your Subject line so it is more specific
than "Re: Contents of FreeSWITCH-users digest..."
--Forwarded Message Attachment--
From: wstephen80 at gmail.com
To: freeswitch-users at lists.freeswitch.org
Date: Wed, 17 Sep 2014 22:58:23 +0200
Subject: Re: [Freeswitch-users] Call released with a 200 OK
I have a trace of one leg only I can try to capture both legs.But a 200 OK with a Reason header is a valid SIP message (below 200 OK forwarded by FreeSWITCH) ?
Frame 5: 957 bytes on wire (7656 bits), 957 bytes captured (7656 bits)Ethernet II, Src: Hewlett-_f3:e9:2c (3c:d9:2b:f3:e9:2c), Dst: JuniperN_f6:ce:27 (78:19:f7:f6:ce:27)Internet Protocol Version 4, Src: FreeSWITCH_IP (FreeSWITCH_IP), Dst: CUSTOMER_IP (CUSTOMER_IP)User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)Session Initiation Protocol (200) Status-Line: SIP/2.0 200 OK Message Header Via: SIP/2.0/UDP CUSTOMER_IP:5060;branch=z9hG4bK00E0F510095D15ED848E0A88725A Max-Forwards: 63 From: <sip:cg at FreeSWITCH_IP>;tag=00E0F510095D15ED848E7A60E97C To: <sip:cd at FreeSWITCH_IP>;tag=5881vaN1reajB Call-ID: ae8f80003582-5417017f-60871148-3ad46cc0-745bf31 at 127.0.0.1 CSeq: 14398 INVITE Contact: <sip:cd at FreeSWITCH_IP:5060;transport=udp> User-Agent: FS_1.2 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Type: application/sdp Content-Disposition: session Content-Length: 217 Message Body
On Wed, Sep 17, 2014 at 10:09 PM, Steven Ayre <steveayre at gmail.com> wrote:
Can you post the sip trace for the call (all legs)
On 17 September 2014 19:54, Stephen Wilde <wstephen80 at gmail.com> wrote:
Anyone can help me on that?
Stephen
On Tue, Sep 16, 2014 at 9:58 PM, Stephen Wilde <wstephen80 at gmail.com> wrote:
I have a strange issue: some calls are dropped with a 200 OK containing the "Reason" header.
Is this valid?The message flow is:
CUSTOMER ---- FS
INVITE ->
<- 100 Trying <- 180 Ringing <- 200 OK (containing the Reason Header)
ACK ->
after some seconds...
BYE ->BYE ->BYE ->BYE ->BYE ->
The 200 OK sent by FreeSwitch contain a "Reason Header":
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
And the call seems dropped and not connected in FreeSWITCH.For the customer side the call seems connected with 200 OK (the customer ignore the Reason).After some seconds, the customer try to disconnect the call with BYE but these messages are ignored by Freeswitch because the call was been already dropped.
It's valid the Reason inside the 200 OK? It's possible that this 200 OK has been forwarded by Freeswitch from the outbound leg.Any advice for that?
Stephen
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting at freeswitch.org
http://www.freeswitchsolutions.com
Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.cluecon.com
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting at freeswitch.org
http://www.freeswitchsolutions.com
Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.cluecon.com
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
--Forwarded Message Attachment--
From: steveayre at gmail.com
To: freeswitch-users at lists.freeswitch.org
Date: Wed, 17 Sep 2014 23:28:37 +0100
Subject: Re: [Freeswitch-users] Call released with a 200 OK
rfc3326 - I believe it's valid in any packet, you can potentially have a Reason passed back before the end of the call.
It's the BYE that's hanging up the call not the 200 OK, but that could be an interop problem where a device doesn't expect the Reason in the 200 OK.
On 17 September 2014 21:58, Stephen Wilde <wstephen80 at gmail.com> wrote:
I have a trace of one leg only I can try to capture both legs.But a 200 OK with a Reason header is a valid SIP message (below 200 OK forwarded by FreeSWITCH) ?
Frame 5: 957 bytes on wire (7656 bits), 957 bytes captured (7656 bits)Ethernet II, Src: Hewlett-_f3:e9:2c (3c:d9:2b:f3:e9:2c), Dst: JuniperN_f6:ce:27 (78:19:f7:f6:ce:27)Internet Protocol Version 4, Src: FreeSWITCH_IP (FreeSWITCH_IP), Dst: CUSTOMER_IP (CUSTOMER_IP)User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)Session Initiation Protocol (200) Status-Line: SIP/2.0 200 OK Message Header Via: SIP/2.0/UDP CUSTOMER_IP:5060;branch=z9hG4bK00E0F510095D15ED848E0A88725A Max-Forwards: 63 From: <sip:cg at FreeSWITCH_IP>;tag=00E0F510095D15ED848E7A60E97C To: <sip:cd at FreeSWITCH_IP>;tag=5881vaN1reajB Call-ID: ae8f80003582-5417017f-60871148-3ad46cc0-745bf31 at 127.0.0.1 CSeq: 14398 INVITE Contact: <sip:cd at FreeSWITCH_IP:5060;transport=udp> User-Agent: FS_1.2 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Type: application/sdp Content-Disposition: session Content-Length: 217 Message Body
On Wed, Sep 17, 2014 at 10:09 PM, Steven Ayre <steveayre at gmail.com> wrote:
Can you post the sip trace for the call (all legs)
On 17 September 2014 19:54, Stephen Wilde <wstephen80 at gmail.com> wrote:
Anyone can help me on that?
Stephen
On Tue, Sep 16, 2014 at 9:58 PM, Stephen Wilde <wstephen80 at gmail.com> wrote:
I have a strange issue: some calls are dropped with a 200 OK containing the "Reason" header.
Is this valid?The message flow is:
CUSTOMER ---- FS
INVITE ->
<- 100 Trying <- 180 Ringing <- 200 OK (containing the Reason Header)
ACK ->
after some seconds...
BYE ->BYE ->BYE ->BYE ->BYE ->
The 200 OK sent by FreeSwitch contain a "Reason Header":
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
And the call seems dropped and not connected in FreeSWITCH.For the customer side the call seems connected with 200 OK (the customer ignore the Reason).After some seconds, the customer try to disconnect the call with BYE but these messages are ignored by Freeswitch because the call was been already dropped.
It's valid the Reason inside the 200 OK? It's possible that this 200 OK has been forwarded by Freeswitch from the outbound leg.Any advice for that?
Stephen
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting at freeswitch.org
http://www.freeswitchsolutions.com
Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.cluecon.com
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting at freeswitch.org
http://www.freeswitchsolutions.com
Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.cluecon.com
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting at freeswitch.org
http://www.freeswitchsolutions.com
Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.cluecon.com
FreeSWITCH-users mailing list
FreeSWITCH-users at lists.freeswitch.org
http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
http://www.freeswitch.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140918/988305aa/attachment-0001.html
Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users
mailing list