Message: 5 Date: Tue, 14 Jul 2009 06:00:10 -0700 From: Michael S Collins <msc@freeswitch.org> Subject: Re: [Freeswitch-users] Get voicemail messages To: "freeswitch-users@lists.freeswitch.org" <freeswitch-users@lists.freeswitch.org> Message-ID: <4429558B-4DA5-43BF-9824-D5B407546CCB@freeswitch.org> Content-Type: text/plain; charset=us-ascii; format=flowed; delsp=yes On Jul 14, 2009, at 5:02 AM, Eli Hayun <elihayun@gmail.com> wrote:
Hi I am not using fixed xml files for the extension registration. I have LUA script to return an XML string to FS. Everything goes fine until I am trying to get the voice messages. When am entering my id, FS (or voicemail module) try to get the xml for that id, but it cant find it. My lua script did NOT recieved any xml request at that point. What should I do to solve the problem.
Thanks Eli Hayun
Can you pastebin the log? Be sure to press F8 to turn up the debug level. Here is the log ( with the XML string for the requested id (80670) freeswitch@tst-sip-srv> API CALL [console(loglevel 7)] output: +OK console log level set to DEBUG freeswitch@tst-sip-srv> 2009-07-14 16:05:15.860230 [DEBUG] sofia.c:4554 IP 132.64.4.238 Rejected by acl "domains". Falling back to Digest auth. 2009-07-14 16:05:16.88367 [DEBUG] sofia.c:4554 IP 132.64.4.238 Rejected by acl "domains". Falling back to Digest auth. -> <?xml version="1.0" encoding="UTF-8" standalone="no"?> <document type="freeswitch/xml"> <section name="directory" description="Huji Directory"> <domain name="132.64.3.86"> <params> <param name="dial-string" value="{presence_id=${dialed_user}@${dialed_domain}}${sofia_contact(${dialed_user}@${dialed_domain})}"/> </params> <user id="80670" mailbox="80670"\> <params> <param name="password" value="ph1pwd"/> <param name="vm-password" value="8670"/> <param name="vm-mailto" value="elihay@savion.huji.ac.il"/> <param name="vm-email-all-messages" value="true"/> <param name="vm-attach-file" value="true"/> </params> <variables> <variable name="accountcode" value="80670"/> <variable name="user_context" value="default"/> <variable name="max_calls" value="1"/> <variable name="effective_caller_id_name" value="n0 l0"/> </variables> </user> </domain> </section> </document> <-- 2009-07-14 16:05:16.108310 [NOTICE] switch_channel.c:602 New Channel sofia/internal/80670@132.64.3.86 [f9716554-7076-11de-9237-7d312efadfc4] 2009-07-14 16:05:16.112125 [DEBUG] sofia.c:3215 Channel sofia/internal/80670@132.64.3.86 entering state [received][100] 2009-07-14 16:05:16.112125 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/80670@132.64.3.86) Running State Change CS_NEW 2009-07-14 16:05:16.112125 [DEBUG] sofia.c:3222 Remote SDP: v=0 o=root 1385664886 1385664886 IN IP4 132.64.4.238 s=call c=IN IP4 132.64.4.238 t=0 0 m=audio 57682 RTP/AVP 0 8 9 99 3 18 4 101 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:9 g722/8000 a=rtpmap:99 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:18 g729/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=direction:both a=ptime:20 2009-07-14 16:05:16.112125 [DEBUG] sofia_glue.c:3070 Audio Codec Compare [pcmu:0:8000:20]/[G7221:115:32000:20] 2009-07-14 16:05:16.112125 [DEBUG] sofia_glue.c:3070 Audio Codec Compare [pcmu:0:8000:20]/[G7221:107:16000:20] 2009-07-14 16:05:16.112125 [DEBUG] sofia_glue.c:3070 Audio Codec Compare [pcmu:0:8000:20]/[G722:9:8000:20] 2009-07-14 16:05:16.112125 [DEBUG] sofia_glue.c:3070 Audio Codec Compare [pcmu:0:8000:20]/[PCMU:0:8000:20] 2009-07-14 16:05:16.112125 [DEBUG] sofia_glue.c:2028 Set Codec sofia/internal/80670@132.64.3.86 PCMU/8000 20 ms 160 samples 2009-07-14 16:05:16.112125 [DEBUG] sofia_glue.c:3030 Set 2833 dtmf payload to 101 2009-07-14 16:05:16.112125 [DEBUG] switch_core_state_machine.c:403 (sofia/internal/80670@132.64.3.86) State NEW 2009-07-14 16:05:16.112125 [DEBUG] sofia.c:3381 (sofia/internal/80670@132.64.3.86) State Change CS_NEW -> CS_INIT 2009-07-14 16:05:16.112125 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/80670@132.64.3.86 [BREAK] 2009-07-14 16:05:16.112125 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/80670@132.64.3.86) Running State Change CS_INIT 2009-07-14 16:05:16.116244 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/80670@132.64.3.86) State INIT 2009-07-14 16:05:16.116244 [DEBUG] mod_sofia.c:83 sofia/internal/80670@132.64.3.86 SOFIA INIT 2009-07-14 16:05:16.116244 [DEBUG] mod_sofia.c:111 (sofia/internal/80670@132.64.3.86) State Change CS_INIT -> CS_ROUTING 2009-07-14 16:05:16.116244 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/80670@132.64.3.86 [BREAK] 2009-07-14 16:05:16.116244 [DEBUG] switch_core_state_machine.c:480 (sofia/internal/80670@132.64.3.86) State INIT going to sleep 2009-07-14 16:05:16.116244 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/80670@132.64.3.86) Running State Change CS_ROUTING 2009-07-14 16:05:16.116244 [DEBUG] switch_core_state_machine.c:483 (sofia/internal/80670@132.64.3.86) State ROUTING 2009-07-14 16:05:16.116244 [DEBUG] mod_sofia.c:130 sofia/internal/80670@132.64.3.86 SOFIA ROUTING 2009-07-14 16:05:16.116244 [DEBUG] switch_core_state_machine.c:78 sofia/internal/80670@132.64.3.86 Standard ROUTING 2009-07-14 16:05:16.116244 [INFO] mod_dialplan_xml.c:252 Processing phone-1->*98 in context default Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->unloop] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->tod_example] continue=true Dialplan: sofia/internal/80670@132.64.3.86 Regex (PASS) [tod_example] ${strftime(%w)}(2) =~ /^([1-5])$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 Regex (PASS) [tod_example] ${strftime(%H%M)}(1605) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 Action set(open=true) Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [global-intercept] destination_number(*98) =~ /^886$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [group-intercept] destination_number(*98) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [intercept-ext] destination_number(*98) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->redial] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [redial] destination_number(*98) =~ /^870$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->global] continue=true Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/80670@132.64.3.86 Absolute Condition [global] Dialplan: sofia/internal/80670@132.64.3.86 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/80670@132.64.3.86 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/80670@132.64.3.86 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [snom-demo-2] destination_number(*98) =~ /^9001$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [snom-demo-1] destination_number(*98) =~ /^9000$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [eavesdrop] destination_number(*98) =~ /^88(.*)$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [eavesdrop] destination_number(*98) =~ /^779$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->call_return] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [call_return] destination_number(*98) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->del-group] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [del-group] destination_number(*98) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->add-group] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [add-group] destination_number(*98) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [call-group-simo] destination_number(*98) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [call-group-order] destination_number(*98) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [extension-intercom] destination_number(*98) =~ /^(8888)$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [Local_Extension] destination_number(*98) =~ /^(80\d{3})$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->group_dial_sales] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [group_dial_sales] destination_number(*98) =~ /^2000$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->group_dial_support] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [group_dial_support] destination_number(*98) =~ /^2001$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->group_dial_billing] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [group_dial_billing] destination_number(*98) =~ /^2002$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->operator] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (FAIL) [operator] destination_number(*98) =~ /^(operator|0)$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 parsing [default->vmain] continue=false Dialplan: sofia/internal/80670@132.64.3.86 Regex (PASS) [vmain] destination_number(*98) =~ /^vmain$|^86111$|^\*98$/ break=on-false Dialplan: sofia/internal/80670@132.64.3.86 Action answer() Dialplan: sofia/internal/80670@132.64.3.86 Action sleep(1000) Dialplan: sofia/internal/80670@132.64.3.86 Action voicemail(check default ${domain_name} ${caller_id_number}) 2009-07-14 16:05:16.120891 [DEBUG] switch_core_state_machine.c:114 (sofia/internal/80670@132.64.3.86) State Change CS_ROUTING -> CS_EXECUTE 2009-07-14 16:05:16.120891 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/80670@132.64.3.86 [BREAK] 2009-07-14 16:05:16.120891 [DEBUG] switch_core_state_machine.c:483 (sofia/internal/80670@132.64.3.86) State ROUTING going to sleep 2009-07-14 16:05:16.120891 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/80670@132.64.3.86) Running State Change CS_EXECUTE 2009-07-14 16:05:16.120891 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/80670@132.64.3.86) State EXECUTE 2009-07-14 16:05:16.120891 [DEBUG] mod_sofia.c:173 sofia/internal/80670@132.64.3.86 SOFIA EXECUTE 2009-07-14 16:05:16.120891 [DEBUG] switch_core_state_machine.c:151 sofia/internal/80670@132.64.3.86 Standard EXECUTE EXECUTE sofia/internal/80670@132.64.3.86 set(open=true) 2009-07-14 16:05:16.120891 [DEBUG] mod_dptools.c:748 sofia/internal/80670@132.64.3.86 SET [open]=[true] EXECUTE sofia/internal/80670@132.64.3.86 hash(insert/132.64.3.86-spymap/80670/f9716554-7076-11de-9237-7d312efadfc4) EXECUTE sofia/internal/80670@132.64.3.86 hash(insert/132.64.3.86-last_dial/80670/*98) EXECUTE sofia/internal/80670@132.64.3.86 hash(insert/132.64.3.86-last_dial/global/f9716554-7076-11de-9237-7d312efadfc4) EXECUTE sofia/internal/80670@132.64.3.86 answer() 2009-07-14 16:05:16.124221 [DEBUG] mod_dptools.c:649 sofia/internal/80670@132.64.3.86 receive message [ANSWER] 2009-07-14 16:05:16.124221 [DEBUG] sofia_glue.c:2262 AUDIO RTP [sofia/internal/80670@132.64.3.86] 132.64.3.86 port 31372 -> 132.64.4.238 port 57682 codec: 0 ms: 20 2009-07-14 16:05:16.124221 [DEBUG] switch_rtp.c:1138 Starting timer [soft] 160 bytes per 20ms 2009-07-14 16:05:16.138142 [DEBUG] mod_sofia.c:549 Local SDP sofia/internal/80670@132.64.3.86: v=0 o=FreeSWITCH 1247545344 1247545345 IN IP4 132.64.3.86 s=FreeSWITCH c=IN IP4 132.64.3.86 t=0 0 m=audio 31372 RTP/AVP 0 101 a=rtpmap:0 pcmu/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2009-07-14 16:05:16.138142 [DEBUG] switch_core_session.c:630 Send signal sofia/internal/80670@132.64.3.86 [BREAK] 2009-07-14 16:05:16.138142 [NOTICE] mod_dptools.c:649 Channel [sofia/internal/80670@132.64.3.86] has been answered 2009-07-14 16:05:16.138142 [DEBUG] switch_channel.c:182 sofia/internal/80670@132.64.3.86 receive message [AUDIO_SYNC] EXECUTE sofia/internal/80670@132.64.3.86 sleep(1000) 2009-07-14 16:05:16.138142 [DEBUG] switch_channel.c:182 sofia/internal/80670@132.64.3.86 receive message [AUDIO_SYNC] 2009-07-14 16:05:16.138142 [DEBUG] sofia.c:3215 Channel sofia/internal/80670@132.64.3.86 entering state [completed][200] 2009-07-14 16:05:16.216623 [DEBUG] sofia.c:3215 Channel sofia/internal/80670@132.64.3.86 entering state [ready][200] EXECUTE sofia/internal/80670@132.64.3.86 voicemail(check default 132.64.3.86 80670) 2009-07-14 16:05:17.148904 [DEBUG] mod_voicemail.c:776 [default] rwlock 2009-07-14 16:05:17.148904 [DEBUG] switch_ivr_play_say.c:118 No language specified - Using [en] 2009-07-14 16:05:17.152174 [DEBUG] switch_ivr_play_say.c:273 Handle play-file:[voicemail/vm-hello.wav] (en:en) 2009-07-14 16:05:17.152174 [DEBUG] switch_ivr_play_say.c:1097 Codec Activated L16@8000hz 1 channels 20ms 2009-07-14 16:05:17.152174 [DEBUG] switch_core_io.c:649 sofia/internal/80670@132.64.3.86 receive message [TRANSCODING_NECESSARY] 2009-07-14 16:05:18.368781 [DEBUG] switch_ivr_play_say.c:1391 done playing file 2009-07-14 16:05:18.488598 [DEBUG] switch_channel.c:182 sofia/internal/80670@132.64.3.86 receive message [AUDIO_SYNC] 2009-07-14 16:05:18.608382 [DEBUG] switch_channel.c:182 sofia/internal/80670@132.64.3.86 receive message [AUDIO_SYNC] 2009-07-14 16:05:18.708720 [WARNING] mod_voicemail.c:2072 Can't find user [80670@132.64.3.86] 2009-07-14 16:05:18.708720 [DEBUG] switch_ivr_play_say.c:118 No language specified - Using [en] 2009-07-14 16:05:18.712630 [DEBUG] switch_ivr_play_say.c:273 Handle play-file:[voicemail/vm-goodbye.wav] (en:en) 2009-07-14 16:05:18.712630 [DEBUG] switch_ivr_play_say.c:1097 Codec Activated L16@8000hz 1 channels 20ms 2009-07-14 16:05:18.712630 [DEBUG] switch_core_io.c:649 sofia/internal/80670@132.64.3.86 receive message [TRANSCODING_NECESSARY] 2009-07-14 16:05:19.188996 [DEBUG] switch_ivr_play_say.c:1391 done playing file 2009-07-14 16:05:19.308974 [NOTICE] switch_core_state_machine.c:179 Hangup sofia/internal/80670@132.64.3.86 [CS_EXECUTE] [NORMAL_CLEARING] 2009-07-14 16:05:19.308974 [DEBUG] switch_channel.c:1683 Send signal sofia/internal/80670@132.64.3.86 [KILL] 2009-07-14 16:05:19.308974 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/80670@132.64.3.86 [BREAK] 2009-07-14 16:05:19.308974 [DEBUG] switch_core_state_machine.c:490 (sofia/internal/80670@132.64.3.86) State EXECUTE going to sleep 2009-07-14 16:05:19.308974 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/80670@132.64.3.86) Running State Change CS_HANGUP 2009-07-14 16:05:19.308974 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/80670@132.64.3.86) State HANGUP 2009-07-14 16:05:19.308974 [DEBUG] mod_sofia.c:338 Channel sofia/internal/80670@132.64.3.86 hanging up, cause: NORMAL_CLEARING 2009-07-14 16:05:19.308974 [DEBUG] mod_sofia.c:393 Sending BYE to sofia/internal/80670@132.64.3.86 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:46 sofia/internal/80670@132.64.3.86 Standard HANGUP, cause: NORMAL_CLEARING 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/80670@132.64.3.86) State HANGUP going to sleep 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:475 (sofia/internal/80670@132.64.3.86) State Change CS_HANGUP -> CS_REPORTING 2009-07-14 16:05:19.312163 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/80670@132.64.3.86 [BREAK] 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:397 (sofia/internal/80670@132.64.3.86) Running State Change CS_REPORTING 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:607 (sofia/internal/80670@132.64.3.86) State REPORTING 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:53 sofia/internal/80670@132.64.3.86 Standard REPORTING, cause: NORMAL_CLEARING 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:607 (sofia/internal/80670@132.64.3.86) State REPORTING going to sleep 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/80670@132.64.3.86) State Change CS_REPORTING -> CS_DESTROY 2009-07-14 16:05:19.312163 [DEBUG] switch_core_session.c:1067 Session 7 (sofia/internal/80670@132.64.3.86) Locked, Waiting on external entities 2009-07-14 16:05:19.312163 [NOTICE] switch_core_session.c:1085 Session 7 (sofia/internal/80670@132.64.3.86) Ended 2009-07-14 16:05:19.312163 [NOTICE] switch_core_session.c:1087 Close Channel sofia/internal/80670@132.64.3.86 [CS_DESTROY] 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:559 (sofia/internal/80670@132.64.3.86) State DESTROY 2009-07-14 16:05:19.312163 [DEBUG] mod_sofia.c:255 sofia/internal/80670@132.64.3.86 SOFIA DESTROY 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:60 sofia/internal/80670@132.64.3.86 Standard DESTROY 2009-07-14 16:05:19.312163 [DEBUG] switch_core_state_machine.c:559 (sofia/internal/80670@132.64.3.86) State DESTROY going to sleep - Thanks Eli Hayun