Re: [Freeswitch-users] Freeswitch-users Digest, Vol 37, Issue 75

14 Jul 2009

      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

Eli Hayun

tags

participants (1)