Re: [Freeswitch-users] FreeSWITCH not sending BYE
I checked the sofia debug. Didnt get anything interesting. Is there some other reason why it might be happening ? From: freeswitch-users-request@lists.freeswitch.org Subject: FreeSWITCH-users Digest, Vol 99, Issue 162 To: freeswitch-users@lists.freeswitch.org Date: Fri, 19 Sep 2014 00:13:50 +0400 Send FreeSWITCH-users mailing list submissions to freeswitch-users@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@lists.freeswitch.org You can reach the person managing the list at freeswitch-users-owner@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: steveayre@gmail.com To: freeswitch-users@lists.freeswitch.org Date: Thu, 18 Sep 2014 21:12:48 +0100 Subject: Re: [Freeswitch-users] FreeSWITCH not sending BYE Turn on the sofia stack debugging - perhaps that'll show an error within the stack where the stack is told to send bye but fails to do so. On 18 September 2014 17:52, Kamrul Khan <dodul@live.com> wrote: Hi,As you can see from the trace all the other packets are passing fine. Its just the BYE message thats not being sent. I just found the below line from my console log:2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/internal/alice@fs.mydomain.com So, the log says its sending BYE, but in reality it sends nothing. Any idea whats happening? please help. --Forwarded Message Attachment-- From: mike@jerris.com To: freeswitch-users@lists.freeswitch.org Date: Wed, 17 Sep 2014 21:32:03 -0400 Subject: Re: [Freeswitch-users] FreeSWITCH not sending BYE something is wrong here... all of the sip packets are coming from and going to the IP address of the freeswitch box? On Sep 17, 2014, at 7:06 PM, Kamrul Khan <dodul@live.com> wrote: 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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com> Contact: "Alice"<sip:alice@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:42.945889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:42.945889 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice@fs.mydomain.com) Running State Change CS_NEW 2014-09-17 16:48:42.945889 [DEBUG] sofia.c:8367 sofia/internal/alice@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com> Contact: "Alice"<sip:alice@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:42.985935 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.005913 [DEBUG] sofia.c:8367 sofia/internal/alice@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice@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@fs.mydomain.com) State INIT 2014-09-17 16:48:43.285898 [DEBUG] mod_sofia.c:87 sofia/internal/alice@fs.mydomain.com SOFIA INIT 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:40 sofia/internal/alice@fs.mydomain.com Standard INIT 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/alice@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:510 (sofia/internal/alice@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@fs.mydomain.com) Running State Change CS_ROUTING 2014-09-17 16:48:43.285898 [DEBUG] switch_channel.c:2180 (sofia/internal/alice@fs.mydomain.com) Callstate Change DOWN -> RINGING 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:526 (sofia/internal/alice@fs.mydomain.com) State ROUTING 2014-09-17 16:48:43.285898 [DEBUG] mod_sofia.c:123 sofia/internal/alice@fs.mydomain.com SOFIA ROUTING 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:164 sofia/internal/alice@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@fs.mydomain.com parsing [dal-ingress->3a05956905ca41e2b43170968d44398e] continue=false Dialplan: sofia/internal/alice@fs.mydomain.com Absolute Condition [3a05956905ca41e2b43170968d44398e] Dialplan: sofia/internal/alice@fs.mydomain.com Action export(dal-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(dal-Language=en) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(effective_caller_id_number=17783315100) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(effective_caller_id_name=Alice) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_rh_X-DAL-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_ph_X-DAL-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_bye_h_X-DAL-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Time-Limit=118) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Time-Limit-Bye=you-have-reached-the-time-limit-for-this-call) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Time-Limit-Warnings=60@aleg:you-have-one-minute-remaining,300@aleg:you-have-five-minutes-remaining-for-this-call) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(nolocal:execute_on_answer=lua mod_callmgr/on-bridge.lua) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Report-URL=http://todo-kkhan.dlcworldwide.com/index.php/internal/) Dialplan: sofia/internal/alice@fs.mydomain.com Action event(Event-Subclass=callmgr::call_uuid,Event-Name=CUSTOM) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_h_Route=<sip:172.16.0.150:5063>) Dialplan: sofia/internal/alice@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:526 (sofia/internal/alice@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@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@fs.mydomain.com) State EXECUTE 2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:178 sofia/internal/alice@fs.mydomain.com SOFIA EXECUTE 2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:256 sofia/internal/alice@fs.mydomain.com Standard EXECUTE EXECUTE sofia/internal/alice@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@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@fs.mydomain.com set(effective_caller_id_number=17783315100) 2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice@fs.mydomain.com SET [effective_caller_id_number]=[17783315100] EXECUTE sofia/internal/alice@fs.mydomain.com set(effective_caller_id_name=Alice) 2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice@fs.mydomain.com SET [effective_caller_id_name]=[Alice] EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_rh_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e] EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_ph_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e] EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_bye_h_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e] EXECUTE sofia/internal/alice@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@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@fs.mydomain.com export(DAL-Time-Limit-Warnings=60@aleg:you-have-one-minute-remaining,300@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@aleg:you-have-one-minute-remaining,300@aleg:you-have-five-minutes-remaining-for-this-call] EXECUTE sofia/internal/alice@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@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@fs.mydomain.com event(Event-Subclass=callmgr::call_uuid,Event-Name=CUSTOM) EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_h_Route]=[<sip:172.16.0.150:5063>] EXECUTE sofia/internal/alice@fs.mydomain.combridge(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@fs.mydomain.comEXPORTING[export_vars] [dal-UUID]=[3a05956905ca41e2b43170968d44398e] to event 2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice@fs.mydomain.comEXPORTING[export_vars] [dal-Language]=[en] to event 2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice@fs.mydomain.comEXPORTING[export_vars] [DAL-Time-Limit]=[118] to event 2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice@fs.mydomain.comEXPORTING[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@fs.mydomain.comEXPORTING[export_vars] [DAL-Time-Limit-Warnings]=[60@aleg:you-have-one-minute-remaining,300@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@fs.mydomain.comEXPORTING[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@fs.mydomain.comEXPORTING[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@48000h@20i,PCMU@8000h@20i@64000b,PCMA@8000h@20i@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@10.2.1.1> Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2 CSeq: 65160997 INVITE Contact: <sip:gw+bobspecial@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@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@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@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 onsofia/internal/alice@fs.mydomain.com to PCMU@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@fs.mydomain.comPCMU/8000 20 ms 160 samples 64000 bits 2014-09-17 16:48:46.225921 [DEBUG] switch_core_codec.c:111 sofia/internal/alice@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@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@fs.mydomain.com! 2014-09-17 16:48:46.225921 [DEBUG] switch_channel.c:3395 (sofia/internal/alice@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@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com>;tag=99eQB5Zae5cee Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32 CSeq: 10770 INVITE Contact: <sip:+12345678@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@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@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@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@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@10.2.1.1>;tag=as5129a390 Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2 CSeq: 65160997 ACK Contact: <sip:gw+bobspecial@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.545977 [NOTICE] switch_ivr_bridge.c:496 Channel [sofia/internal/alice@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com>;tag=99eQB5Zae5cee Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32 CSeq: 10770 INVITE Contact: <sip:+12345678@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.545977 [DEBUG] switch_channel.c:3685 (sofia/internal/alice@fs.mydomain.com) Callstate Change EARLY -> ACTIVE 2014-09-17 16:48:54.545977 [DEBUG] sofia.c:6229 Channel sofia/internal/alice@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com>;tag=99eQB5Zae5cee Contact: "Alice"<sip:alice@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.585908 [DEBUG] sofia.c:6229 Channel sofia/internal/alice@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@fs.mydomain.com[BREAK] recv 774 bytes from udp/[172.16.0.150]:5063 at 16:49:00.467309: ------------------------------------------------------------------------ BYE sip:gw+bobspecial@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@10.2.1.1>;tag=as5129a390 To: "Alice" <sip:bob@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@10.2.1.1>;tag=as5129a390 To: "Alice" <sip:bob@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@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@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@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@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:533 (sofia/internal/alice@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@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@fs.mydomain.com) Callstate Change ACTIVE -> HANGUP 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/alice@fs.mydomain.com) State HANGUP 2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:407 sofia/internal/alice@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@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@fs.mydomain.com 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:58 sofia/internal/alice@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/alice@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@fs.mydomain.com) State REPORTING 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:102 sofia/internal/alice@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1614 Session 103 (sofia/internal/alice@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@fs.mydomain.com) Ended 2014-09-17 16:49:00.485939 [NOTICE] switch_core_session.c:1636 Close Channel sofia/internal/alice@fs.mydomain.com[CS_DESTROY] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:624 (sofia/internal/alice@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@fs.mydomain.com) State DESTROY 2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:323 sofia/internal/alice@fs.mydomain.com SOFIA DESTROY 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:109 sofia/internal/alice@fs.mydomain.com Standard DESTROY 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:634 (sofia/internal/alice@fs.mydomain.com) State DESTROY going to sleep From: freeswitch-users-request@lists.freeswitch.org Subject: FreeSWITCH-users Digest, Vol 99, Issue 146 To: freeswitch-users@lists.freeswitch.org Date: Thu, 18 Sep 2014 02:29:41 +0400 Send FreeSWITCH-users mailing list submissions to freeswitch-users@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@lists.freeswitch.org You can reach the person managing the list at freeswitch-users-owner@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@gmail.com To: freeswitch-users@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@FreeSWITCH_IP>;tag=00E0F510095D15ED848E7A60E97C To: <sip:cd@FreeSWITCH_IP>;tag=5881vaN1reajB Call-ID: ae8f80003582-5417017f-60871148-3ad46cc0-745bf31@127.0.0.1 CSeq: 14398 INVITE Contact: <sip:cd@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@gmail.com> wrote: Can you post the sip trace for the call (all legs) On 17 September 2014 19:54, Stephen Wilde <wstephen80@gmail.com> wrote: Anyone can help me on that? Stephen On Tue, Sep 16, 2014 at 9:58 PM, Stephen Wilde <wstephen80@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@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@gmail.com To: freeswitch-users@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@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@FreeSWITCH_IP>;tag=00E0F510095D15ED848E7A60E97C To: <sip:cd@FreeSWITCH_IP>;tag=5881vaN1reajB Call-ID: ae8f80003582-5417017f-60871148-3ad46cc0-745bf31@127.0.0.1 CSeq: 14398 INVITE Contact: <sip:cd@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@gmail.com> wrote: Can you post the sip trace for the call (all legs) On 17 September 2014 19:54, Stephen Wilde <wstephen80@gmail.com> wrote: Anyone can help me on that? Stephen On Tue, Sep 16, 2014 at 9:58 PM, Stephen Wilde <wstephen80@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
sofia loglevel all 9 Is this local network or over the public internet? On Thu, Sep 18, 2014 at 4:52 PM, Kamrul Khan <dodul@live.com> wrote:
I checked the sofia debug. Didnt get anything interesting. Is there some other reason why it might be happening ?
From: freeswitch-users-request@lists.freeswitch.org Subject: FreeSWITCH-users Digest, Vol 99, Issue 162 To: freeswitch-users@lists.freeswitch.org Date: Fri, 19 Sep 2014 00:13:50 +0400
Send FreeSWITCH-users mailing list submissions to freeswitch-users@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@lists.freeswitch.org
You can reach the person managing the list at freeswitch-users-owner@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: steveayre@gmail.com To: freeswitch-users@lists.freeswitch.org Date: Thu, 18 Sep 2014 21:12:48 +0100 Subject: Re: [Freeswitch-users] FreeSWITCH not sending BYE
Turn on the sofia stack debugging - perhaps that'll show an error within the stack where the stack is told to send bye but fails to do so.
On 18 September 2014 17:52, Kamrul Khan <dodul@live.com> wrote:
Hi,
As you can see from the trace all the other packets are passing fine. Its just the BYE message thats not being sent. I just found the below line from my console log:
2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:465 Sending BYE to sofia/internal/alice@fs.mydomain.com So, the log says its sending BYE, but in reality it sends nothing. Any idea whats happening? please help.
--Forwarded Message Attachment-- From: mike@jerris.com To: freeswitch-users@lists.freeswitch.org Date: Wed, 17 Sep 2014 21:32:03 -0400 Subject: Re: [Freeswitch-users] FreeSWITCH not sending BYE
something is wrong here... all of the sip packets are coming from and going to the IP address of the freeswitch box?
On Sep 17, 2014, at 7:06 PM, Kamrul Khan <dodul@live.com> wrote:
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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com> Contact: "Alice"< sip:alice@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 <http://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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:42.945889 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:42.945889 [DEBUG] switch_core_state_machine.c:470 ( sofia/internal/alice@fs.mydomain.com) Running State Change CS_NEW 2014-09-17 16:48:42.945889 [DEBUG] sofia.c:8367 sofia/internal/alice@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com> Contact: "Alice"< sip:alice@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@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 <http://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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:42.985935 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.005913 [DEBUG] sofia.c:8367 sofia/internal/alice@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:470 ( sofia/internal/alice@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@fs.mydomain.com) State INIT 2014-09-17 16:48:43.285898 [DEBUG] mod_sofia.c:87 sofia/internal/alice@fs.mydomain.com SOFIA INIT 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:40 sofia/internal/alice@fs.mydomain.com Standard INIT 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:48 ( sofia/internal/alice@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:510 ( sofia/internal/alice@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@fs.mydomain.com) Running State Change CS_ROUTING 2014-09-17 16:48:43.285898 [DEBUG] switch_channel.c:2180 ( sofia/internal/alice@fs.mydomain.com) Callstate Change DOWN -> RINGING 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:526 ( sofia/internal/alice@fs.mydomain.com) State ROUTING 2014-09-17 16:48:43.285898 [DEBUG] mod_sofia.c:123 sofia/internal/alice@fs.mydomain.com SOFIA ROUTING 2014-09-17 16:48:43.285898 [DEBUG] switch_core_state_machine.c:164 sofia/internal/alice@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@fs.mydomain.com parsing [dal-ingress->3a05956905ca41e2b43170968d44398e] continue=false Dialplan: sofia/internal/alice@fs.mydomain.com Absolute Condition [3a05956905ca41e2b43170968d44398e] Dialplan: sofia/internal/alice@fs.mydomain.com Action export(dal-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(dal-Language=en) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(effective_caller_id_number=17783315100) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(effective_caller_id_name=Alice) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_rh_X-DAL-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_ph_X-DAL-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_bye_h_X-DAL-UUID=3a05956905ca41e2b43170968d44398e) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Time-Limit=118) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Time-Limit-Bye=you-have-reached-the-time-limit-for-this-call) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Time-Limit-Warnings=60@aleg :you-have-one-minute-remaining,300@aleg :you-have-five-minutes-remaining-for-this-call) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(nolocal:execute_on_answer=lua mod_callmgr/on-bridge.lua) Dialplan: sofia/internal/alice@fs.mydomain.com Action export(DAL-Report-URL= http://todo-kkhan.dlcworldwide.com/index.php/internal/) Dialplan: sofia/internal/alice@fs.mydomain.com Action event(Event-Subclass=callmgr::call_uuid,Event-Name=CUSTOM) Dialplan: sofia/internal/alice@fs.mydomain.com Action set(sip_h_Route=< sip:172.16.0.150:5063>) Dialplan: sofia/internal/alice@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:526 ( sofia/internal/alice@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@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@fs.mydomain.com) State EXECUTE 2014-09-17 16:48:43.705898 [DEBUG] mod_sofia.c:178 sofia/internal/alice@fs.mydomain.com SOFIA EXECUTE 2014-09-17 16:48:43.705898 [DEBUG] switch_core_state_machine.c:256 sofia/internal/alice@fs.mydomain.com Standard EXECUTE EXECUTE sofia/internal/alice@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@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@fs.mydomain.com set(effective_caller_id_number=17783315100) 2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice@fs.mydomain.com SET [effective_caller_id_number]=[17783315100] EXECUTE sofia/internal/alice@fs.mydomain.com set(effective_caller_id_name=Alice) 2014-09-17 16:48:43.705898 [DEBUG] mod_dptools.c:1435 sofia/internal/alice@fs.mydomain.com SET [effective_caller_id_name]=[Alice] EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_rh_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e] EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_ph_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e] EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_bye_h_X-DAL-UUID]=[3a05956905ca41e2b43170968d44398e] EXECUTE sofia/internal/alice@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@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@fs.mydomain.com export(DAL-Time-Limit-Warnings=60@aleg :you-have-one-minute-remaining,300@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@aleg :you-have-one-minute-remaining,300@aleg :you-have-five-minutes-remaining-for-this-call] EXECUTE sofia/internal/alice@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@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@fs.mydomain.com event(Event-Subclass=callmgr::call_uuid,Event-Name=CUSTOM) EXECUTE sofia/internal/alice@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@fs.mydomain.com SET [sip_h_Route]=[< sip:172.16.0.150:5063>] EXECUTE sofia/internal/alice@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@fs.mydomain.comEXPORTING[export_vars] [dal-UUID]=[3a05956905ca41e2b43170968d44398e] to event 2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice@fs.mydomain.comEXPORTING[export_vars] [dal-Language]=[en] to event 2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice@fs.mydomain.comEXPORTING[export_vars] [DAL-Time-Limit]=[118] to event 2014-09-17 16:48:43.705898 [DEBUG] switch_channel.c:1199 sofia/internal/alice@fs.mydomain.comEXPORTING[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@fs.mydomain.comEXPORTING[export_vars] [DAL-Time-Limit-Warnings]=[60@aleg:you-have-one-minute-remaining,300@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@fs.mydomain.comEXPORTING[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@fs.mydomain.comEXPORTING[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@48000h@20i,PCMU@8000h@20i@64000b ,PCMA@8000h@20i@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@10.2.1.1> Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2 CSeq: 65160997 INVITE Contact: < sip:gw+bobspecial@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@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@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@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 onsofia/internal/alice@fs.mydomain.com to PCMU@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@fs.mydomain.comPCMU/8000 20 ms 160 samples 64000 bits 2014-09-17 16:48:46.225921 [DEBUG] switch_core_codec.c:111 sofia/internal/alice@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@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@fs.mydomain.com! 2014-09-17 16:48:46.225921 [DEBUG] switch_channel.c:3395 ( sofia/internal/alice@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@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com>;tag=99eQB5Zae5cee Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32 CSeq: 10770 INVITE Contact: <sip:+12345678@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@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@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@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@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@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@10.2.1.1>;tag=aK8FD0geBe30S To: <sip:0000100912345678@10.2.1.1>;tag=as5129a390 Call-ID: 9e1e4217-b95f-1232-dcb8-0015e9bb72e2 CSeq: 65160997 ACK Contact: < sip:gw+bobspecial@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.545977 [NOTICE] switch_ivr_bridge.c:496 Channel [ sofia/internal/alice@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com>;tag=99eQB5Zae5cee Call-ID: cdff3f60-5133-6104-9f7a-f50b516b2f32 CSeq: 10770 INVITE Contact: <sip:+12345678@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.545977 [DEBUG] switch_channel.c:3685 ( sofia/internal/alice@fs.mydomain.com) Callstate Change EARLY -> ACTIVE 2014-09-17 16:48:54.545977 [DEBUG] sofia.c:6229 Channel sofia/internal/alice@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@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@fs.mydomain.com>;tag=tKWvsNl5oHT5STgFSpWU To: <sip:+12345678@fs.mydomain.com>;tag=99eQB5Zae5cee Contact: "Alice"< sip:alice@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@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 <http://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@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.585908 [DEBUG] switch_core_session.c:1052 Send signal sofia/internal/alice@fs.mydomain.com[BREAK] 2014-09-17 16:48:54.585908 [DEBUG] sofia.c:6229 Channel sofia/internal/alice@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@fs.mydomain.com[BREAK] recv 774 bytes from udp/[172.16.0.150]:5063 at 16:49:00.467309: ------------------------------------------------------------------------ BYE sip:gw+bobspecial@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@10.2.1.1>;tag=as5129a390 To: "Alice" <sip:bob@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@10.2.1.1>;tag=as5129a390 To: "Alice" <sip:bob@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@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@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@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@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:533 ( sofia/internal/alice@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@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@fs.mydomain.com) Callstate Change ACTIVE -> HANGUP 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:735 ( sofia/internal/alice@fs.mydomain.com) State HANGUP 2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:407 sofia/internal/alice@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@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@fs.mydomain.com 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:58 sofia/internal/alice@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:470 ( sofia/internal/alice@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@fs.mydomain.com) State REPORTING 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:102 sofia/internal/alice@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@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@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@fs.mydomain.com[BREAK] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_session.c:1614 Session 103 ( sofia/internal/alice@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@fs.mydomain.com) Ended 2014-09-17 16:49:00.485939 [NOTICE] switch_core_session.c:1636 Close Channel sofia/internal/alice@fs.mydomain.com[CS_DESTROY] 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:624 ( sofia/internal/alice@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@fs.mydomain.com) State DESTROY 2014-09-17 16:49:00.485939 [DEBUG] mod_sofia.c:323 sofia/internal/alice@fs.mydomain.com SOFIA DESTROY 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:109 sofia/internal/alice@fs.mydomain.com Standard DESTROY 2014-09-17 16:49:00.485939 [DEBUG] switch_core_state_machine.c:634 ( sofia/internal/alice@fs.mydomain.com) State DESTROY going to sleep
From: freeswitch-users-request@lists.freeswitch.org Subject: FreeSWITCH-users Digest, Vol 99, Issue 146 To: freeswitch-users@lists.freeswitch.org Date: Thu, 18 Sep 2014 02:29:41 +0400
Send FreeSWITCH-users mailing list submissions to freeswitch-users@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@lists.freeswitch.org
You can reach the person managing the list at freeswitch-users-owner@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@gmail.com To: freeswitch-users@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@FreeSWITCH_IP>;tag=00E0F510095D15ED848E7A60E97C To: <sip:cd@FreeSWITCH_IP>;tag=5881vaN1reajB Call-ID: ae8f80003582-5417017f-60871148-3ad46cc0-745bf31@127.0.0.1 CSeq: 14398 INVITE Contact: <sip:cd@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@gmail.com> wrote:
Can you post the sip trace for the call (all legs)
On 17 September 2014 19:54, Stephen Wilde <wstephen80@gmail.com> wrote:
Anyone can help me on that? Stephen
On Tue, Sep 16, 2014 at 9:58 PM, Stephen Wilde <wstephen80@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@gmail.com To: freeswitch-users@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@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@FreeSWITCH_IP>;tag=00E0F510095D15ED848E7A60E97C To: <sip:cd@FreeSWITCH_IP>;tag=5881vaN1reajB Call-ID: ae8f80003582-5417017f-60871148-3ad46cc0-745bf31@127.0.0.1 CSeq: 14398 INVITE Contact: <sip:cd@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@gmail.com> wrote:
Can you post the sip trace for the call (all legs)
On 17 September 2014 19:54, Stephen Wilde <wstephen80@gmail.com> wrote:
Anyone can help me on that? Stephen
On Tue, Sep 16, 2014 at 9:58 PM, Stephen Wilde <wstephen80@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- *Brian West* brian@freeswitch.org *Twitter: @FreeSWITCH , @briankwest* http://www.freeswitchbook.com http://www.freeswitchcookbook.com *T:*+19184209001 | *F:*+19184209002 | *M:*+1918424WEST (9378) *iNUM:*+883 5100 1420 9001 | *ISN:*410*543 | *Skype:*briankwest
participants (2)
-
Brian West
-
Kamrul Khan