[Freeswitch-users] g.722 --> SPEEX/16000 or SPEEX/32000 transcoding issue

Tue Feb 9 14:04:51 PST 2010

I think I see the problem:

In the log is the following:

2010-02-09 21:49:36.995060 [WARNING] switch_core_file.c:177 Sample rate
doesn't match

However, surely this is incorrect, as g.722 and SPEEX/16000 in fact both do
use the same sample rate of 16kHz

g.722 might not look like it from the SDP which announces g722/8000 - but
this is a historical error in the RFC.

Bruce

On 9 February 2010 21:55, Bruce Hopkins <jbrucehopkins at gmail.com> wrote:

> Willdo,
>
> To clarify in brief though, the scenario which occurs and causes the call
> to fail is:
>
> SIP client  1 (g.722 enabled only ) -----> INVITE (with SDP offer: Media
> Attribute (a): rtpmap:9 g722/8000 ) -->FreeSWITCH
>
> ---> INVITE (with SDP offer including a bunch of codecs including rtpmap:
> rtpmap:98 SPEEX/8000 but crucially *not* including SPEEX/16000 or
> SPEEX/32000)
>
> ---> SIP client 2 (with only SPEEX/16000 or SPEEX/32000 enabled).
>
> The second SIP client does not get offered a codec it can accept, so SIP
> client 1 is sent a method 488 "Not Acceptable Here" message and the calling
> party gets directed to the voicemail for the other SIP client.
>
> By contrast, there is no problem calling SPEEX/32000 --> SPEEX/32000 or
> calling SPEEX/16000 --> SPEEX/16000.
>
> there is also no problem calling SPEEX/32000 --> g.722/8000.
>
> I am wondering if the problem is that FreeSWITCH is interpreting g.722 as
> being a narrowband (8kHz sample rate) codec, due to the historic anomaly of
> it presenting g722/8000 in the SDP even though it in fact uses 16kHz
> sampling, and for that reason not wanting to offer a 16kHz sample rate codec
> to the second SIP client?
>
> I suggest this as I also found trying to call alaw --> SPEEX/16000 does not
> work, for example.
>
>
>
> Here is the log file for the scenario which does not work (g.722 client
> trying to call Speex wideband client).  Please let me know if a Wireshark
> trace would be helpful.
>
> 2010-02-09 21:49:32.784387 [DEBUG] sofia.c:5224 0 acls to check for proxy
> 2010-02-09 21:49:32.784387 [DEBUG] sofia.c:5242 network ip is a proxy [0]
> 2010-02-09 21:49:32.784387 [DEBUG] sofia.c:5270 IP 192.168.10.131 Rejected
> by acl "domains". Falling back to Digest auth.
> 2010-02-09 21:49:32.791074 [DEBUG] sofia.c:5224 0 acls to check for proxy
> 2010-02-09 21:49:32.791074 [DEBUG] sofia.c:5242 network ip is a proxy [0]
> 2010-02-09 21:49:32.791074 [DEBUG] sofia.c:5270 IP 192.168.10.131 Rejected
> by acl "domains". Falling back to Digest auth.
> 2010-02-09 21:49:32.794074 [NOTICE] switch_channel.c:613 New Channel
> sofia/internal/60002 at 192.168.10.30 [66610a8c-aec9-48ca-9b67-aafdcd3e3d08]
> 2010-02-09 21:49:32.794074 [DEBUG] sofia.c:3727 Channel sofia/internal/
> 60002 at 192.168.10.30 entering state [received][100]
> 2010-02-09 21:49:32.794074 [DEBUG] sofia.c:3738 Remote SDP:
> v=0
> o=- 5 2 IN IP4 192.168.10.131
> s=CounterPath eyeBeam 1.5
> c=IN IP4 192.168.10.131
> t=0 0
> m=audio 25592 RTP/AVP 9 101
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-15
>
> 2010-02-09 21:49:32.794074 [DEBUG] sofia_glue.c:3305 Audio Codec Compare
> [G722:9:8000:20]/[G722:9:8000:20]
> 2010-02-09 21:49:32.795079 [DEBUG] sofia_glue.c:2143 Set Codec
> sofia/internal/60002 at 192.168.10.30 G722/8000 20 ms 160 samples
> 2010-02-09 21:49:32.795079 [DEBUG] sofia_glue.c:3261 Set 2833 dtmf payload
> to 101
> 2010-02-09 21:49:32.795079 [DEBUG] sofia.c:3885 (sofia/internal/
> 60002 at 192.168.10.30) State Change CS_NEW -> CS_INIT
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/60002 at 192.168.10.30) Running State Change CS_INIT
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/60002 at 192.168.10.30) State INIT
> 2010-02-09 21:49:32.795079 [DEBUG] mod_sofia.c:83 sofia/internal/
> 60002 at 192.168.10.30 SOFIA INIT
> 2010-02-09 21:49:32.795079 [DEBUG] mod_sofia.c:111 (sofia/internal/
> 60002 at 192.168.10.30) State Change CS_INIT -> CS_ROUTING
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/60002 at 192.168.10.30) State INIT going to sleep
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/60002 at 192.168.10.30) Running State Change CS_ROUTING
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/60002 at 192.168.10.30) State ROUTING
> 2010-02-09 21:49:32.795079 [DEBUG] mod_sofia.c:132 sofia/internal/
> 60002 at 192.168.10.30 SOFIA ROUTING
> 2010-02-09 21:49:32.795079 [DEBUG] switch_core_state_machine.c:78
> sofia/internal/60002 at 192.168.10.30 Standard ROUTING
> 2010-02-09 21:49:32.795079 [INFO] mod_dialplan_xml.c:408 Processing
> 60002->1001 in context default
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->unloop]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [unloop]
> ${unroll_loops}(true) =~ /^true$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [unloop]
> ${sip_looped_call}() =~ /^true$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->tod_example] continue=true
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [tod_example]
> ${strftime(%w)}(2) =~ /^([1-5])$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [tod_example]
> ${strftime(%H%M)}(2149) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->global-intercept] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [global-intercept] destination_number(1001) =~ /^\*886$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->group-intercept] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->intercept-ext] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [intercept-ext]
> destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->redial]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [redial]
> destination_number(1001) =~ /^\*870$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->global]
> continue=true
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [global]
> ${network_addr}(192.168.10.131) =~ /^$/ break=never
> Dialplan: sofia/internal/60002 at 192.168.10.30 ANTI-Action
> set(use_profile=${cond(${acl(${network_addr} rfc1918)} == true ? nat :
> default)})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [global]
> ${numbering_plan}() =~ /^$/ break=never
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action set_user(default@${domain_name})
>
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [global]
> ${call_debug}(false) =~ /^true$/ break=never
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [global]
> ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/
> break=never
> Dialplan: sofia/internal/60002 at 192.168.10.30 Absolute Condition [global]
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> db(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> db(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
>
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> db(insert/${domain_name}-last_dial/global/${uuid})
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->snom-demo-2] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [snom-demo-2]
> destination_number(1001) =~ /^\*9001$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->snom-demo-1] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [snom-demo-1]
> destination_number(1001) =~ /^\*9000$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->eavesdrop]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [eavesdrop]
> destination_number(1001) =~ /^\*88(.*)$|^\*0(.*)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->eavesdrop]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [eavesdrop]
> destination_number(1001) =~ /^\*779$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->call_privacy] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [call_privacy]
> destination_number(1001) =~ /^\*67(\d+)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->call_return] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [call_return]
> destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->del-group]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [del-group]
> destination_number(1001) =~ /^\*80(\d{2})$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->add-group]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [add-group]
> destination_number(1001) =~ /^\*81(\d{2})$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->call-group-simo] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [call-group-simo] destination_number(1001) =~ /^\*82(\d{2})$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->call-group-order] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [call-group-order] destination_number(1001) =~ /^\*83(\d{2})$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->extension-intercom] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [extension-intercom] destination_number(1001) =~ /^\*8(\d{4})$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->send_to_voicemail_5digits] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [send_to_voicemail_5digits] destination_number(1001) =~ /^\*99(\d{5})$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->send_to_voicemail_4digits] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [send_to_voicemail_4digits] destination_number(1001) =~ /^\*99(\d{4})$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->send_to_voicemail_3digits] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [send_to_voicemail_3digits] destination_number(1001) =~ /^\*99(\d{3})$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->pizza_demo]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [pizza_demo]
> destination_number(1001) =~ /^(pizza|74992)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->2001]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [2001]
> destination_number(1001) =~ /^2001$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->Call via
> asterisk-pbx1] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [Call via
> asterisk-pbx1] destination_number(1001) =~ /269065/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->pizza_demo]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [pizza_demo]
> destination_number(1001) =~ /^(pizza|74992)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->5002]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [5002]
> destination_number(1001) =~ /^5002$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->7002]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [7002]
> destination_number(1001) =~ /^7002$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->DISA]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [DISA]
> destination_number(1001) =~ /^\*(3472)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->Recordings]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [Recordings]
> destination_number(1001) =~ /^\*(732673)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->7002.park]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [7002.park]
> destination_number(1001) =~ /^\*7002$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->group_dial_sales] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [group_dial_sales] destination_number(1001) =~ /^\*2000$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->group_dial_support] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [group_dial_support] destination_number(1001) =~ /^\*2001$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->group_dial_billing] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [group_dial_billing] destination_number(1001) =~ /^\*2002$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->vmain2]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [vmain2]
> destination_number(1001) =~ /^vmain2$|^\*97$|^\*4000$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->vmain]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [vmain]
> destination_number(1001) =~ /^vmain$|^\*98$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->sip_uri]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [sip_uri]
> destination_number(1001) =~ /^sip:(.*)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->nb_conferences] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [nb_conferences]
> destination_number(1001) =~ /^\*(30\d{2})$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->wb_conferences] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [wb_conferences]
> destination_number(1001) =~ /^\*(31\d{2})$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->uwb_conferences] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [uwb_conferences] destination_number(1001) =~ /^\*(32\d{2})$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->cdquality_conferences] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [cdquality_conferences] destination_number(1001) =~ /^\*(33\d{2})$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->freeswitch_public_conf_via_sip] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [freeswitch_public_conf_via_sip] destination_number(1001) =~
> /^\*9(888|1616|3232)$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->mad_boss_intercom] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [mad_boss_intercom] destination_number(1001) =~ /^\*0911$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->mad_boss_intercom] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [mad_boss_intercom] destination_number(1001) =~ /^\*0912$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->mad_boss]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [mad_boss]
> destination_number(1001) =~ /^\*0913$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->ivr_demo]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [ivr_demo]
> destination_number(1001) =~ /^\*5000$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->dynamic_conference] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [dynamic_conference] destination_number(1001) =~ /^\*5001$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->rtp_multicast_page] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [rtp_multicast_page] destination_number(1001) =~ /^\*pagegroup$|^\*7243/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->park]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [park]
> destination_number(1001) =~ /^\*5900$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->unpark]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [unpark]
> destination_number(1001) =~ /^\*5901$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->park]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [park]
> source(mod_sofia) =~ /mod_sofia/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [park]
> destination_number(1001) =~ /park\+(\d+)/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->unpark]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [unpark]
> source(mod_sofia) =~ /mod_sofia/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [unpark]
> destination_number(1001) =~ /^parking$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->park]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [park]
> source(mod_sofia) =~ /mod_sofia/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [park]
> destination_number(1001) =~ /callpark/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->unpark]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS) [unpark]
> source(mod_sofia) =~ /mod_sofia/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [unpark]
> destination_number(1001) =~ /pickup/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->wait]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [wait]
> destination_number(1001) =~ /^wait$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->fax_receive] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [fax_receive]
> destination_number(1001) =~ /^\*9978$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->fax_transmit] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [fax_transmit]
> destination_number(1001) =~ /^\*9979$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->ringback_180] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [ringback_180]
> destination_number(1001) =~ /^\*9980$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->ringback_183_uk_ring] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [ringback_183_uk_ring] destination_number(1001) =~ /^\*9981$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->ringback_183_music_ring] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [ringback_183_music_ring] destination_number(1001) =~ /^\*9982$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->ringback_post_answer_uk_ring] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [ringback_post_answer_uk_ring] destination_number(1001) =~ /^\*9983$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->ringback_post_answer_music] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [ringback_post_answer_music] destination_number(1001) =~ /^\*9984$/
> break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->ClueCon]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [ClueCon]
> destination_number(1001) =~ /^\*9991$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->show_info]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [show_info]
> destination_number(1001) =~ /^\*9992$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->video_record] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [video_record]
> destination_number(1001) =~ /^\*9993$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->video_playback] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [video_playback]
> destination_number(1001) =~ /^\*9994$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->delay_echo]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [delay_echo]
> destination_number(1001) =~ /^\*9995$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->echo]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [echo]
> destination_number(1001) =~ /^\*9996$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->milliwatt]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [milliwatt]
> destination_number(1001) =~ /^\*9997$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->tone_stream] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [tone_stream]
> destination_number(1001) =~ /^\*9998$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->zrtp_enrollement] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL)
> [zrtp_enrollement] destination_number(1001) =~ /^\*9787$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing [default->hold_music]
> continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (FAIL) [hold_music]
> destination_number(1001) =~ /^\*9999$/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 parsing
> [default->Local_Extension] continue=false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Regex (PASS)
> [Local_Extension] destination_number(1001) =~
> /(^\d{6}$|\d{5}$|^\d{4}$|^\d{3}$)/ break=on-false
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> set(dialed_extension=1001)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> export(dialed_extension=1001)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action bind_meta_app(1 b s
> execute_extension::dx XML features)
> Dialplan: sofia/internal/60002 at 192.168.10.30 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/60002 at 192.168.10.30 Action bind_meta_app(3 b s
> execute_extension::cf XML features)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> set(ringback=${us-ring})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> set(transfer_ringback=local_stream://moh)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action set(call_timeout=30)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> set(hangup_after_bridge=true)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> set(continue_on_fail=true)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> db(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
>
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> db(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name}
> var callgroup)})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> db(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action
> bridge(user/${dialed_extension}@${domain_name})
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action answer()
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action sleep(1000)
> Dialplan: sofia/internal/60002 at 192.168.10.30 Action voicemail(default
> ${domain_name} ${dialed_extension})
> 2010-02-09 21:49:32.798073 [DEBUG] switch_core_state_machine.c:122
> (sofia/internal/60002 at 192.168.10.30) State Change CS_ROUTING -> CS_EXECUTE
> 2010-02-09 21:49:32.798073 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:32.798073 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/60002 at 192.168.10.30) State ROUTING going to sleep
> 2010-02-09 21:49:32.798073 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/60002 at 192.168.10.30) Running State Change CS_EXECUTE
> 2010-02-09 21:49:32.798073 [DEBUG] switch_core_state_machine.c:348
> (sofia/internal/60002 at 192.168.10.30) State EXECUTE
> 2010-02-09 21:49:32.798073 [DEBUG] mod_sofia.c:181 sofia/internal/
> 60002 at 192.168.10.30 SOFIA EXECUTE
> 2010-02-09 21:49:32.798073 [DEBUG] switch_core_state_machine.c:159
> sofia/internal/60002 at 192.168.10.30 Standard EXECUTE
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(use_profile=default)
> 2010-02-09 21:49:32.798073 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [use_profile]=[default]
> EXECUTE sofia/internal/60002 at 192.168.10.30 set_user(default at 192.168.10.30)
> EXECUTE sofia/internal/60002 at 192.168.10.30db(insert/192.168.10.30-spymap/60002/66610a8c-aec9-48ca-9b67-aafdcd3e3d08)
> EXECUTE sofia/internal/60002 at 192.168.10.30db(insert/192.168.10.30-last_dial/60002/1001)
> EXECUTE sofia/internal/60002 at 192.168.10.30db(insert/192.168.10.30-last_dial/global/66610a8c-aec9-48ca-9b67-aafdcd3e3d08)
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(dialed_extension=1001)
> 2010-02-09 21:49:32.857126 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [dialed_extension]=[1001]
> EXECUTE sofia/internal/60002 at 192.168.10.30 export(dialed_extension=1001)
> 2010-02-09 21:49:32.858075 [DEBUG] mod_dptools.c:851 EXPORT
> [dialed_extension]=[1001]
> EXECUTE sofia/internal/60002 at 192.168.10.30 bind_meta_app(1 b s
> execute_extension::dx XML features)
> 2010-02-09 21:49:32.858075 [INFO] switch_ivr_async.c:2174 Bound B-Leg: 1
> execute_extension::dx XML features
> EXECUTE sofia/internal/60002 at 192.168.10.30 bind_meta_app(2 b s
> record_session::/usr/local/freeswitch/recordings/60002.2010-02-09-21-49-32.wav)
> 2010-02-09 21:49:32.858075 [INFO] switch_ivr_async.c:2174 Bound B-Leg: 2
> record_session::/usr/local/freeswitch/recordings/60002.2010-02-09-21-49-32.wav
> EXECUTE sofia/internal/60002 at 192.168.10.30 bind_meta_app(3 b s
> execute_extension::cf XML features)
> 2010-02-09 21:49:32.859074 [INFO] switch_ivr_async.c:2174 Bound B-Leg: 3
> execute_extension::cf XML features
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(ringback=%(2000, 4000,
> 440.0, 480.0))
> 2010-02-09 21:49:32.859074 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]
> EXECUTE sofia/internal/60002 at 192.168.10.30set(transfer_ringback=local_stream://moh)
> 2010-02-09 21:49:32.859074 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [transfer_ringback]=[local_stream://moh]
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(call_timeout=30)
> 2010-02-09 21:49:32.860074 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [call_timeout]=[30]
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(hangup_after_bridge=true)
> 2010-02-09 21:49:32.860074 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [hangup_after_bridge]=[true]
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(continue_on_fail=true)
> 2010-02-09 21:49:32.860074 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [continue_on_fail]=[true]
> EXECUTE sofia/internal/60002 at 192.168.10.30db(insert/192.168.10.30-call_return/1001/60002)
> EXECUTE sofia/internal/60002 at 192.168.10.30db(insert/192.168.10.30-last_dial_ext/1001/66610a8c-aec9-48ca-9b67-aafdcd3e3d08)
> EXECUTE sofia/internal/60002 at 192.168.10.30 set(called_party_callgroup=)
> 2010-02-09 21:49:32.870074 [DEBUG] mod_dptools.c:768 sofia/internal/
> 60002 at 192.168.10.30 SET [called_party_callgroup]=[UNDEF]
> EXECUTE sofia/internal/60002 at 192.168.10.30db(insert/192.168.10.30-last_dial//66610a8c-aec9-48ca-9b67-aafdcd3e3d08)
> EXECUTE sofia/internal/60002 at 192.168.10.30 bridge(user/1001 at 192.168.10.30)
> 2010-02-09 21:49:32.905073 [DEBUG] switch_ivr_originate.c:1735 variable
> string 0 = [presence_id=1001 at 192.168.10.30]
> 2010-02-09 21:49:32.905073 [NOTICE] switch_channel.c:613 New Channel
> sofia/internal/sip:1001 at 192.168.10.192:41080[df7cf235-f0e4-406a-83a5-dd2d681bb278]
> 2010-02-09 21:49:32.905073 [DEBUG] mod_sofia.c:3142 (sofia/internal/
> sip:1001 at 192.168.10.192:41080) State Change CS_NEW -> CS_INIT
> 2010-02-09 21:49:32.905073 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [BREAK]
> 2010-02-09 21:49:32.906075 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Running State Change
> CS_INIT
> 2010-02-09 21:49:32.906075 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State INIT
> 2010-02-09 21:49:32.906075 [DEBUG] mod_sofia.c:83 sofia/internal/
> sip:1001 at 192.168.10.192:41080 SOFIA INIT
> 2010-02-09 21:49:32.907184 [DEBUG] mod_sofia.c:111 (sofia/internal/
> sip:1001 at 192.168.10.192:41080) State Change CS_INIT -> CS_ROUTING
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [BREAK]
> 2010-02-09 21:49:32.907184 [DEBUG] sofia.c:3727 Channel sofia/internal/
> sip:1001 at 192.168.10.192:41080 entering state [calling][0]
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_state_machine.c:338
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State INIT going to sleep
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Running State Change
> CS_ROUTING
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State ROUTING
> 2010-02-09 21:49:32.907184 [DEBUG] mod_sofia.c:132 sofia/internal/
> sip:1001 at 192.168.10.192:41080 SOFIA ROUTING
> 2010-02-09 21:49:32.907184 [DEBUG] switch_ivr_originate.c:66
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State Change CS_ROUTING ->
> CS_CONSUME_MEDIA
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [BREAK]
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_state_machine.c:341
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State ROUTING going to
> sleep
> 2010-02-09 21:49:32.907184 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Running State Change
> CS_CONSUME_MEDIA
> 2010-02-09 21:49:33.023071 [DEBUG] switch_core_state_machine.c:360
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State CONSUME_MEDIA
> 2010-02-09 21:49:33.023071 [DEBUG] switch_core_state_machine.c:360
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State CONSUME_MEDIA going
> to sleep
> 2010-02-09 21:49:33.329319 [DEBUG] sofia.c:3727 Channel sofia/internal/
> sip:1001 at 192.168.10.192:41080 entering state [terminated][488]
> 2010-02-09 21:49:33.329319 [NOTICE] sofia.c:4331 Hangup sofia/internal/
> sip:1001 at 192.168.10.192:41080 [CS_CONSUME_MEDIA]
> [INCOMPATIBLE_DESTINATION]
> 2010-02-09 21:49:33.329319 [DEBUG] switch_channel.c:1912 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [KILL]
> 2010-02-09 21:49:33.329319 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [BREAK]
> 2010-02-09 21:49:33.329319 [DEBUG] switch_core_state_machine.c:459
> sofia/internal/sip:1001 at 192.168.10.192:41080 thread mismatch skipping
> state handler.
> 2010-02-09 21:49:33.329319 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Running State Change
> CS_HANGUP
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:488
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State HANGUP
> 2010-02-09 21:49:33.330075 [DEBUG] mod_sofia.c:352 sofia/internal/
> sip:1001 at 192.168.10.192:41080 Overriding SIP cause 488 with 488 from the
> other leg
> 2010-02-09 21:49:33.330075 [DEBUG] mod_sofia.c:358 Channel sofia/internal/
> sip:1001 at 192.168.10.192:41080 hanging up, cause: INCOMPATIBLE_DESTINATION
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:46
> sofia/internal/sip:1001 at 192.168.10.192:41080 Standard HANGUP, cause:
> INCOMPATIBLE_DESTINATION
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:488
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State HANGUP going to sleep
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:333
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State Change CS_HANGUP ->
> CS_REPORTING
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [BREAK]
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Running State Change
> CS_REPORTING
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:579
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State REPORTING
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:53
> sofia/internal/sip:1001 at 192.168.10.192:41080 Standard REPORTING, cause:
> INCOMPATIBLE_DESTINATION
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:579
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State REPORTING going to
> sleep
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_state_machine.c:327
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State Change CS_REPORTING
> -> CS_DESTROY
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/sip:1001 at 192.168.10.192:41080 [BREAK]
> 2010-02-09 21:49:33.330075 [DEBUG] switch_core_session.c:1136 Session 2
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Locked, Waiting on external
> entities
> 2010-02-09 21:49:33.331072 [DEBUG] switch_ivr_originate.c:3009 Originate
> Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
> 2010-02-09 21:49:33.331072 [NOTICE] switch_core_session.c:1154 Session 2
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Ended
> 2010-02-09 21:49:33.331072 [NOTICE] switch_core_session.c:1156 Close
> Channel sofia/internal/sip:1001 at 192.168.10.192:41080 [CS_DESTROY]
> 2010-02-09 21:49:33.331072 [DEBUG] switch_core_state_machine.c:423
> (sofia/internal/sip:1001 at 192.168.10.192:41080) Running State Change
> CS_DESTROY
> 2010-02-09 21:49:33.331072 [DEBUG] switch_core_state_machine.c:434
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State DESTROY
> 2010-02-09 21:49:33.331072 [DEBUG] mod_sofia.c:293 sofia/internal/
> sip:1001 at 192.168.10.192:41080 SOFIA DESTROY
> 2010-02-09 21:49:33.331072 [DEBUG] switch_core_state_machine.c:60
> sofia/internal/sip:1001 at 192.168.10.192:41080 Standard DESTROY
> 2010-02-09 21:49:33.331072 [DEBUG] switch_core_state_machine.c:434
> (sofia/internal/sip:1001 at 192.168.10.192:41080) State DESTROY going to
> sleep
> 2010-02-09 21:49:33.331072 [ERR] switch_ivr_originate.c:2249 Cannot create
> outgoing channel of type [user] cause: [INCOMPATIBLE_DESTINATION]
> 2010-02-09 21:49:33.331072 [DEBUG] switch_ivr_originate.c:3009 Originate
> Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
> 2010-02-09 21:49:33.331072 [INFO] mod_dptools.c:2294 Originate Failed.
> Cause: INCOMPATIBLE_DESTINATION
> EXECUTE sofia/internal/60002 at 192.168.10.30 answer()
> 2010-02-09 21:49:33.332075 [DEBUG] mod_dptools.c:658 sofia/internal/
> 60002 at 192.168.10.30 receive message [ANSWER]
> 2010-02-09 21:49:33.332075 [DEBUG] sofia_glue.c:2381 AUDIO RTP
> [sofia/internal/60002 at 192.168.10.30] 192.168.10.30 port 27634 ->
> 192.168.10.131 port 25592 codec: 9 ms: 20
> 2010-02-09 21:49:33.332075 [DEBUG] switch_rtp.c:1167 Starting timer [soft]
> 160 bytes per 20ms
> 2010-02-09 21:49:33.333080 [DEBUG] mod_sofia.c:571 Local SDP
> sofia/internal/60002 at 192.168.10.30:
> v=0
> o=FreeSWITCH 1265704739 1265704740 IN IP4 192.168.10.30
> s=FreeSWITCH
> c=IN IP4 192.168.10.30
> t=0 0
> m=audio 27634 RTP/AVP 9 101
> a=rtpmap:9 G722/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=silenceSupp:off - - - -
> a=ptime:20
> a=sendrecv
>
> 2010-02-09 21:49:33.333080 [DEBUG] sofia.c:3727 Channel sofia/internal/
> 60002 at 192.168.10.30 entering state [completed][200]
> 2010-02-09 21:49:33.333080 [DEBUG] switch_core_session.c:645 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:33.333080 [NOTICE] mod_dptools.c:658 Channel
> [sofia/internal/60002 at 192.168.10.30] has been answered
> 2010-02-09 21:49:33.333080 [DEBUG] switch_channel.c:182 sofia/internal/
> 60002 at 192.168.10.30 receive message [AUDIO_SYNC]
> EXECUTE sofia/internal/60002 at 192.168.10.30 sleep(1000)
> 2010-02-09 21:49:33.334081 [DEBUG] switch_channel.c:182 sofia/internal/
> 60002 at 192.168.10.30 receive message [AUDIO_SYNC]
> 2010-02-09 21:49:33.395069 [DEBUG] switch_rtp.c:2004 Correct ip/port
> confirmed.
> 2010-02-09 21:49:33.455069 [DEBUG] sofia.c:3727 Channel sofia/internal/
> 60002 at 192.168.10.30 entering state [ready][200]
> EXECUTE sofia/internal/60002 at 192.168.10.30 voicemail(default 192.168.10.30
> 1001)
> 2010-02-09 21:49:34.335070 [DEBUG] mod_voicemail.c:730 [default] rwlock
> 2010-02-09 21:49:34.370083 [DEBUG] switch_channel.c:182 sofia/internal/
> 60002 at 192.168.10.30 receive message [AUDIO_SYNC]
> 2010-02-09 21:49:34.475070 [DEBUG] switch_ivr_play_say.c:118 No language
> specified - Using [en]
> 2010-02-09 21:49:34.475070 [DEBUG] switch_ivr_play_say.c:273 Handle
> play-file:[voicemail/vm-person.wav] (en:en)
> 2010-02-09 21:49:34.523070 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:34.524073 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:34.526072 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:35.875063 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:35.995062 [DEBUG] switch_ivr_play_say.c:273 Handle
> say:[1001] (en:en)
> 2010-02-09 21:49:36.027062 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:36.027062 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:36.028065 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:36.455072 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:36.460061 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:36.460061 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:36.461074 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:36.995060 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:36.995060 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:36.995060 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:36.995060 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:37.535061 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:37.535061 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:37.535061 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:37.535061 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:37.995060 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:38.095060 [DEBUG] switch_ivr_play_say.c:273 Handle
> play-file:[voicemail/vm-not_available.wav] (en:en)
> 2010-02-09 21:49:38.118060 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:38.119063 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:38.120062 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:39.075057 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:39.175057 [DEBUG] switch_ivr_play_say.c:118 No language
> specified - Using [en]
> 2010-02-09 21:49:39.177086 [DEBUG] switch_ivr_play_say.c:273 Handle
> play-file:[voicemail/vm-record_message.wav] (en:en)
> 2010-02-09 21:49:39.181967 [WARNING] switch_core_file.c:177 Sample rate
> doesn't match
> 2010-02-09 21:49:39.181967 [DEBUG] switch_ivr_play_say.c:1154 Codec
> Activated L16 at 16000hz 1 channels 20ms
> 2010-02-09 21:49:39.192068 [DEBUG] switch_core_io.c:652 sofia/internal/
> 60002 at 192.168.10.30 receive message [TRANSCODING_NECESSARY]
> 2010-02-09 21:49:40.999151 [NOTICE] sofia.c:329 Hangup sofia/internal/
> 60002 at 192.168.10.30 [CS_EXECUTE] [NORMAL_CLEARING]
> 2010-02-09 21:49:40.999151 [DEBUG] switch_channel.c:1912 Send signal
> sofia/internal/60002 at 192.168.10.30 [KILL]
> 2010-02-09 21:49:40.999151 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:40.999151 [DEBUG] switch_core_state_machine.c:459
> sofia/internal/60002 at 192.168.10.30 thread mismatch skipping state handler.
> 2010-02-09 21:49:41.015049 [DEBUG] switch_ivr_play_say.c:1446 done playing
> file
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:348
> (sofia/internal/60002 at 192.168.10.30) State EXECUTE going to sleep
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/60002 at 192.168.10.30) Running State Change CS_HANGUP
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:488
> (sofia/internal/60002 at 192.168.10.30) State HANGUP
> 2010-02-09 21:49:41.114049 [DEBUG] mod_sofia.c:352 sofia/internal/
> 60002 at 192.168.10.30 Overriding SIP cause 480 with 488 from the other leg
> 2010-02-09 21:49:41.114049 [DEBUG] mod_sofia.c:358 Channel sofia/internal/
> 60002 at 192.168.10.30 hanging up, cause: NORMAL_CLEARING
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:46
> sofia/internal/60002 at 192.168.10.30 Standard HANGUP, cause: NORMAL_CLEARING
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:488
> (sofia/internal/60002 at 192.168.10.30) State HANGUP going to sleep
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:333
> (sofia/internal/60002 at 192.168.10.30) State Change CS_HANGUP ->
> CS_REPORTING
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:314
> (sofia/internal/60002 at 192.168.10.30) Running State Change CS_REPORTING
> 2010-02-09 21:49:41.114049 [DEBUG] switch_core_state_machine.c:579
> (sofia/internal/60002 at 192.168.10.30) State REPORTING
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:53
> sofia/internal/60002 at 192.168.10.30 Standard REPORTING, cause:
> NORMAL_CLEARING
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:579
> (sofia/internal/60002 at 192.168.10.30) State REPORTING going to sleep
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:327
> (sofia/internal/60002 at 192.168.10.30) State Change CS_REPORTING ->
> CS_DESTROY
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_session.c:999 Send signal
> sofia/internal/60002 at 192.168.10.30 [BREAK]
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_session.c:1136 Session 1
> (sofia/internal/60002 at 192.168.10.30) Locked, Waiting on external entities
> 2010-02-09 21:49:41.129049 [NOTICE] switch_core_session.c:1154 Session 1
> (sofia/internal/60002 at 192.168.10.30) Ended
> 2010-02-09 21:49:41.129049 [NOTICE] switch_core_session.c:1156 Close
> Channel sofia/internal/60002 at 192.168.10.30 [CS_DESTROY]
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:423
> (sofia/internal/60002 at 192.168.10.30) Running State Change CS_DESTROY
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:434
> (sofia/internal/60002 at 192.168.10.30) State DESTROY
> 2010-02-09 21:49:41.129049 [DEBUG] mod_sofia.c:293 sofia/internal/
> 60002 at 192.168.10.30 SOFIA DESTROY
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:60
> sofia/internal/60002 at 192.168.10.30 Standard DESTROY
> 2010-02-09 21:49:41.129049 [DEBUG] switch_core_state_machine.c:434
> (sofia/internal/60002 at 192.168.10.30) State DESTROY going to sleep
>
>
>
>
>
>
>
> On 9 February 2010 21:18, Brian West <brian at freeswitch.org> wrote:
>
>> What you're saying makes little or no sense to me even on 1.0.4, Can you
>> pastebin your logs?
>>
>> /b
>>
>> On Feb 9, 2010, at 3:15 PM, Bruce Hopkins wrote:
>>
>> > OK, many thanks for the extremely swift response Brian.
>> >
>> > I will try to get up and running as soon as I can with 1.0.5 and see if
>> the issue goes away.
>> >
>> > thanks again
>> > Bruce
>>
>>
>> _______________________________________________
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20100209/e2ab1b54/attachment-0002.html 