Re: [Freeswitch-users] trans-coding is not working
no i want to transcode GSM with PCMA so i <param name="inbound-zrtp-passthru" value="false"/> <param name="inbound-late-negotiation" value="true"/> to enable late negotiation only for trans-coding. Regards Shahzad Bhatti ---------- Forwarded message ----------
From: Michael Jerris <mike@jerris.com> To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org> Cc: Date: Thu, 23 Jan 2014 08:28:04 -0500 Subject: Re: [Freeswitch-users] trans-coding is not working Your trying to transcode and play files to someone and at the same time use zrtp-passtrhough?
On Jan 23, 2014, at 6:51 AM, Shahzad Bhatti <shahzad.bhatti@g-r-v.com> wrote:
Hi Everybody, i want to call legB in a scnerio that i have "inbound-codec-prefs" value="GSM,PCMA,PCMU,G729" "outbound-codec-prefs" value="PCMA,PCMU,G729" so i change sip profile as <param name="inbound-zrtp-passthru" value="false"/> <param name="inbound-late-negotiation" value="true"/> then after *reload mod_sofia* i originate call to bLeg where on inbound i only offer GSM Codec and i think that GSM codec should trans code using PCMA but i got response [415] here is my cli log http://pastebin.freeswitch.org/21881
tell me how i can trans code and correct me if i am wrong;
Regards
Shahzad Bhatti
Am Freitag, den 24.01.2014, 16:48 +0500 schrieb Shahzad Bhatti:
no i want to transcode GSM with PCMA so i <param name="inbound-zrtp-passthru" value="false"/> <param name="inbound-late-negotiation" value="true"/> to enable late negotiation only for trans-coding.
Please try "inbound-late-negotiation=false" to negotiate both call legs independently. (see http://wiki.freeswitch.org/wiki/Codec_negotiation) -- David Dahlberg Fraunhofer FKIE, Dept. Communication Systems (KOM) | Tel: +49-228-9435-845 Fraunhoferstr. 20, 53343 Wachtberg, Germany | Fax: +49-228-856277
This isn’t required it will transcode I suspect possibly a misconfig. Can you paste bin another call? -- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED) On Jan 24, 2014, at 8:01 AM, Dahlberg, David <david.dahlberg@fkie.fraunhofer.de> wrote:
Please try "inbound-late-negotiation=false" to negotiate both call legs independently. (see http://wiki.freeswitch.org/wiki/Codec_negotiation)
i have the same problem. i am running a FS with the default config 1000 supports only PCMA and 1001 only PCMU (one client is blink, the other jitsi), the call between 1000 and 1001 doesnt work. as soon as i enable the same codecs on both clients, it works without any problem. thanks a lot for your help! best regards, thomas 2014/1/28 Brian West <brian@freeswitch.org>:
This isn't required it will transcode I suspect possibly a misconfig. Can you paste bin another call? -- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com
T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)
On Jan 24, 2014, at 8:01 AM, Dahlberg, David <david.dahlberg@fkie.fraunhofer.de> wrote:
Please try "inbound-late-negotiation=false" to negotiate both call legs independently. (see http://wiki.freeswitch.org/wiki/Codec_negotiation)
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.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
Logs, with sip trace on please. -- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED) On Jan 28, 2014, at 9:13 AM, thomas peterseil <thomas.peterseil@gmail.com> wrote:
i have the same problem. i am running a FS with the default config 1000 supports only PCMA and 1001 only PCMU (one client is blink, the other jitsi), the call between 1000 and 1001 doesnt work. as soon as i enable the same codecs on both clients, it works without any problem. thanks a lot for your help!
best regards, thomas
hello, here are the logs from the cli with sip trace on with this problem: -------------------- freeswitch@internal> recv 2305 bytes from udp/[192.168.5.10]:20842 at 16:53:06.430550: ------------------------------------------------------------------------ PUBLISH sip:1000@192.168.65.98 SIP/2.0 Via: SIP/2.0/UDP 192.168.129.229:2425;rport;branch=z9hG4bKPj18e288b0ce3340a59a0ce2d3134fe4c5 Max-Forwards: 70 From: "thomas" <sip:1000@192.168.65.98>;tag=00d8d7ddf78c4a3f9627c52a06e68272 To: "thomas" <sip:1000@192.168.65.98> Call-ID: 08af2532df5f4c058b66de677cb88f3a CSeq: 1 PUBLISH Event: presence Expires: 600 SIP-If-Match: FBwNeu9F User-Agent: Blink 0.6.0 (Windows) Content-Type: application/pidf+xml Content-Length: 1825 <?xml version='1.0' encoding='UTF-8'?> <presence xmlns:c="urn:ietf:params:xml:ns:pidf:cipid" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:agp-caps="urn:ag-projects:xml:ns:pidf:caps" xmlns:caps="urn:ietf:params:xml:ns:pidf:caps" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid" xmlns:agp-pidf="urn:ag-projects:xml:ns:pidf" xmlns="urn:ietf:params:xml:ns:pidf" entity="sip%3A1000%40192.168.65.98"><tuple id="SID-ef6d4e1c-bb74-4bd9-8c55-1aeda5750f99"><status><basic>open</basic><agp-pidf:extended>busy</agp-pidf:extended></status><caps:servcaps><caps:audio>true</caps:audio><caps:message>false</caps:message><caps:text>false</caps:text><agp-caps:file-transfer>false</agp-caps:file-transfer><agp-caps:screen-sharing-server>false</agp-caps:screen-sharing-server><agp-caps:screen-sharing-client>false</agp-caps:screen-sharing-client></caps:servcaps><c:display-name>thomas</c:display-name><agp-pidf:device-info id="ef6d4e1c-bb74-4bd9-8c55-1aeda5750f99"><agp-pidf:description>OPTI-10</agp-pidf:description><agp-pidf:user-agent>:user-agent><agp-pidf:time-offset>60</agp-pidf:time-offset></agp-pidf:device-info><rpid:user-input idle-threshold="600">active</rpid:user-input><dm:deviceID>ef6d4e1c-bb74-4bd9-8c55-1aeda5750f99</dm:deviceID><contact>sip%3A1000%40192.168.65.98</contact><note>On the phone</note><timestamp>2014-01-30T17:53:03.589000+01:00</timestamp></tuple><dm:person id="PID-3dadb95a5ce54f457c35c3c2a9ddf52a"><rpid:activities><rpid:busy/></rpid:activities><dm:timestamp>2014-01-30T17:53:03.589000+01:00</dm:timestamp></dm:person><dm:device id="DID-ef6d4e1c-bb74-4bd9-8c55-1aeda5750f99"><dm:deviceID>ef6d4e1c-bb74-4bd9-8c55-1aeda5750f99</dm:deviceID><dm:note>Blink 0.6.0 (Windows) at OPTI-10</dm:note><dm:timestamp>2014-01-30T17:53:03.589000+01:00</dm:timestamp></dm:device></presence> ------------------------------------------------------------------------ send 778 bytes to udp/[192.168.5.10]:20842 at 16:53:06.432299: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPj18e288b0ce3340a59a0ce2d3134fe4c5;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=00d8d7ddf78c4a3f9627c52a06e68272 To: "thomas" <sip:1000@192.168.65.98>;tag=2p634jB77Byac Call-ID: 08af2532df5f4c058b66de677cb88f3a CSeq: 1 PUBLISH Contact: <sip:192.168.65.98> Expires: 600 User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer SIP-ETag: yTJwnz2d Content-Length: 0 ------------------------------------------------------------------------ recv 828 bytes from udp/[192.168.5.10]:20842 at 16:53:06.446771: ------------------------------------------------------------------------ INVITE sip:1001@192.168.65.98 SIP/2.0 Via: SIP/2.0/UDP 192.168.129.229:2425;rport;branch=z9hG4bKPjdcf4691faf2f47248598a01604325727 Max-Forwards: 70 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98> Contact: <sip:49583627@192.168.129.229:2425> Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22405 INVITE Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER Supported: 100rel, replaces, norefersub, gruu User-Agent: Blink 0.6.0 (Windows) Content-Type: application/sdp Content-Length: 239 v=0 o=- 3600093183 3600093183 IN IP4 192.168.129.229 s=Blink 0.6.0 (Windows) c=IN IP4 192.168.129.229 t=0 0 m=audio 50040 RTP/AVP 8 96 a=rtcp:50041 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 a=sendrecv ------------------------------------------------------------------------ send 383 bytes to udp/[192.168.5.10]:20842 at 16:53:06.447052: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPjdcf4691faf2f47248598a01604325727;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98> Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22405 INVITE User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:06.442538 [NOTICE] switch_channel.c:1052 New Channel sofia/internal/1000@192.168.65.98 [505cd4ee-eb6f-4b1b-91e5-2988258e9410] 2014-01-30 17:53:06.442538 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.442538 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.442538 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@192.168.65.98) Running State Change CS_NEW 2014-01-30 17:53:06.442538 [DEBUG] sofia.c:7834 sofia/internal/1000@192.168.65.98 receiving invite from 192.168.5.10:20842 version: 1.2.18 -1 64bit 2014-01-30 17:53:06.442538 [DEBUG] sofia.c:7985 IP 192.168.5.10 Rejected by acl "domains". Falling back to Digest auth. send 883 bytes to udp/[192.168.5.10]:20842 at 16:53:06.447832: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPjdcf4691faf2f47248598a01604325727;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=3ZZv6Dva5mmXQ Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22405 INVITE User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="192.168.65.98", nonce="6e75dcd4-79e3-4562-97a4-c88fc292cd6f", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:06.442538 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.442538 [DEBUG] sofia.c:1794 detaching session 505cd4ee-eb6f-4b1b-91e5-2988258e9410 2014-01-30 17:53:06.442538 [DEBUG] switch_core_state_machine.c:434 (sofia/internal/1000@192.168.65.98) State NEW recv 391 bytes from udp/[192.168.5.10]:20842 at 16:53:06.452970: ------------------------------------------------------------------------ ACK sip:1001@192.168.65.98 SIP/2.0 Via: SIP/2.0/UDP 192.168.129.229:2425;rport;branch=z9hG4bKPjdcf4691faf2f47248598a01604325727 Max-Forwards: 70 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=3ZZv6Dva5mmXQ Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22405 ACK User-Agent: Blink 0.6.0 (Windows) Content-Length: 0 ------------------------------------------------------------------------ recv 1098 bytes from udp/[192.168.5.10]:20842 at 16:53:06.475581: ------------------------------------------------------------------------ INVITE sip:1001@192.168.65.98 SIP/2.0 Via: SIP/2.0/UDP 192.168.129.229:2425;rport;branch=z9hG4bKPjd2684561262d4d288280a129a7f9846c Max-Forwards: 70 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98> Contact: <sip:49583627@192.168.129.229:2425> Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22406 INVITE Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE, REFER Supported: 100rel, replaces, norefersub, gruu User-Agent: Blink 0.6.0 (Windows) Proxy-Authorization: Digest username="1000", realm="192.168.65.98", nonce="6e75dcd4-79e3-4562-97a4-c88fc292cd6f", uri="sip:1001@192.168.65.98", response="c388584cea57037857fa19d191927a33", algorithm=MD5, cnonce="4bffd2f3ec9944cf806aae69bb6d87e6", qop=auth, nc=00000001 Content-Type: application/sdp Content-Length: 239 v=0 o=- 3600093183 3600093183 IN IP4 192.168.129.229 s=Blink 0.6.0 (Windows) c=IN IP4 192.168.129.229 t=0 0 m=audio 50040 RTP/AVP 8 96 a=rtcp:50041 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 a=sendrecv ------------------------------------------------------------------------ send 383 bytes to udp/[192.168.5.10]:20842 at 16:53:06.475828: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPjd2684561262d4d288280a129a7f9846c;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98> Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22406 INVITE User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:06.463222 [DEBUG] sofia.c:1886 Re-attaching to session 505cd4ee-eb6f-4b1b-91e5-2988258e9410 2014-01-30 17:53:06.463222 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.463222 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] sofia.c:7834 sofia/internal/1000@192.168.65.98 receiving invite from 192.168.5.10:20842 version: 1.2.18 -1 64bit 2014-01-30 17:53:06.482481 [DEBUG] sofia.c:7985 IP 192.168.5.10 Rejected by acl "domains". Falling back to Digest auth. 2014-01-30 17:53:06.482481 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@192.168.65.98 entering state [received][100] 2014-01-30 17:53:06.482481 [DEBUG] sofia.c:5792 Remote SDP: v=0 o=- 3600093183 3600093183 IN IP4 192.168.129.229 s=Blink 0.6.0 (Windows) c=IN IP4 192.168.129.229 t=0 0 m=audio 50040 RTP/AVP 8 96 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 a=rtcp:50041 2014-01-30 17:53:06.482481 [DEBUG] sofia.c:6039 (sofia/internal/1000@192.168.65.98) State Change CS_NEW -> CS_INIT 2014-01-30 17:53:06.482481 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@192.168.65.98) Running State Change CS_INIT 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/1000@192.168.65.98) State INIT 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:87 sofia/internal/1000@192.168.65.98 SOFIA INIT 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:127 (sofia/internal/1000@192.168.65.98) State Change CS_INIT -> CS_ROUTING 2014-01-30 17:53:06.482481 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/1000@192.168.65.98) State INIT going to sleep 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@192.168.65.98) Running State Change CS_ROUTING 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:2165 (sofia/internal/1000@192.168.65.98) Callstate Change DOWN -> RINGING 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/1000@192.168.65.98) State ROUTING 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:150 sofia/internal/1000@192.168.65.98 SOFIA ROUTING 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:117 sofia/internal/1000@192.168.65.98 Standard ROUTING 2014-01-30 17:53:06.482481 [INFO] mod_dialplan_xml.c:558 Processing thomas <1000>->1001 in context default Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->unloop] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1000@192.168.65.98 Date/Time Match (PASS) [tod_example] break=on-false Dialplan: sofia/internal/1000@192.168.65.98 Action set(open=true) Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1000@192.168.65.98 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->redial] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->global] continue=true Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/1000@192.168.65.98 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=- 3600093183 3600093183 IN IP4 192.168.129.229 s=Blink 0.6.0 (Windows) c=IN IP4 192.168.129.229 t=0 0 m=audio 50040 RTP/AVP 8 96 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 a=rtcp:50041 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/1000@192.168.65.98 Absolute Condition [global] Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1000@192.168.65.98 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->call_return] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->del-group] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->add-group] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1000@192.168.65.98 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1000@192.168.65.98 Action export(dialed_extension=1001) Dialplan: sofia/internal/1000@192.168.65.98 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1000@192.168.65.98 Action bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1000@192.168.65.98 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1000@192.168.65.98 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1000@192.168.65.98 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1000@192.168.65.98 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1000@192.168.65.98 Action set(call_timeout=30) Dialplan: sofia/internal/1000@192.168.65.98 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1000@192.168.65.98 Action set(continue_on_fail=true) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1000@192.168.65.98 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1000@192.168.65.98 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1000@192.168.65.98 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1000@192.168.65.98 Action answer() Dialplan: sofia/internal/1000@192.168.65.98 Action sleep(1000) Dialplan: sofia/internal/1000@192.168.65.98 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/1000@192.168.65.98) State Change CS_ROUTING -> CS_EXECUTE 2014-01-30 17:53:06.482481 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/1000@192.168.65.98) State ROUTING going to sleep 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@192.168.65.98) Running State Change CS_EXECUTE 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@192.168.65.98) State EXECUTE 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:243 sofia/internal/1000@192.168.65.98 SOFIA EXECUTE 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:209 sofia/internal/1000@192.168.65.98 Standard EXECUTE EXECUTE sofia/internal/1000@192.168.65.98 set(open=true) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [open]=[true] EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-spymap/1000/505cd4ee-eb6f-4b1b-91e5-2988258e9410) EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-last_dial/1000/1001) EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-last_dial/global/505cd4ee-eb6f-4b1b-91e5-2988258e9410) EXECUTE sofia/internal/1000@192.168.65.98 export(RFC2822_DATE=Thu, 30 Jan 2014 17:53:06 +0100) 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:1244 EXPORT (export_vars) [RFC2822_DATE]=[Thu, 30 Jan 2014 17:53:06 +0100] EXECUTE sofia/internal/1000@192.168.65.98 export(dialed_extension=1001) 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:1244 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE sofia/internal/1000@192.168.65.98 bind_meta_app(1 b s execute_extension::dx XML features) 2014-01-30 17:53:06.482481 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/internal/1000@192.168.65.98 bind_meta_app(2 b s record_session::/var/lib/freeswitch/recordings/1000.2014-01-30-17-53-06.wav) 2014-01-30 17:53:06.482481 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *2 record_session::/var/lib/freeswitch/recordings/1000.2014-01-30-17-53-06.wav EXECUTE sofia/internal/1000@192.168.65.98 bind_meta_app(3 b s execute_extension::cf XML features) 2014-01-30 17:53:06.482481 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/internal/1000@192.168.65.98 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2014-01-30 17:53:06.482481 [INFO] switch_ivr_async.c:3701 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/internal/1000@192.168.65.98 set(ringback=%(2000,4000,440,480)) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1000@192.168.65.98 set(transfer_ringback=local_stream://moh) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1000@192.168.65.98 set(call_timeout=30) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [call_timeout]=[30] EXECUTE sofia/internal/1000@192.168.65.98 set(hangup_after_bridge=true) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1000@192.168.65.98 set(continue_on_fail=true) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-call_return/1001/1000) EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-last_dial_ext/1001/505cd4ee-eb6f-4b1b-91e5-2988258e9410) EXECUTE sofia/internal/1000@192.168.65.98 set(called_party_callgroup=techsupport) 2014-01-30 17:53:06.482481 [DEBUG] mod_dptools.c:1402 sofia/internal/1000@192.168.65.98 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-last_dial_ext/techsupport/505cd4ee-eb6f-4b1b-91e5-2988258e9410) EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-last_dial_ext/global/505cd4ee-eb6f-4b1b-91e5-2988258e9410) EXECUTE sofia/internal/1000@192.168.65.98 hash(insert/192.168.65.98-last_dial/techsupport/505cd4ee-eb6f-4b1b-91e5-2988258e9410) EXECUTE sofia/internal/1000@192.168.65.98 bridge(user/1001@192.168.65.98) 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:1198 sofia/internal/1000@192.168.65.98 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 30 Jan 2014 17:53:06 +0100] to event 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:1198 sofia/internal/1000@192.168.65.98 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2014-01-30 17:53:06.482481 [DEBUG] switch_ivr_originate.c:2061 Parsing global variables 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:1198 sofia/internal/1000@192.168.65.98 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 30 Jan 2014 17:53:06 +0100] to event 2014-01-30 17:53:06.482481 [DEBUG] switch_channel.c:1198 sofia/internal/1000@192.168.65.98 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2014-01-30 17:53:06.482481 [DEBUG] switch_ivr_originate.c:2061 Parsing global variables 2014-01-30 17:53:06.482481 [DEBUG] switch_event.c:1661 Parsing variable [sip_invite_domain]=[192.168.65.98] 2014-01-30 17:53:06.482481 [DEBUG] switch_event.c:1661 Parsing variable [presence_id]=[1001@192.168.65.98] 2014-01-30 17:53:06.482481 [NOTICE] switch_channel.c:1052 New Channel sofia/internal/sip:1001@192.168.65.124:3588 [cab230d1-27d2-443c-b531-81dac71c027c] 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:5231 (sofia/internal/sip:1001@192.168.65.124:3588) State Change CS_NEW -> CS_INIT 2014-01-30 17:53:06.482481 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:5301 [zrtp_passthru] Setting a-leg inherit_codec=true 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:5304 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMA@8000h@20i@64000b' 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1001@192.168.65.124:3588) Running State Change CS_INIT 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:1001@192.168.65.124:3588) State INIT 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1001@192.168.65.124:3588 SOFIA INIT 2014-01-30 17:53:06.482481 [DEBUG] sofia_glue.c:2738 sofia/internal/sip:1001@192.168.65.124:3588 sending invite version: 1.2.18 -1 64bit Local SDP: v=0 o=FreeSWITCH 1391074358 1391074359 IN IP4 192.168.65.98 s=FreeSWITCH c=IN IP4 192.168.65.98 t=0 0 m=audio 26428 RTP/AVP 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv send 1185 bytes to udp/[192.168.65.124]:3588 at 16:53:06.501475: ------------------------------------------------------------------------ INVITE sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917 SIP/2.0 Via: SIP/2.0/UDP 192.168.65.98;rport;branch=z9hG4bK27cZcy3ZyrZjj Max-Forwards: 69 From: "Extension 1000" <sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917> Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 INVITE Contact: <sip:mod_sofia@192.168.65.98:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 203 X-FS-Support: update_display,send_info Remote-Party-ID: "Extension 1000" <sip:1000@192.168.65.98>;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1391074358 1391074359 IN IP4 192.168.65.98 s=FreeSWITCH c=IN IP4 192.168.65.98 t=0 0 m=audio 26428 RTP/AVP 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-01-30 17:53:06.482481 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] mod_sofia.c:127 (sofia/internal/sip:1001@192.168.65.124:3588) State Change CS_INIT -> CS_ROUTING 2014-01-30 17:53:06.482481 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:06.482481 [DEBUG] switch_core_state_machine.c:455 (sofia/internal/sip:1001@192.168.65.124:3588) State INIT going to sleep 2014-01-30 17:53:06.502511 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1001@192.168.65.124:3588) Running State Change CS_ROUTING 2014-01-30 17:53:06.502511 [DEBUG] sofia.c:5779 Channel sofia/internal/sip:1001@192.168.65.124:3588 entering state [calling][0] 2014-01-30 17:53:06.502511 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:1001@192.168.65.124:3588) State ROUTING 2014-01-30 17:53:06.502511 [DEBUG] mod_sofia.c:150 sofia/internal/sip:1001@192.168.65.124:3588 SOFIA ROUTING 2014-01-30 17:53:06.502511 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1001@192.168.65.124:3588) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-01-30 17:53:06.502511 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:06.502511 [DEBUG] switch_core_state_machine.c:471 (sofia/internal/sip:1001@192.168.65.124:3588) State ROUTING going to sleep 2014-01-30 17:53:06.502511 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1001@192.168.65.124:3588) Running State Change CS_CONSUME_MEDIA 2014-01-30 17:53:06.502511 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:1001@192.168.65.124:3588) State CONSUME_MEDIA 2014-01-30 17:53:06.502511 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/sip:1001@192.168.65.124:3588) State CONSUME_MEDIA going to sleep recv 312 bytes from udp/[192.168.65.124]:3588 at 16:53:06.583154: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.65.98;rport=5060;branch=z9hG4bK27cZcy3ZyrZjj To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917> From: "Extension 1000" <sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 INVITE Content-Length: 0 ------------------------------------------------------------------------ recv 438 bytes from udp/[192.168.65.124]:3588 at 16:53:06.618431: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.65.98;rport=5060;branch=z9hG4bK27cZcy3ZyrZjj Contact: <sip:1001@192.168.65.124:3588> To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917>;tag=c5d7df41 From: "Extension 1000"<sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 INVITE User-Agent: X-Lite release 4.5.5 stamp 71241 Allow-Events: hold, talk Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:06.602764 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:06.602764 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:06.602764 [DEBUG] sofia.c:5779 Channel sofia/internal/sip:1001@192.168.65.124:3588 entering state [proceeding][180] 2014-01-30 17:53:06.602764 [NOTICE] sofia.c:5874 Ring-Ready sofia/internal/sip:1001@192.168.65.124:3588! 2014-01-30 17:53:06.602764 [DEBUG] switch_channel.c:3239 (sofia/internal/sip:1001@192.168.65.124:3588) Callstate Change DOWN -> RINGING 2014-01-30 17:53:06.622431 [INFO] switch_ivr_originate.c:1191 Sending early media 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:5276 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000] 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:5276 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:5276 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000] 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:3184 Set Codec sofia/internal/1000@192.168.65.98 PCMA/8000 20 ms 160 samples 64000 bits 2014-01-30 17:53:06.622431 [DEBUG] switch_core_codec.c:111 sofia/internal/1000@192.168.65.98 Original read codec set to PCMA:8 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:5445 Set 2833 dtmf send/recv payload to 96 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:3443 AUDIO RTP [sofia/internal/1000@192.168.65.98] 192.168.65.98 port 17870 -> 192.168.129.229 port 50040 codec: 8 ms: 20 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:2033 Starting timer [soft] 160 bytes per 20ms 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: START SESSION INITIALIZATION. sID=0. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: ZID=633061383431363264366363. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: Loading User's profile: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: allowclear: OFF 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: autosecure: ON 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: disclose_bit: OFF 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: signal. role: Unknown 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: TTL: 4294967295 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: SAS schemes: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 B256 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 B32 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: Ciphers: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 AES3 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 AES1 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: PK schemes: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 EC25 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 DH3k 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 DH2k 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 Mult 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATL: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 HS32 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: Hashes: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 S256 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: Session initialization - DONE. sID=0. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATTACH NEW STREAM to sID=0: 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: Empty slot was found - initializing new stream with ID=0. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: Preparing ZRTP Hello according to the Session profile. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp main]: ATTACH NEW STREAM - DONE. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp engine]: START STREAM ID=0 mode=CLEAR state=ACTIVE. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 CLEAR switching <ACTIVE> ---> <START>. 2014-01-30 17:53:06.622431 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42140 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:3710 Set 2833 dtmf send payload to 96 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:3716 Set 2833 dtmf receive payload to 96 2014-01-30 17:53:06.622431 [DEBUG] sofia_glue.c:3743 sofia/internal/1000@192.168.65.98 Set rtp dtmf delay to 40 2014-01-30 17:53:06.622431 [NOTICE] sofia_glue.c:4354 Pre-Answer sofia/internal/1000@192.168.65.98! 2014-01-30 17:53:06.622431 [DEBUG] switch_channel.c:3365 (sofia/internal/1000@192.168.65.98) Callstate Change RINGING -> EARLY 2014-01-30 17:53:06.622431 [DEBUG] mod_sofia.c:2885 Ring SDP: v=0 o=FreeSWITCH 1391082916 1391082917 IN IP4 192.168.65.98 s=FreeSWITCH c=IN IP4 192.168.65.98 t=0 0 m=audio 17870 RTP/AVP 8 96 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 a=sendrecv send 1169 bytes to udp/[192.168.5.10]:20842 at 16:53:06.630060: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPjd2684561262d4d288280a129a7f9846c;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=48rN88ce2XagK Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22406 INVITE Contact: <sip:1001@192.168.65.98:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 219 Remote-Party-ID: "1001" <sip:1001@192.168.65.98>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1391082916 1391082917 IN IP4 192.168.65.98 s=FreeSWITCH c=IN IP4 192.168.65.98 t=0 0 m=audio 17870 RTP/AVP 8 96 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-01-30 17:53:06.622431 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.622431 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@192.168.65.98 entering state [early][183] 2014-01-30 17:53:06.622431 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:06.622431 [DEBUG] switch_ivr_originate.c:1248 Raw Codec Activation Success L16@8000hz 1 channel 20ms 2014-01-30 17:53:06.622431 [DEBUG] switch_core_codec.c:219 sofia/internal/1000@192.168.65.98 Push codec L16:70 2014-01-30 17:53:06.622431 [DEBUG] switch_ivr_originate.c:1316 Play Ringback Tone [%(2000,4000,440,480)] 2014-01-30 17:53:06.682455 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42141 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:06.782481 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42142 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:06.882499 [INFO] switch_rtp.c:3730 Auto Changing port from 192.168.129.229:50040 to 192.168.5.10:53756 2014-01-30 17:53:06.982476 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42143 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:07.182473 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42144 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:07.383303 [DEBUG] switch_rtp.c:948 [ zrtp engine]: WARNING! HELLO have been resent 5 times without a response. Raising ZRTP_EVENT_NO_ZRTP_QUICK event. ID=0 2014-01-30 17:53:07.383303 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42145 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:07.582444 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42146 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:07.782471 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42147 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:08.002871 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42148 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:08.203152 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42149 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:08.402496 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42150 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:08.602538 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42151 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:08.803222 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42152 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:09.022481 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42153 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:09.222457 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42154 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:09.422492 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42155 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:09.622497 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42156 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:09.842523 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42157 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:10.043027 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42158 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:10.242993 [DEBUG] switch_rtp.c:948 [ zrtp utils]: Send <HELLO> ssrc=1427653722 seq=42159 size=144. Stream 0:CLEAR:START 2014-01-30 17:53:10.442488 [DEBUG] switch_rtp.c:948 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=0 2014-01-30 17:53:10.442488 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 CLEAR switching <START> ---> <NOZRTP>. recv 455 bytes from udp/[192.168.65.124]:3588 at 16:53:11.401846: ------------------------------------------------------------------------ SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/UDP 192.168.65.98;rport=5060;branch=z9hG4bK27cZcy3ZyrZjj To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917>;tag=c5d7df41 From: "Extension 1000"<sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 INVITE User-Agent: X-Lite release 4.5.5 stamp 71241 Warning: 305 devnull "SDP: Incompatible media format: no common codec" Content-Length: 0 ------------------------------------------------------------------------ send 384 bytes to udp/[192.168.65.124]:3588 at 16:53:11.403623: ------------------------------------------------------------------------ ACK sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917 SIP/2.0 Via: SIP/2.0/UDP 192.168.65.98;rport;branch=z9hG4bK27cZcy3ZyrZjj Max-Forwards: 69 From: "Extension 1000" <sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917>;tag=c5d7df41 Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 ACK Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:11.407504 [DEBUG] sofia.c:5779 Channel sofia/internal/sip:1001@192.168.65.124:3588 entering state [terminated][488] 2014-01-30 17:53:11.407504 [NOTICE] sofia.c:6623 Hangup sofia/internal/sip:1001@192.168.65.124:3588 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION] 2014-01-30 17:53:11.407504 [DEBUG] switch_channel.c:3184 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [KILL] 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1001@192.168.65.124:3588) Running State Change CS_HANGUP 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:1001@192.168.65.124:3588) State HANGUP 2014-01-30 17:53:11.407504 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:1001@192.168.65.124:3588 hanging up, cause: INCOMPATIBLE_DESTINATION 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:1001@192.168.65.124:3588 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/sip:1001@192.168.65.124:3588) State HANGUP going to sleep 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:690 (sofia/internal/sip:1001@192.168.65.124:3588) Callstate Change RINGING -> HANGUP 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/sip:1001@192.168.65.124:3588) State Change CS_HANGUP -> CS_REPORTING 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/sip:1001@192.168.65.124:3588) Running State Change CS_REPORTING 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:762 (sofia/internal/sip:1001@192.168.65.124:3588) State REPORTING 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:1001@192.168.65.124:3588 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:762 (sofia/internal/sip:1001@192.168.65.124:3588) State REPORTING going to sleep 2014-01-30 17:53:11.407504 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/sip:1001@192.168.65.124:3588) State Change CS_REPORTING -> CS_DESTROY 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:1001@192.168.65.124:3588 [BREAK] 2014-01-30 17:53:11.407504 [DEBUG] switch_core_session.c:1559 Session 2 (sofia/internal/sip:1001@192.168.65.124:3588) Locked, Waiting on external entities 2014-01-30 17:53:11.424472 [DEBUG] switch_core_codec.c:244 sofia/internal/1000@192.168.65.98 Restore previous codec PCMA:8. 2014-01-30 17:53:11.424472 [DEBUG] switch_ivr_originate.c:3639 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION] 2014-01-30 17:53:11.424472 [NOTICE] switch_ivr_originate.c:2662 Cannot create outgoing channel of type [user] cause: [INCOMPATIBLE_DESTINATION] 2014-01-30 17:53:11.424472 [DEBUG] switch_ivr_originate.c:3639 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION] 2014-01-30 17:53:11.424472 [INFO] mod_dptools.c:3201 Originate Failed. Cause: INCOMPATIBLE_DESTINATION EXECUTE sofia/internal/1000@192.168.65.98 answer() 2014-01-30 17:53:11.424472 [DEBUG] mod_sofia.c:866 Local SDP sofia/internal/1000@192.168.65.98: v=0 o=FreeSWITCH 1391082916 1391082918 IN IP4 192.168.65.98 s=FreeSWITCH c=IN IP4 192.168.65.98 t=0 0 m=audio 17870 RTP/AVP 8 96 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 a=sendrecv send 1139 bytes to udp/[192.168.5.10]:20842 at 16:53:11.430754: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPjd2684561262d4d288280a129a7f9846c;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=48rN88ce2XagK Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22406 INVITE Contact: <sip:1001@192.168.65.98:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 219 Remote-Party-ID: "Outbound Call" <sip:1001@192.168.65.98>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1391082916 1391082917 IN IP4 192.168.65.98 s=FreeSWITCH c=IN IP4 192.168.65.98 t=0 0 m=audio 17870 RTP/AVP 8 96 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-01-30 17:53:11.424472 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:11.424472 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@192.168.65.98 entering state [completed][200] 2014-01-30 17:53:11.424472 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:11.424472 [NOTICE] mod_dptools.c:1225 Channel [sofia/internal/1000@192.168.65.98] has been answered 2014-01-30 17:53:11.424472 [DEBUG] switch_channel.c:3644 (sofia/internal/1000@192.168.65.98) Callstate Change EARLY -> ACTIVE EXECUTE sofia/internal/1000@192.168.65.98 sleep(1000) 2014-01-30 17:53:11.424472 [NOTICE] switch_core_session.c:1577 Session 2 (sofia/internal/sip:1001@192.168.65.124:3588) Ended 2014-01-30 17:53:11.424472 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/sip:1001@192.168.65.124:3588 [CS_DESTROY] 2014-01-30 17:53:11.424472 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/sip:1001@192.168.65.124:3588) Callstate Change HANGUP -> DOWN 2014-01-30 17:53:11.424472 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/sip:1001@192.168.65.124:3588) Running State Change CS_DESTROY 2014-01-30 17:53:11.424472 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:1001@192.168.65.124:3588) State DESTROY 2014-01-30 17:53:11.424472 [DEBUG] mod_sofia.c:399 sofia/internal/sip:1001@192.168.65.124:3588 SOFIA DESTROY 2014-01-30 17:53:11.424472 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:1001@192.168.65.124:3588 Standard DESTROY 2014-01-30 17:53:11.424472 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/sip:1001@192.168.65.124:3588) State DESTROY going to sleep recv 410 bytes from udp/[192.168.5.10]:20842 at 16:53:11.464680: ------------------------------------------------------------------------ ACK sip:1001@192.168.65.98:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.129.229:2425;rport;branch=z9hG4bKPjdd90edd2522045c79127fa96e72c6487 Max-Forwards: 70 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=48rN88ce2XagK Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22406 ACK User-Agent: Blink 0.6.0 (Windows) Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:11.464095 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:11.464095 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:11.464095 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:11.488073 [DEBUG] sofia.c:5779 Channel sofia/internal/1000@192.168.65.98 entering state [ready][200] EXECUTE sofia/internal/1000@192.168.65.98 bridge(loopback/app=voicemail:default 192.168.65.98 1001) 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:1765 (sofia/internal/1000@192.168.65.98) Callstate Change ACTIVE -> RING_WAIT 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:1198 sofia/internal/1000@192.168.65.98 EXPORTING[export_vars] [RFC2822_DATE]=[Thu, 30 Jan 2014 17:53:06 +0100] to event 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:1198 sofia/internal/1000@192.168.65.98 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2014-01-30 17:53:12.442539 [DEBUG] switch_ivr_originate.c:2061 Parsing global variables 2014-01-30 17:53:12.442539 [NOTICE] switch_channel.c:1052 New Channel loopback/app=voicemail:default 192.168.65.98 1001-a [0ec9cff0-d6ff-48f7-8cbe-4b18a663e7cb] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 192.168.65.98 1001-a setup codec PCMA/8000/20 2014-01-30 17:53:12.442539 [NOTICE] switch_channel.c:1050 Rename Channel loopback/app=voicemail:default 192.168.65.98 1001-a->loopback/voicemail-a [0ec9cff0-d6ff-48f7-8cbe-4b18a663e7cb] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:1158 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_INIT 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT 2014-01-30 17:53:12.442539 [NOTICE] switch_channel.c:1052 New Channel loopback/voicemail-b [89b050fa-b391-488f-882b-ca3607f1dabd] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec PCMA/8000/20 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:272 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:357 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-a) State INIT going to sleep 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_ROUTING 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:389 loopback/voicemail-a CHANNEL ROUTING 2014-01-30 17:53:12.442539 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-a) State ROUTING going to sleep 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:648 CHANNEL CONSUME_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:490 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_INIT 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:357 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:455 (loopback/voicemail-b) State INIT going to sleep 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_ROUTING 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:2165 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:389 loopback/voicemail-b CHANNEL ROUTING 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:408 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:471 (loopback/voicemail-b) State ROUTING going to sleep 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_EXECUTE 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:431 loopback/voicemail-b CHANNEL EXECUTE 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:209 loopback/voicemail-b Standard EXECUTE EXECUTE loopback/voicemail-b pre_answer() 2014-01-30 17:53:12.442539 [NOTICE] mod_loopback.c:945 Pre-Answer loopback/voicemail-a! 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:3361 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:3365 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:12.442539 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:3365 (loopback/voicemail-b) Callstate Change RINGING -> EARLY EXECUTE loopback/voicemail-b voicemail(default 192.168.65.98 1001) 2014-01-30 17:53:12.442539 [DEBUG] switch_ivr_originate.c:3495 Originate Resulted in Success: [loopback/voicemail-a] 2014-01-30 17:53:12.442539 [DEBUG] switch_channel.c:1969 (sofia/internal/1000@192.168.65.98) Callstate Change RING_WAIT -> ACTIVE 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:871 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] switch_ivr_bridge.c:1426 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA 2014-01-30 17:53:12.442539 [DEBUG] mod_loopback.c:610 CHANNEL LOOPBACK 2014-01-30 17:53:12.542890 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-01-30 17:53:12.542890 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) 2014-01-30 17:53:12.542890 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-01-30 17:53:13.922469 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav 2014-01-30 17:53:14.023721 [DEBUG] switch_ivr_play_say.c:251 Handle say:[1001] (en:en) 2014-01-30 17:53:14.023721 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-01-30 17:53:16.263327 [DEBUG] switch_ivr_play_say.c:1717 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/1.wav 2014-01-30 17:53:16.363379 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2014-01-30 17:53:16.363379 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms 2014-01-30 17:53:17.342459 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav 2014-01-30 17:53:17.442546 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2014-01-30 17:53:17.442546 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) 2014-01-30 17:53:17.442546 [DEBUG] switch_ivr_play_say.c:1314 Codec Activated L16@8000hz 1 channels 20ms recv 410 bytes from udp/[192.168.5.10]:20842 at 16:53:18.270540: ------------------------------------------------------------------------ BYE sip:1001@192.168.65.98:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.129.229:2425;rport;branch=z9hG4bKPje4e3e31a701c4d77b2b7d5dde2de9f6d Max-Forwards: 70 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=48rN88ce2XagK Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22407 BYE User-Agent: Blink 0.6.0 (Windows) Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:18.262629 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:18.283431 [NOTICE] sofia.c:737 Hangup sofia/internal/1000@192.168.65.98 [CS_EXECUTE] [NORMAL_CLEARING] 2014-01-30 17:53:18.283431 [DEBUG] switch_channel.c:3184 Send signal sofia/internal/1000@192.168.65.98 [KILL] 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@192.168.65.98 [BREAK] send 552 bytes to udp/[192.168.5.10]:20842 at 16:53:18.284629: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.129.229:2425;rport=20842;branch=z9hG4bKPje4e3e31a701c4d77b2b7d5dde2de9f6d;received=192.168.5.10 From: "thomas" <sip:1000@192.168.65.98>;tag=1753abc633294d3c8e2a69fd3a1ee28a To: <sip:1001@192.168.65.98>;tag=48rN88ce2XagK Call-ID: bb25748be1f94505a7132e68f5576bae CSeq: 22407 BYE User-Agent: FreeSWITCH-mod_sofia/1.2.18-1~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2014-01-30 17:53:18.283431 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [sofia/internal/1000@192.168.65.98] 2014-01-30 17:53:18.283431 [DEBUG] switch_ivr_bridge.c:658 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_ivr_bridge.c:557 sofia/internal/1000@192.168.65.98 ending bridge by request from write function 2014-01-30 17:53:18.283431 [DEBUG] switch_ivr_bridge.c:633 BRIDGE THREAD DONE [loopback/voicemail-a] 2014-01-30 17:53:18.283431 [DEBUG] switch_ivr_bridge.c:658 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:18.283431 [NOTICE] switch_ivr_bridge.c:719 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2014-01-30 17:53:18.283431 [DEBUG] switch_channel.c:3184 Send signal loopback/voicemail-a [KILL] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:481 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_HANGUP 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:679 (loopback/voicemail-a) State HANGUP 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:535 loopback/voicemail-a CHANNEL HANGUP 2014-01-30 17:53:18.283431 [NOTICE] mod_loopback.c:551 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2014-01-30 17:53:18.283431 [DEBUG] switch_channel.c:3184 Send signal loopback/voicemail-b [KILL] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:679 (loopback/voicemail-a) State HANGUP going to sleep 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:690 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-a) Running State Change CS_REPORTING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:762 (loopback/voicemail-a) State REPORTING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:762 (loopback/voicemail-a) State REPORTING going to sleep 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-a [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] mod_loopback.c:588 loopback/voicemail-a CHANNEL KILL 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1559 Session 3 (loopback/voicemail-a) Locked, Waiting on external entities 2014-01-30 17:53:18.283431 [DEBUG] switch_ivr_bridge.c:1527 sofia/internal/1000@192.168.65.98 skip receive message [UNBRIDGE] (channel is hungup already) 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:2810 sofia/internal/1000@192.168.65.98 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:478 (sofia/internal/1000@192.168.65.98) State EXECUTE going to sleep 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@192.168.65.98) Running State Change CS_HANGUP 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/1000@192.168.65.98) State HANGUP 2014-01-30 17:53:18.283431 [DEBUG] mod_sofia.c:500 sofia/internal/1000@192.168.65.98 Overriding SIP cause 480 with 488 from the other leg 2014-01-30 17:53:18.283431 [DEBUG] mod_sofia.c:506 Channel sofia/internal/1000@192.168.65.98 hanging up, cause: NORMAL_CLEARING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:48 sofia/internal/1000@192.168.65.98 Standard HANGUP, cause: NORMAL_CLEARING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:679 (sofia/internal/1000@192.168.65.98) State HANGUP going to sleep 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:690 (sofia/internal/1000@192.168.65.98) Callstate Change ACTIVE -> HANGUP 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:447 (sofia/internal/1000@192.168.65.98) State Change CS_HANGUP -> CS_REPORTING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/1000@192.168.65.98) Running State Change CS_REPORTING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:762 (sofia/internal/1000@192.168.65.98) State REPORTING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:92 sofia/internal/1000@192.168.65.98 Standard REPORTING, cause: NORMAL_CLEARING 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:762 (sofia/internal/1000@192.168.65.98) State REPORTING going to sleep 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:441 (sofia/internal/1000@192.168.65.98) State Change CS_REPORTING -> CS_DESTROY 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/1000@192.168.65.98 [BREAK] 2014-01-30 17:53:18.283431 [DEBUG] switch_core_session.c:1559 Session 1 (sofia/internal/1000@192.168.65.98) Locked, Waiting on external entities 2014-01-30 17:53:18.283431 [NOTICE] switch_core_session.c:1577 Session 1 (sofia/internal/1000@192.168.65.98) Ended 2014-01-30 17:53:18.283431 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/1000@192.168.65.98 [CS_DESTROY] 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:566 (sofia/internal/1000@192.168.65.98) Callstate Change HANGUP -> DOWN 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/1000@192.168.65.98) Running State Change CS_DESTROY 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/1000@192.168.65.98) State DESTROY 2014-01-30 17:53:18.283431 [DEBUG] mod_sofia.c:399 sofia/internal/1000@192.168.65.98 SOFIA DESTROY 2014-01-30 17:53:18.283431 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=CLEAR state=NOZRTP. 2014-01-30 17:53:18.283431 [DEBUG] switch_rtp.c:948 [ zrtp]: Stream ID=0 UNKNOWN switching <NONE> ---> <NONE>. 2014-01-30 17:53:18.283431 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. 2014-01-30 17:53:18.283431 [DEBUG] switch_rtp.c:948 [ zrtp engine]: STOP STREAM ID=0 mode=UNKNOWN state=NONE. 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:99 sofia/internal/1000@192.168.65.98 Standard DESTROY 2014-01-30 17:53:18.283431 [DEBUG] switch_core_state_machine.c:579 (sofia/internal/1000@192.168.65.98) State DESTROY going to sleep 2014-01-30 17:53:18.302529 [DEBUG] switch_ivr_play_say.c:1717 done playing file /usr/share/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav 2014-01-30 17:53:18.302529 [DEBUG] switch_core_session.c:2810 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:478 (loopback/voicemail-b) State EXECUTE going to sleep 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_HANGUP 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:679 (loopback/voicemail-b) State HANGUP 2014-01-30 17:53:18.302529 [DEBUG] mod_loopback.c:535 loopback/voicemail-b CHANNEL HANGUP 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:48 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:679 (loopback/voicemail-b) State HANGUP going to sleep 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:690 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:447 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2014-01-30 17:53:18.302529 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:18.302529 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:415 (loopback/voicemail-b) Running State Change CS_REPORTING 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:762 (loopback/voicemail-b) State REPORTING 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:92 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:762 (loopback/voicemail-b) State REPORTING going to sleep 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:441 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_session.c:1351 Send signal loopback/voicemail-b [BREAK] 2014-01-30 17:53:18.302529 [DEBUG] mod_loopback.c:588 loopback/voicemail-b CHANNEL KILL 2014-01-30 17:53:18.302529 [DEBUG] switch_core_session.c:1559 Session 4 (loopback/voicemail-b) Locked, Waiting on external entities 2014-01-30 17:53:18.302529 [NOTICE] switch_core_session.c:1577 Session 4 (loopback/voicemail-b) Ended 2014-01-30 17:53:18.302529 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-b [CS_DESTROY] 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-b) Callstate Change HANGUP -> DOWN 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-b) Running State Change CS_DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-b Standard DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-b) State DESTROY going to sleep 2014-01-30 17:53:18.302529 [NOTICE] switch_core_session.c:1577 Session 3 (loopback/voicemail-a) Ended 2014-01-30 17:53:18.302529 [NOTICE] switch_core_session.c:1581 Close Channel loopback/voicemail-a [CS_DESTROY] 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:566 (loopback/voicemail-a) Callstate Change HANGUP -> DOWN 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:569 (loopback/voicemail-a) Running State Change CS_DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:99 loopback/voicemail-a Standard DESTROY 2014-01-30 17:53:18.302529 [DEBUG] switch_core_state_machine.c:579 (loopback/voicemail-a) State DESTROY going to sleep recv 2307 bytes from udp/[192.168.5.10]:20842 at 16:53:18.329959: --------------------- one client (blink, 1000) supports only PCMA, the other client (bria, 1001) supports only PCMU. i didnt touch the default config of the freeswitch on a debian system. thank you very much for help! best, thomas 2014-01-28 Brian West <brian@freeswitch.org>:
Logs, with sip trace on please.
-- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com
T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)
On Jan 28, 2014, at 9:13 AM, thomas peterseil <thomas.peterseil@gmail.com> wrote:
i have the same problem. i am running a FS with the default config 1000 supports only PCMA and 1001 only PCMU (one client is blink, the other jitsi), the call between 1000 and 1001 doesnt work. as soon as i enable the same codecs on both clients, it works without any problem. thanks a lot for your help!
best regards, thomas
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.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
What are you expecting exactly? Looks to me like you have it configured to do PCMA, and X-lite responds 488? Based on my observation here is what you have: FreeSWITCH only configured to do PCMA based on the invite, X-Lite configure to use something that isn’t PCMA. Is my assessment of your expectations correct? -- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED) On Jan 30, 2014, at 11:02 AM, thomas peterseil <thomas.peterseil@gmail.com> wrote:
SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/UDP 192.168.65.98;rport=5060;branch=z9hG4bK27cZcy3ZyrZjj To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917>;tag=c5d7df41 From: "Extension 1000"<sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 INVITE User-Agent: X-Lite release 4.5.5 stamp 71241 Warning: 305 devnull "SDP: Incompatible media format: no common codec" Content-Length: 0
hello brian, as far as i know FS by default is doing transcoding, so my expectation is that FS will do a transcoding between both call-legs. i didn´t change anything of the default config. on one client PCMA is enabled, on the other PCMU. thank you very much! best, thomas 2014-01-30 Brian West <brian@freeswitch.org>:
What are you expecting exactly? Looks to me like you have it configured to do PCMA, and X-lite responds 488?
Based on my observation here is what you have:
FreeSWITCH only configured to do PCMA based on the invite, X-Lite configure to use something that isn't PCMA.
Is my assessment of your expectations correct?
-- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com
T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)
On Jan 30, 2014, at 11:02 AM, thomas peterseil <thomas.peterseil@gmail.com> wrote:
SIP/2.0 488 Not Acceptable Here Via: SIP/2.0/UDP 192.168.65.98;rport=5060;branch=z9hG4bK27cZcy3ZyrZjj To: <sip:1001@192.168.65.124:3588;rinstance=c88f5661c51fa917>;tag=c5d7df41 From: "Extension 1000"<sip:1000@192.168.65.98>;tag=5Hjea4XHZ602e Call-ID: d5227656-0471-1232-bd8c-08002740dafd CSeq: 55214329 INVITE User-Agent: X-Lite release 4.5.5 stamp 71241 Warning: 305 devnull "SDP: Incompatible media format: no common codec" Content-Length: 0
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.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
Thomas, It will, but if you wish this to take place then you MUST offer both PCMU and PCMA on the leg headed to the device that only has PCMU enabled, otherwise you’re sending an invite with only PCMA in it and that x-lite thats configured with only PCMU, Its responding 488. Its behaving exactly how its configured. Please add PCMA and PCMU to your codecs list on FreeSWITCH. -- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED) On Jan 30, 2014, at 1:51 PM, thomas peterseil <thomas.peterseil@gmail.com> wrote:
hello brian, as far as i know FS by default is doing transcoding, so my expectation is that FS will do a transcoding between both call-legs. i didn´t change anything of the default config. on one client PCMA is enabled, on the other PCMU. thank you very much! best, thomas
hello brian, thanks for your help! as far as i understood the default config of FS, it takes the codec list from the vars.xml file. i have both codecs (PCMU,PCMA) there: -------------- <X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/> -------------- when i do a show codec it also shows me both codecs. can you give me a hint where else i should look for this config problem? thanks a lot! best, thomas 2014-01-30 Brian West <brian@freeswitch.org>:
Thomas, It will, but if you wish this to take place then you MUST offer both PCMU and PCMA on the leg headed to the device that only has PCMU enabled, otherwise you're sending an invite with only PCMA in it and that x-lite thats configured with only PCMU, Its responding 488. Its behaving exactly how its configured. Please add PCMA and PCMU to your codecs list on FreeSWITCH.
-- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com
T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED)
On Jan 30, 2014, at 1:51 PM, thomas peterseil <thomas.peterseil@gmail.com> wrote:
hello brian, as far as i know FS by default is doing transcoding, so my expectation is that FS will do a transcoding between both call-legs. i didn´t change anything of the default config. on one client PCMA is enabled, on the other PCMU. thank you very much! best, thomas
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.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
Am Donnerstag, den 30.01.2014, 22:02 +0100 schrieb thomas peterseil:
hello brian, thanks for your help! as far as i understood the default config of FS, it takes the codec list from the vars.xml file. i have both codecs (PCMU,PCMA) there: -------------- <X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/> --------------
Right, but the default configuration (i.e. the "vanilla demo") also sets "inbound-late-negotiation" and "zrtp-passthru", which implicitly sets "inbound-late-negotiation". "Late negotiation" with "inherit codec" will make FS only to offer only those codecs on the outbound side, that it received on the inbound side. For example be there a setup "A -- FS -- B", A uses G.711A and G.711µ, FS uses G.711A and GSM-FR, and B uses GSM-FR. If then FS receives an "INVITE B, codec PCMA, PCMU" from A, it will forward PCMA as the only codec choice to B. See http://wiki.freeswitch.org/wiki/Codec_Negotiation Regards, David -- David Dahlberg Fraunhofer FKIE, Dept. Communication Systems (KOM) | Tel: +49-228-9435-845 Fraunhoferstr. 20, 53343 Wachtberg, Germany | Fax: +49-228-856277
Works: <extension name="Local_Extension"> <condition field="destination_number" expression="^(10[01][0-9])$"> <action application="export" data="absolute_codec_string=${ep_codec_string},PCMU@8000h"/> <action application="export" data="inherit_codec=true"/> <action application="bridge" data="user/${dialed_extension}@${domain_name}"/> <action application="answer"/> <action application="sleep" data="1000"/> <action application="bridge" data="loopback/app=voicemail:default ${domain_name} ${dialed_extension}"/> </condition> </extension> -- Brian West brian@freeswitch.org FreeSWITCH Solutions, LLC PO BOX 2531 Brookfield, WI 53008-2531 Twitter: @FreeSWITCH , @briankwest http://www.freeswitchbook.com http://www.freeswitchcookbook.com T: +1.918.420.9001 | F: +1.918.420.9002 | M: +1.918.424.WEST iNUM: +883 5100 1420 9001 ISN: 410*543 Skype:briankwest PGP Key: http://www.bkw.org/key.txt (AB93356707C76CED) On Jan 31, 2014, at 1:52 AM, Dahlberg, David <david.dahlberg@fkie.fraunhofer.de> wrote:
Am Donnerstag, den 30.01.2014, 22:02 +0100 schrieb thomas peterseil:
hello brian, thanks for your help! as far as i understood the default config of FS, it takes the codec list from the vars.xml file. i have both codecs (PCMU,PCMA) there: -------------- <X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/> --------------
Right, but the default configuration (i.e. the "vanilla demo") also sets "inbound-late-negotiation" and "zrtp-passthru", which implicitly sets "inbound-late-negotiation".
"Late negotiation" with "inherit codec" will make FS only to offer only those codecs on the outbound side, that it received on the inbound side.
For example be there a setup "A -- FS -- B", A uses G.711A and G.711µ, FS uses G.711A and GSM-FR, and B uses GSM-FR. If then FS receives an "INVITE B, codec PCMA, PCMU" from A, it will forward PCMA as the only codec choice to B.
See http://wiki.freeswitch.org/wiki/Codec_Negotiation
Regards, David
participants (4)
-
Brian West
-
Dahlberg, David
-
Shahzad Bhatti
-
thomas peterseil