First off all thanks for your kind helps.
Let me tell you the situation more clearly.
Firstly I used Android phones as sip clients with the open source sip client program, CSipSimple. My server computer has Ubuntu 12.04 LTS with one static ip address.
freeswitch version output: FreeSWITCH Version 1.3.13b+git~20130205T003128Z~70a9560306 (git 70a9560 2013-02-05 00:31:28Z)
We were using the system with 4 digits number sip account names without any problem. Also the account name will be used as dial number. An example of the user xml file is below. I changed the regex in dialpan/default.xml. The changings were perfectly succesfull with, again, 4 digits number. But when trying to include any other number of digits (3, 5 and 6 were tested), it doesn't work(When I change the regex to accept only 5 digits numbers, 4 digits ones didnt work as expected). I really could not understand why it is happening. Why there was no problem with 4 digits number and why the exact same system does not work with this basic change.
To explain the errors more, I want to talk about my tests. Firstly I used 4 digits number user. This test repeated with tls and srtp. These two test were succesfull.
And the secand test is same with first test but with 5 digits numbers without tls and srtp. Registration was succesfull but cant call. (or the call could not be forwarded) Of course I changed the regex and execute reloadxml in this test. GSM (8kHz) and G722(16kHz) codecs were used. As you see below, CODEC NEGOTIATION ERROR occured. After getting this error I changed the codes as SILK(16kHz). With this change I made the third test. Third test result is also below.
show registretions output:
reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostname,metadata
60022,my.server.ip.address,oOnxiVJFAgQWLABrD01UsYTVOY3TVSlx,sofia/internal/sip:60022@141.196.174.60:52245;ob,1368271435,141.196.174.60,52245,udp,server,
60021,my.server.ip.address,5r4MTDiZPhs5qzdin9A3hEUh1zZsdqqk,sofia/internal/sip:60021@141.196.174.60:57938;ob,1368271446,141.196.174.60,57938,udp,server,
@Sean, sorry but I cant post my whole log file because my server has got a network attack so I am quite busy with this attacker. And also I dont think CSipSimple has a problem with 5 digits because this system (with 5 digits) was succesfull with Kamailio and CSipSimple.
If I could not be clear please let me know. Thanks...
user xml example: This was exact same with the default users in freeswitch. Only the number changed.
<include>
<user id="60022">
<params>
<param name="password" value="$${default_password}"/>
<param name="vm-password" value="60022"/>
</params>
<variables>
<variable name="toll_allow" value="domestic,international,local"/>
<variable name="accountcode" value="60022"/>
<variable name="user_context" value="default"/>
<variable name="effective_caller_id_name" value="Extension 60022"/>
<variable name="effective_caller_id_number" value="60022"/>
<variable name="outbound_caller_id_name" value="$${outbound_caller_name}"/>
<variable name="outbound_caller_id_number" value="$${outbound_caller_id}"/>
<variable name="callgroup" value="techsupport"/>
</variables>
</user>
</include>
The second test error:
2013-05-11 12:13:56.800443 [DEBUG] sofia_reg.c:1511 Send challenge for [60021@my.server.ip.address]
2013-05-11 12:13:56.900444 [DEBUG] sofia_reg.c:1511 Send challenge for [60021@my.server.ip.address]
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60021'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60021'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60021'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 12:13:56.920444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60021'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60021'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60021'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 12:13:56.980451 [DEBUG] sofia_reg.c:1683 Register:
From: [60021@my.server.ip.address]
Contact: ["user" <sip:60021@141.196.174.60:54008;ob>]
Expires: [900]
2013-05-11 12:14:06.820443 [DEBUG] sofia_reg.c:1511 Send challenge for [60022@my.server.ip.address]
2013-05-11 12:14:06.900444 [DEBUG] sofia_reg.c:1511 Send challenge for [60022@my.server.ip.address]
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60022'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60022'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60022'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 12:14:06.980444 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60022'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60022'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60022'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 12:14:07.020442 [DEBUG] sofia_reg.c:1683 Register:
From: [60022@my.server.ip.address]
Contact: ["user" <sip:60022@141.196.174.60:33822;ob>]
Expires: [900]
2013-05-11 12:14:14.640437 [NOTICE] switch_channel.c:968 New Channel sofia/internal/60021@my.server.ip.address [26730cd2-ba1b-11e2-acc5-bda7cbfd9554]
2013-05-11 12:14:14.640437 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.640437 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.640437 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60021@my.server.ip.address) Running State Change CS_NEW
2013-05-11 12:14:14.640437 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/60021@my.server.ip.address) State NEW
2013-05-11 12:14:14.660438 [DEBUG] sofia.c:7733 IP 141.196.174.60 Rejected by acl "domains". Falling back to Digest auth.
2013-05-11 12:14:14.660438 [DEBUG] sofia_reg.c:1511 Send challenge for [60022@my.server.ip.address]
2013-05-11 12:14:14.660438 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.660438 [DEBUG] sofia.c:1719 detaching session 26730cd2-ba1b-11e2-acc5-bda7cbfd9554
2013-05-11 12:14:14.780439 [DEBUG] sofia.c:1811 Re-attaching to session 26730cd2-ba1b-11e2-acc5-bda7cbfd9554
2013-05-11 12:14:14.780439 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.780439 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.800439 [DEBUG] sofia.c:7733 IP 141.196.174.60 Rejected by acl "domains". Falling back to Digest auth.
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60021'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60021'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60021'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 12:14:14.800439 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 12:14:14.800439 [DEBUG] sofia.c:5578 Channel sofia/internal/60021@my.server.ip.address entering state [received][100]
2013-05-11 12:14:14.800439 [DEBUG] sofia.c:5589 Remote SDP:
v=0
o=- 3577252345 3577252345 IN IP4 141.196.174.60
s=pjmedia
c=IN IP4 141.196.174.60
t=0 0
m=audio 4010 RTP/AVP 8 0 3 101
c=IN IP4 141.196.174.60
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4011 IN IP4 192.168.43.10
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:fig56WojEoKmN07gnvdJZ9Mk6lznskMJszpBOqik
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:HUiy486/260zwSkQ0Z771fKC+g48P9cYEXNqlEYO
2013-05-11 12:14:14.800439 [DEBUG] sofia.c:5802 (sofia/internal/60021@my.server.ip.address) State Change CS_NEW -> CS_INIT
2013-05-11 12:14:14.800439 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60021@my.server.ip.address) Running State Change CS_INIT
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/60021@my.server.ip.address) State INIT
2013-05-11 12:14:14.800439 [DEBUG] mod_sofia.c:86 sofia/internal/60021@my.server.ip.address SOFIA INIT
2013-05-11 12:14:14.800439 [DEBUG] mod_sofia.c:126 (sofia/internal/60021@my.server.ip.address) State Change CS_INIT -> CS_ROUTING
2013-05-11 12:14:14.800439 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/60021@my.server.ip.address) State INIT going to sleep
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60021@my.server.ip.address) Running State Change CS_ROUTING
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:2003 (sofia/internal/60021@my.server.ip.address) Callstate Change DOWN -> RINGING
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/60021@my.server.ip.address) State ROUTING
2013-05-11 12:14:14.800439 [DEBUG] mod_sofia.c:149 sofia/internal/60021@my.server.ip.address SOFIA ROUTING
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:117 sofia/internal/60021@my.server.ip.address Standard ROUTING
2013-05-11 12:14:14.800439 [INFO] mod_dialplan_xml.c:557 Processing 60021 <60021>->60022 in context default
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->unloop] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->tod_example] continue=true
Dialplan: sofia/internal/60021@my.server.ip.address Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/60021@my.server.ip.address Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [global-intercept] destination_number(60022) =~ /^886$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [group-intercept] destination_number(60022) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [intercept-ext] destination_number(60022) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->redial] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [redial] destination_number(60022) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->global] continue=true
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/60021@my.server.ip.address Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (PASS) [global] ${switch_r_sdp}(v=0
o=- 3577252345 3577252345 IN IP4 141.196.174.60
s=pjmedia
c=IN IP4 141.196.174.60
t=0 0
m=audio 4010 RTP/AVP 8 0 3 101
c=IN IP4 141.196.174.60
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4011 IN IP4 192.168.43.10
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:fig56WojEoKmN07gnvdJZ9Mk6lznskMJszpBOqik
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:HUiy486/260zwSkQ0Z771fKC+g48P9cYEXNqlEYO
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/60021@my.server.ip.address Action set(sip_secure_media=true)
Dialplan: sofia/internal/60021@my.server.ip.address Action export(sip_secure_media=true)
Dialplan: sofia/internal/60021@my.server.ip.address Absolute Condition [global]
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/60021@my.server.ip.address Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [snom-demo-2] destination_number(60022) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [snom-demo-1] destination_number(60022) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [eavesdrop] destination_number(60022) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [eavesdrop] destination_number(60022) =~ /^779$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->call_return] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [call_return] destination_number(60022) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->del-group] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [del-group] destination_number(60022) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->add-group] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [add-group] destination_number(60022) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [call-group-simo] destination_number(60022) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [call-group-order] destination_number(60022) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (FAIL) [extension-intercom] destination_number(60022) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/60021@my.server.ip.address Regex (PASS) [Local_Extension] destination_number(60022) =~ /^([0-9][0-9][0-9][0-9]|[0-9][0-9][0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/60021@my.server.ip.address Action export(dialed_extension=60022)
Dialplan: sofia/internal/60021@my.server.ip.address Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/60021@my.server.ip.address Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/60021@my.server.ip.address Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/60021@my.server.ip.address Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/60021@my.server.ip.address Action set(ringback=${us-ring})
Dialplan: sofia/internal/60021@my.server.ip.address Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/60021@my.server.ip.address Action set(call_timeout=30)
Dialplan: sofia/internal/60021@my.server.ip.address Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/60021@my.server.ip.address Action set(continue_on_fail=true)
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/60021@my.server.ip.address Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/60021@my.server.ip.address Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/60021@my.server.ip.address Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/60021@my.server.ip.address Action answer()
Dialplan: sofia/internal/60021@my.server.ip.address Action sleep(1000)
Dialplan: sofia/internal/60021@my.server.ip.address Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/60021@my.server.ip.address) State Change CS_ROUTING -> CS_EXECUTE
2013-05-11 12:14:14.800439 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/60021@my.server.ip.address) State ROUTING going to sleep
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60021@my.server.ip.address) Running State Change CS_EXECUTE
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/60021@my.server.ip.address) State EXECUTE
2013-05-11 12:14:14.800439 [DEBUG] mod_sofia.c:242 sofia/internal/60021@my.server.ip.address SOFIA EXECUTE
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:209 sofia/internal/60021@my.server.ip.address Standard EXECUTE
EXECUTE sofia/internal/60021@my.server.ip.address set(sip_secure_media=true)
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [sip_secure_media]=[true]
EXECUTE sofia/internal/60021@my.server.ip.address export(sip_secure_media=true)
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [sip_secure_media]=[true]
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-spymap/60021/26730cd2-ba1b-11e2-acc5-bda7cbfd9554)
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-last_dial/60021/60022)
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-last_dial/global/26730cd2-ba1b-11e2-acc5-bda7cbfd9554)
EXECUTE sofia/internal/60021@my.server.ip.address export(RFC2822_DATE=Sat, 11 May 2013 12:14:14 +0300)
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [RFC2822_DATE]=[Sat, 11 May 2013 12:14:14 +0300]
EXECUTE sofia/internal/60021@my.server.ip.address export(dialed_extension=60022)
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [dialed_extension]=[60022]
EXECUTE sofia/internal/60021@my.server.ip.address bind_meta_app(1 b s execute_extension::dx XML features)
2013-05-11 12:14:14.800439 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/60021@my.server.ip.address bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/60021.2013-05-11-12-14-14.wav)
2013-05-11 12:14:14.800439 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/60021.2013-05-11-12-14-14.wav
EXECUTE sofia/internal/60021@my.server.ip.address bind_meta_app(3 b s execute_extension::cf XML features)
2013-05-11 12:14:14.800439 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/60021@my.server.ip.address bind_meta_app(4 b s execute_extension::att_xfer XML features)
2013-05-11 12:14:14.800439 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/60021@my.server.ip.address set(ringback=%(2000,4000,440,480))
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/60021@my.server.ip.address set(transfer_ringback=local_stream://moh)
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/60021@my.server.ip.address set(call_timeout=30)
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [call_timeout]=[30]
EXECUTE sofia/internal/60021@my.server.ip.address set(hangup_after_bridge=true)
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/60021@my.server.ip.address set(continue_on_fail=true)
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [continue_on_fail]=[true]
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-call_return/60022/60021)
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-last_dial_ext/60022/26730cd2-ba1b-11e2-acc5-bda7cbfd9554)
EXECUTE sofia/internal/60021@my.server.ip.address set(called_party_callgroup=techsupport)
2013-05-11 12:14:14.800439 [DEBUG] mod_dptools.c:1349 sofia/internal/60021@my.server.ip.address SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-last_dial_ext/techsupport/26730cd2-ba1b-11e2-acc5-bda7cbfd9554)
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-last_dial_ext/global/26730cd2-ba1b-11e2-acc5-bda7cbfd9554)
EXECUTE sofia/internal/60021@my.server.ip.address hash(insert/my.server.ip.address-last_dial/techsupport/26730cd2-ba1b-11e2-acc5-bda7cbfd9554)
EXECUTE sofia/internal/60021@my.server.ip.address bridge(user/60022@my.server.ip.address)
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1089 sofia/internal/60021@my.server.ip.address EXPORTING[export_vars] [sip_secure_media]=[true] to event
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1089 sofia/internal/60021@my.server.ip.address EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 11 May 2013 12:14:14 +0300] to event
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1089 sofia/internal/60021@my.server.ip.address EXPORTING[export_vars] [dialed_extension]=[60022] to event
2013-05-11 12:14:14.800439 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1089 sofia/internal/60021@my.server.ip.address EXPORTING[export_vars] [sip_secure_media]=[true] to event
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1089 sofia/internal/60021@my.server.ip.address EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 11 May 2013 12:14:14 +0300] to event
2013-05-11 12:14:14.800439 [DEBUG] switch_channel.c:1089 sofia/internal/60021@my.server.ip.address EXPORTING[export_vars] [dialed_extension]=[60022] to event
2013-05-11 12:14:14.800439 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables
2013-05-11 12:14:14.800439 [DEBUG] switch_event.c:1608 Parsing variable [sip_invite_domain]=[my.server.ip.address]
2013-05-11 12:14:14.800439 [DEBUG] switch_event.c:1608 Parsing variable [presence_id]=[60022@my.server.ip.address]
2013-05-11 12:14:14.800439 [NOTICE] switch_channel.c:968 New Channel sofia/internal/
sip:60022@141.196.174.60:33822 [268c95ee-ba1b-11e2-ace5-bda7cbfd9554]
2013-05-11 12:14:14.800439 [DEBUG] mod_sofia.c:5031 [zrtp_passthru] Setting a-leg inherit_codec=true
2013-05-11 12:14:14.800439 [DEBUG] mod_sofia.c:5034 [zrtp_passthru] Setting b-leg absolute_codec_string='PCMA@8000h@20i@64000b,PCMU@8000h@20i@64000b,GSM@8000h@20i@13200b'
2013-05-11 12:14:14.800439 [DEBUG] sofia_glue.c:3157 Set Local Key [1 AES_CM_128_HMAC_SHA1_32 inline:jy7Mnu44PUrnS4nFSUGkaIsFNftmZRTnE61m4sui]
2013-05-11 12:14:14.800439 [DEBUG] sofia_glue.c:2649 Local SDP:
v=0
o=FreeSWITCH 1368242802 1368242803 IN IP4 my.server.ip.address
s=FreeSWITCH
c=IN IP4 my.server.ip.address
t=0 0
m=audio 20852 RTP/SAVP 8 0 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:jy7Mnu44PUrnS4nFSUGkaIsFNftmZRTnE61m4sui
a=ptime:20
a=sendrecv
m=audio 20852 RTP/AVP 8 0 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2013-05-11 12:14:14.800439 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/
sip:60022@141.196.174.60:33822) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-05-11 12:14:14.800439 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/
sip:60022@141.196.174.60:33822) Running State Change CS_CONSUME_MEDIA
2013-05-11 12:14:14.980444 [INFO] switch_ivr_originate.c:1185 Sending early media
2013-05-11 12:14:14.980444 [ERR] sofia_glue.c:4927 a=crypto in RTP/AVP, refer to rfc3711
2013-05-11 12:14:14.980444 [ERR] mod_sofia.c:2789 CODEC NEGOTIATION ERROR. SDP:
v=0
o=- 3577252345 3577252345 IN IP4 141.196.174.60
s=pjmedia
c=IN IP4 141.196.174.60
t=0 0
m=audio 4010 RTP/AVP 8 0 3 101
c=IN IP4 141.196.174.60
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4011 IN IP4 192.168.43.10
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:fig56WojEoKmN07gnvdJZ9Mk6lznskMJszpBOqik
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:HUiy486/260zwSkQ0Z771fKC+g48P9cYEXNqlEYO
2013-05-11 12:14:14.980444 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.980444 [DEBUG] switch_channel.c:2994 (sofia/internal/60021@my.server.ip.address) Callstate Change RINGING -> HANGUP
2013-05-11 12:14:14.980444 [NOTICE] switch_channel.c:3216 Hangup sofia/internal/60021@my.server.ip.address [CS_EXECUTE] [INCOMPATIBLE_DESTINATION]
2013-05-11 12:14:14.980444 [DEBUG] switch_channel.c:3017 Send signal sofia/internal/60021@my.server.ip.address [KILL]
2013-05-11 12:14:14.980444 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:14.980444 [DEBUG] switch_ivr_originate.c:1186 sofia/internal/60021@my.server.ip.address Media Establishment Failed.
2013-05-11 12:14:14.980444 [DEBUG] switch_ivr_originate.c:3533 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2013-05-11 12:14:14.980444 [NOTICE] switch_ivr_originate.c:3620 Hangup sofia/internal/
sip:60022@141.196.174.60:33822 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL]
2013-05-11 12:14:14.980444 [NOTICE] switch_ivr_originate.c:2608 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL]
2013-05-11 12:14:14.980444 [DEBUG] switch_ivr_originate.c:3533 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL]
2013-05-11 12:14:14.980444 [INFO] mod_dptools.c:3060 Originate Failed. Cause: ORIGINATOR_CANCEL
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:48 sofia/internal/
sip:60022@141.196.174.60:33822 Standard HANGUP, cause: ORIGINATOR_CANCEL
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/
sip:60022@141.196.174.60:33822) State Change CS_HANGUP -> CS_REPORTING
2013-05-11 12:14:14.980444 [DEBUG] switch_core_session.c:2689 sofia/internal/60021@my.server.ip.address skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/60021@my.server.ip.address) State EXECUTE going to sleep
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60021@my.server.ip.address) Running State Change CS_HANGUP
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:92 sofia/internal/
sip:60022@141.196.174.60:33822 Standard REPORTING, cause: ORIGINATOR_CANCEL
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:667 (sofia/internal/60021@my.server.ip.address) State HANGUP
2013-05-11 12:14:14.980444 [DEBUG] mod_sofia.c:503 Channel sofia/internal/60021@my.server.ip.address hanging up, cause: INCOMPATIBLE_DESTINATION
2013-05-11 12:14:14.980444 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/
sip:60022@141.196.174.60:33822) State Change CS_REPORTING -> CS_DESTROY
2013-05-11 12:14:14.980444 [DEBUG] switch_core_session.c:1499 Session 23 (sofia/internal/
sip:60022@141.196.174.60:33822) Locked, Waiting on external entities
2013-05-11 12:14:15.000444 [DEBUG] mod_sofia.c:633 Responding to INVITE with: 488
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:48 sofia/internal/60021@my.server.ip.address Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:667 (sofia/internal/60021@my.server.ip.address) State HANGUP going to sleep
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/60021@my.server.ip.address) State Change CS_HANGUP -> CS_REPORTING
2013-05-11 12:14:15.000444 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60021@my.server.ip.address) Running State Change CS_REPORTING
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/60021@my.server.ip.address) State REPORTING
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:92 sofia/internal/60021@my.server.ip.address Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/60021@my.server.ip.address) State REPORTING going to sleep
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/60021@my.server.ip.address) State Change CS_REPORTING -> CS_DESTROY
2013-05-11 12:14:15.000444 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60021@my.server.ip.address [BREAK]
2013-05-11 12:14:15.000444 [DEBUG] switch_core_session.c:1499 Session 22 (sofia/internal/60021@my.server.ip.address) Locked, Waiting on external entities
2013-05-11 12:14:15.000444 [NOTICE] switch_core_session.c:1517 Session 22 (sofia/internal/60021@my.server.ip.address) Ended
2013-05-11 12:14:15.000444 [NOTICE] switch_core_session.c:1521 Close Channel sofia/internal/60021@my.server.ip.address [CS_DESTROY]
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:556 (sofia/internal/60021@my.server.ip.address) Callstate Change HANGUP -> DOWN
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:559 (sofia/internal/60021@my.server.ip.address) Running State Change CS_DESTROY
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/60021@my.server.ip.address) State DESTROY
2013-05-11 12:14:15.000444 [DEBUG] mod_sofia.c:396 sofia/internal/60021@my.server.ip.address SOFIA DESTROY
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:99 sofia/internal/60021@my.server.ip.address Standard DESTROY
2013-05-11 12:14:15.000444 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/60021@my.server.ip.address) State DESTROY going to sleep
2013-05-11 12:29:03.100449 [DEBUG] sofia_reg.c:1511 Send challenge for [60022@my.server.ip.address]
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60022'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60022'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60022'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 12:29:05.900434 [DEBUG] sofia_reg.c:1683 Register:
From: [60022@my.server.ip.address]
Contact: ["user" <sip:60022@141.196.174.60:33822;ob>]
Expires: [900]
third test
2013-05-11 14:08:17.980434 [NOTICE] switch_channel.c:968 New Channel sofia/internal/60022@my.server.ip.address [156488c0-ba2b-11e2-ad18-bda7cbfd9554]
2013-05-11 14:08:17.980434 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:17.980434 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:17.980434 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60022@my.server.ip.address) Running State Change CS_NEW
2013-05-11 14:08:17.980434 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/60022@my.server.ip.address) State NEW
2013-05-11 14:08:18.000438 [DEBUG] sofia.c:7733 IP 141.196.174.60 Rejected by acl "domains". Falling back to Digest auth.
2013-05-11 14:08:18.000438 [DEBUG] sofia_reg.c:1511 Send challenge for [60021@my.server.ip.address]
2013-05-11 14:08:18.000438 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.000438 [DEBUG] sofia.c:1719 detaching session 156488c0-ba2b-11e2-ad18-bda7cbfd9554
2013-05-11 14:08:18.120438 [DEBUG] sofia.c:1811 Re-attaching to session 156488c0-ba2b-11e2-ad18-bda7cbfd9554
2013-05-11 14:08:18.120438 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.120438 [DEBUG] switch_core_session.c:975 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.140456 [DEBUG] sofia.c:7733 IP 141.196.174.60 Rejected by acl "domains". Falling back to Digest auth.
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'record_stereo' = 'true'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_gateway' = '
example.com'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'default_areacode' = '918'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'transfer_fallback_extension' = 'operator'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'toll_allow' = 'domestic,international,local'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'accountcode' = '60022'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'user_context' = 'default'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_name' = 'Extension 60022'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'effective_caller_id_number' = '60022'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_name' = 'FreeSWITCH'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'outbound_caller_id_number' = '0000000000'
2013-05-11 14:08:18.140456 [DEBUG] sofia_reg.c:2767 event_add_header -> 'callgroup' = 'techsupport'
2013-05-11 14:08:18.140456 [DEBUG] sofia.c:5578 Channel sofia/internal/60022@my.server.ip.address entering state [received][100]
2013-05-11 14:08:18.140456 [DEBUG] sofia.c:5589 Remote SDP:
v=0
o=- 3577259178 3577259178 IN IP4 141.196.174.60
s=pjmedia
c=IN IP4 141.196.174.60
t=0 0
m=audio 4000 RTP/AVP 97 101
c=IN IP4 141.196.174.60
a=rtpmap:97 SILK/16000
a=fmtp:97 useinbandfec=0
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4001 IN IP4 192.168.43.193
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:+8RV0fxAu+3s1Fc8BQxiMa9ras5u/JDmQ9uCVagu
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:CQ25iu0Z418+mKdV+nRcwXqkd5z+gUxuXsqQt40P
2013-05-11 14:08:18.140456 [DEBUG] sofia.c:5802 (sofia/internal/60022@my.server.ip.address) State Change CS_NEW -> CS_INIT
2013-05-11 14:08:18.140456 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60022@my.server.ip.address) Running State Change CS_INIT
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/60022@my.server.ip.address) State INIT
2013-05-11 14:08:18.140456 [DEBUG] mod_sofia.c:86 sofia/internal/60022@my.server.ip.address SOFIA INIT
2013-05-11 14:08:18.140456 [DEBUG] mod_sofia.c:126 (sofia/internal/60022@my.server.ip.address) State Change CS_INIT -> CS_ROUTING
2013-05-11 14:08:18.140456 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/60022@my.server.ip.address) State INIT going to sleep
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60022@my.server.ip.address) Running State Change CS_ROUTING
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:2003 (sofia/internal/60022@my.server.ip.address) Callstate Change DOWN -> RINGING
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/60022@my.server.ip.address) State ROUTING
2013-05-11 14:08:18.140456 [DEBUG] mod_sofia.c:149 sofia/internal/60022@my.server.ip.address SOFIA ROUTING
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:117 sofia/internal/60022@my.server.ip.address Standard ROUTING
2013-05-11 14:08:18.140456 [INFO] mod_dialplan_xml.c:557 Processing 60022 <60022>->60021 in context default
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->unloop] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->tod_example] continue=true
Dialplan: sofia/internal/60022@my.server.ip.address Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/60022@my.server.ip.address Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [global-intercept] destination_number(60021) =~ /^886$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [group-intercept] destination_number(60021) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [intercept-ext] destination_number(60021) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->redial] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [redial] destination_number(60021) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->global] continue=true
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/60022@my.server.ip.address Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (PASS) [global] ${switch_r_sdp}(v=0
o=- 3577259178 3577259178 IN IP4 141.196.174.60
s=pjmedia
c=IN IP4 141.196.174.60
t=0 0
m=audio 4000 RTP/AVP 97 101
c=IN IP4 141.196.174.60
a=rtpmap:97 SILK/16000
a=fmtp:97 useinbandfec=0
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtcp:4001 IN IP4 192.168.43.193
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:+8RV0fxAu+3s1Fc8BQxiMa9ras5u/JDmQ9uCVagu
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:CQ25iu0Z418+mKdV+nRcwXqkd5z+gUxuXsqQt40P
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/60022@my.server.ip.address Action set(sip_secure_media=true)
Dialplan: sofia/internal/60022@my.server.ip.address Action export(sip_secure_media=true)
Dialplan: sofia/internal/60022@my.server.ip.address Absolute Condition [global]
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/60022@my.server.ip.address Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [snom-demo-2] destination_number(60021) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [snom-demo-1] destination_number(60021) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [eavesdrop] destination_number(60021) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [eavesdrop] destination_number(60021) =~ /^779$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->call_return] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [call_return] destination_number(60021) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->del-group] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [del-group] destination_number(60021) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->add-group] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [add-group] destination_number(60021) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [call-group-simo] destination_number(60021) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [call-group-order] destination_number(60021) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (FAIL) [extension-intercom] destination_number(60021) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/60022@my.server.ip.address Regex (PASS) [Local_Extension] destination_number(60021) =~ /^([0-9][0-9][0-9][0-9]|[0-9][0-9][0-9][0-9][0-9])$/ break=on-false
Dialplan: sofia/internal/60022@my.server.ip.address Action export(dialed_extension=60021)
Dialplan: sofia/internal/60022@my.server.ip.address Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/60022@my.server.ip.address Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav)
Dialplan: sofia/internal/60022@my.server.ip.address Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/60022@my.server.ip.address Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/60022@my.server.ip.address Action set(ringback=${us-ring})
Dialplan: sofia/internal/60022@my.server.ip.address Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/60022@my.server.ip.address Action set(call_timeout=30)
Dialplan: sofia/internal/60022@my.server.ip.address Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/60022@my.server.ip.address Action set(continue_on_fail=true)
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/60022@my.server.ip.address Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/60022@my.server.ip.address Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/60022@my.server.ip.address Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/60022@my.server.ip.address Action answer()
Dialplan: sofia/internal/60022@my.server.ip.address Action sleep(1000)
Dialplan: sofia/internal/60022@my.server.ip.address Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/60022@my.server.ip.address) State Change CS_ROUTING -> CS_EXECUTE
2013-05-11 14:08:18.140456 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/60022@my.server.ip.address) State ROUTING going to sleep
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60022@my.server.ip.address) Running State Change CS_EXECUTE
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/60022@my.server.ip.address) State EXECUTE
2013-05-11 14:08:18.140456 [DEBUG] mod_sofia.c:242 sofia/internal/60022@my.server.ip.address SOFIA EXECUTE
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:209 sofia/internal/60022@my.server.ip.address Standard EXECUTE
EXECUTE sofia/internal/60022@my.server.ip.address set(sip_secure_media=true)
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [sip_secure_media]=[true]
EXECUTE sofia/internal/60022@my.server.ip.address export(sip_secure_media=true)
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [sip_secure_media]=[true]
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-spymap/60022/156488c0-ba2b-11e2-ad18-bda7cbfd9554)
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-last_dial/60022/60021)
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-last_dial/global/156488c0-ba2b-11e2-ad18-bda7cbfd9554)
EXECUTE sofia/internal/60022@my.server.ip.address export(RFC2822_DATE=Sat, 11 May 2013 14:08:18 +0300)
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [RFC2822_DATE]=[Sat, 11 May 2013 14:08:18 +0300]
EXECUTE sofia/internal/60022@my.server.ip.address export(dialed_extension=60021)
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1135 EXPORT (export_vars) [dialed_extension]=[60021]
EXECUTE sofia/internal/60022@my.server.ip.address bind_meta_app(1 b s execute_extension::dx XML features)
2013-05-11 14:08:18.140456 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/60022@my.server.ip.address bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/60022.2013-05-11-14-08-18.wav)
2013-05-11 14:08:18.140456 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/60022.2013-05-11-14-08-18.wav
EXECUTE sofia/internal/60022@my.server.ip.address bind_meta_app(3 b s execute_extension::cf XML features)
2013-05-11 14:08:18.140456 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/60022@my.server.ip.address bind_meta_app(4 b s execute_extension::att_xfer XML features)
2013-05-11 14:08:18.140456 [INFO] switch_ivr_async.c:3409 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/60022@my.server.ip.address set(ringback=%(2000,4000,440,480))
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/60022@my.server.ip.address set(transfer_ringback=local_stream://moh)
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/60022@my.server.ip.address set(call_timeout=30)
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [call_timeout]=[30]
EXECUTE sofia/internal/60022@my.server.ip.address set(hangup_after_bridge=true)
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/60022@my.server.ip.address set(continue_on_fail=true)
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [continue_on_fail]=[true]
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-call_return/60021/60022)
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-last_dial_ext/60021/156488c0-ba2b-11e2-ad18-bda7cbfd9554)
EXECUTE sofia/internal/60022@my.server.ip.address set(called_party_callgroup=techsupport)
2013-05-11 14:08:18.140456 [DEBUG] mod_dptools.c:1349 sofia/internal/60022@my.server.ip.address SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-last_dial_ext/techsupport/156488c0-ba2b-11e2-ad18-bda7cbfd9554)
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-last_dial_ext/global/156488c0-ba2b-11e2-ad18-bda7cbfd9554)
EXECUTE sofia/internal/60022@my.server.ip.address hash(insert/my.server.ip.address-last_dial/techsupport/156488c0-ba2b-11e2-ad18-bda7cbfd9554)
EXECUTE sofia/internal/60022@my.server.ip.address bridge(user/60021@my.server.ip.address)
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1089 sofia/internal/60022@my.server.ip.address EXPORTING[export_vars] [sip_secure_media]=[true] to event
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1089 sofia/internal/60022@my.server.ip.address EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 11 May 2013 14:08:18 +0300] to event
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1089 sofia/internal/60022@my.server.ip.address EXPORTING[export_vars] [dialed_extension]=[60021] to event
2013-05-11 14:08:18.140456 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1089 sofia/internal/60022@my.server.ip.address EXPORTING[export_vars] [sip_secure_media]=[true] to event
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1089 sofia/internal/60022@my.server.ip.address EXPORTING[export_vars] [RFC2822_DATE]=[Sat, 11 May 2013 14:08:18 +0300] to event
2013-05-11 14:08:18.140456 [DEBUG] switch_channel.c:1089 sofia/internal/60022@my.server.ip.address EXPORTING[export_vars] [dialed_extension]=[60021] to event
2013-05-11 14:08:18.140456 [DEBUG] switch_ivr_originate.c:2022 Parsing global variables
2013-05-11 14:08:18.140456 [DEBUG] switch_event.c:1608 Parsing variable [sip_invite_domain]=[my.server.ip.address]
2013-05-11 14:08:18.140456 [DEBUG] switch_event.c:1608 Parsing variable [presence_id]=[60021@my.server.ip.address]
2013-05-11 14:08:18.140456 [NOTICE] switch_channel.c:968 New Channel sofia/internal/
sip:60021@141.196.174.60:57938 [157eb0a6-ba2b-11e2-ad38-bda7cbfd9554]
2013-05-11 14:08:18.140456 [DEBUG] mod_sofia.c:5031 [zrtp_passthru] Setting a-leg inherit_codec=true
2013-05-11 14:08:18.140456 [DEBUG] sofia_glue.c:3157 Set Local Key [1 AES_CM_128_HMAC_SHA1_32 inline:FGwgO9qNK7dbHa/ZYQcA2fWT17ktjsvjEt5fYXf4]
2013-05-11 14:08:18.140456 [DEBUG] sofia_glue.c:2649 Local SDP:
v=0
o=FreeSWITCH 1368243506 1368243507 IN IP4 my.server.ip.address
s=FreeSWITCH
c=IN IP4 my.server.ip.address
t=0 0
m=audio 26992 RTP/SAVP 9 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:FGwgO9qNK7dbHa/ZYQcA2fWT17ktjsvjEt5fYXf4
a=ptime:20
a=sendrecv
m=audio 26992 RTP/AVP 9 0 8 3 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
2013-05-11 14:08:18.140456 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/
sip:60021@141.196.174.60:57938) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-05-11 14:08:18.140456 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/
sip:60021@141.196.174.60:57938) Running State Change CS_CONSUME_MEDIA
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:48 sofia/internal/
sip:60021@141.196.174.60:57938 Standard HANGUP, cause: SERVICE_NOT_IMPLEMENTED
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/
sip:60021@141.196.174.60:57938) State Change CS_HANGUP -> CS_REPORTING
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:92 sofia/internal/
sip:60021@141.196.174.60:57938 Standard REPORTING, cause: SERVICE_NOT_IMPLEMENTED
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/
sip:60021@141.196.174.60:57938) State Change CS_REPORTING -> CS_DESTROY
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:1499 Session 27 (sofia/internal/
sip:60021@141.196.174.60:57938) Locked, Waiting on external entities
2013-05-11 14:08:18.340438 [DEBUG] switch_ivr_originate.c:3533 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED]
2013-05-11 14:08:18.340438 [NOTICE] switch_ivr_originate.c:2608 Cannot create outgoing channel of type [user] cause: [SERVICE_NOT_IMPLEMENTED]
2013-05-11 14:08:18.340438 [DEBUG] switch_ivr_originate.c:3533 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED]
2013-05-11 14:08:18.340438 [INFO] mod_dptools.c:3060 Originate Failed. Cause: SERVICE_NOT_IMPLEMENTED
EXECUTE sofia/internal/60022@my.server.ip.address answer()
2013-05-11 14:08:18.340438 [ERR] sofia_glue.c:4927 a=crypto in RTP/AVP, refer to rfc3711
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:830 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.340438 [DEBUG] switch_channel.c:2994 (sofia/internal/60022@my.server.ip.address) Callstate Change RINGING -> HANGUP
2013-05-11 14:08:18.340438 [NOTICE] switch_channel.c:3484 Hangup sofia/internal/60022@my.server.ip.address [CS_EXECUTE] [INCOMPATIBLE_DESTINATION]
2013-05-11 14:08:18.340438 [DEBUG] switch_channel.c:3017 Send signal sofia/internal/60022@my.server.ip.address [KILL]
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:2689 sofia/internal/60022@my.server.ip.address skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/60022@my.server.ip.address) State EXECUTE going to sleep
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60022@my.server.ip.address) Running State Change CS_HANGUP
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:667 (sofia/internal/60022@my.server.ip.address) State HANGUP
2013-05-11 14:08:18.340438 [DEBUG] mod_sofia.c:497 sofia/internal/60022@my.server.ip.address Overriding SIP cause 488 with 406 from the other leg
2013-05-11 14:08:18.340438 [DEBUG] mod_sofia.c:503 Channel sofia/internal/60022@my.server.ip.address hanging up, cause: INCOMPATIBLE_DESTINATION
2013-05-11 14:08:18.340438 [DEBUG] mod_sofia.c:633 Responding to INVITE with: 406
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:48 sofia/internal/60022@my.server.ip.address Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:667 (sofia/internal/60022@my.server.ip.address) State HANGUP going to sleep
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/60022@my.server.ip.address) State Change CS_HANGUP -> CS_REPORTING
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/60022@my.server.ip.address) Running State Change CS_REPORTING
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/60022@my.server.ip.address) State REPORTING
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:92 sofia/internal/60022@my.server.ip.address Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:749 (sofia/internal/60022@my.server.ip.address) State REPORTING going to sleep
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/60022@my.server.ip.address) State Change CS_REPORTING -> CS_DESTROY
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:1291 Send signal sofia/internal/60022@my.server.ip.address [BREAK]
2013-05-11 14:08:18.340438 [DEBUG] switch_core_session.c:1499 Session 26 (sofia/internal/60022@my.server.ip.address) Locked, Waiting on external entities
2013-05-11 14:08:18.340438 [NOTICE] switch_core_session.c:1517 Session 26 (sofia/internal/60022@my.server.ip.address) Ended
2013-05-11 14:08:18.340438 [NOTICE] switch_core_session.c:1521 Close Channel sofia/internal/60022@my.server.ip.address [CS_DESTROY]
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:556 (sofia/internal/60022@my.server.ip.address) Callstate Change HANGUP -> DOWN
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:559 (sofia/internal/60022@my.server.ip.address) Running State Change CS_DESTROY
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/60022@my.server.ip.address) State DESTROY
2013-05-11 14:08:18.340438 [DEBUG] mod_sofia.c:396 sofia/internal/60022@my.server.ip.address SOFIA DESTROY
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:99 sofia/internal/60022@my.server.ip.address Standard DESTROY
2013-05-11 14:08:18.340438 [DEBUG] switch_core_state_machine.c:569 (sofia/internal/60022@my.server.ip.address) State DESTROY going to sleep