Voicemail hangs up after greeting

error · January 15, 2008, 9:44pm

I just upgraded to asterisk-1.4.17 and freepbx-2.3.1.3. I was previously running 1.4.4 and 2.2.2 respectively.

Now, when someone gets to voicemail, the unavailable greeting plays, but Allison doesn’t come on to tell people to leave a message. Instead, the system hangs up. I am not (yet) using VmX. I literally just upgraded and haven’t altered any of my (previously) working configs.

This is what I see on console (it’s kind of long; the interesting stuff is at the bottom, but I include it for completeness). Where do I start with this?!

-- Accepting AUTHENTICATED call from 64.2.142.28:
   > requested format = ulaw,
   > requested prefs = (),
   > actual format = ulaw,
   > host prefs = (ulaw|alaw|gsm),
   > priority = mine
-- Executing [6032064321@from-pstn:1] Set("IAX2/vitel-inbound-11", "__FROM_DID=6032064321") in new stack
-- Executing [6032064321@from-pstn:2] Gosub("IAX2/vitel-inbound-11", "cidlookup|cidlookup_1|1") in new stack
-- Executing [cidlookup_1@cidlookup:1] LookupCIDName("IAX2/vitel-inbound-11", "") in new stack
-- Executing [cidlookup_1@cidlookup:2] Return("IAX2/vitel-inbound-11", "") in new stack
-- Executing [6032064321@from-pstn:3] Gosub("IAX2/vitel-inbound-11", "app-blacklist-check|s|1") in new stack
-- Executing [s@app-blacklist-check:1] LookupBlacklist("IAX2/vitel-inbound-11", "") in new stack
-- Executing [s@app-blacklist-check:2] GotoIf("IAX2/vitel-inbound-11", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:3] Return("IAX2/vitel-inbound-11", "") in new stack
-- Executing [6032064321@from-pstn:4] GotoIf("IAX2/vitel-inbound-11", "1 ?cidok") in new stack
-- Goto (from-pstn,6032064321,6)
-- Executing [6032064321@from-pstn:6] NoOp("IAX2/vitel-inbound-11", "CallerID is "Cell Phone   NH" <6032649104>") in new stack
-- Executing [6032064321@from-pstn:7] Macro("IAX2/vitel-inbound-11", "privacy-mgr|") in new stack
-- Executing [s@macro-privacy-mgr:1] Set("IAX2/vitel-inbound-11", "KEEPCID=6032649104") in new stack
-- Executing [s@macro-privacy-mgr:2] GotoIf("IAX2/vitel-inbound-11", "0?CIDTEST2:CIDTEST1") in new stack
-- Goto (macro-privacy-mgr,s,3)
-- Executing [s@macro-privacy-mgr:3] Set("IAX2/vitel-inbound-11", "TESTCID=6032649105.000000") in new stack
-- Executing [s@macro-privacy-mgr:4] Goto("IAX2/vitel-inbound-11", "TESTRESULT") in new stack
-- Goto (macro-privacy-mgr,s,6)
-- Executing [s@macro-privacy-mgr:6] GotoIf("IAX2/vitel-inbound-11", "0?CLEARCID:PRIVMGR") in new stack
-- Goto (macro-privacy-mgr,s,8)
-- Executing [s@macro-privacy-mgr:8] PrivacyManager("IAX2/vitel-inbound-11", "") in new stack
-- CallerID Present: Skipping
-- Executing [s@macro-privacy-mgr:9] GotoIf("IAX2/vitel-inbound-11", "0?fail") in new stack
-- Executing [s@macro-privacy-mgr:10] SetCallerPres("IAX2/vitel-inbound-11", "allowed_passed_screen") in new stack
-- Executing [6032064321@from-pstn:8] Goto("IAX2/vitel-inbound-11", "from-did-direct|16032064321|1") in new stack
-- Goto (from-did-direct,16032064321,1)
-- Executing [16032064321@from-did-direct:1] GotoIf("IAX2/vitel-inbound-11", "1?ext-local|16032064321|1") in new stack
-- Goto (ext-local,16032064321,1)
-- Executing [16032064321@ext-local:1] Macro("IAX2/vitel-inbound-11", "exten-vm|16032064321|16032064321") in new stack
-- Executing [s@macro-exten-vm:1] Macro("IAX2/vitel-inbound-11", "user-callerid") in new stack
-- Executing [s@macro-user-callerid:1] NoOp("IAX2/vitel-inbound-11", "user-callerid: Cell Phone   NH 6032649104") in new stack
-- Executing [s@macro-user-callerid:2] Set("IAX2/vitel-inbound-11", "AMPUSER=6032649104") in new stack
-- Executing [s@macro-user-callerid:3] GotoIf("IAX2/vitel-inbound-11", "0?report") in new stack
-- Executing [s@macro-user-callerid:4] GotoIf("IAX2/vitel-inbound-11", "0?start") in new stack
-- Executing [s@macro-user-callerid:5] Set("IAX2/vitel-inbound-11", "REALCALLERIDNUM=6032649104") in new stack
-- Executing [s@macro-user-callerid:6] NoOp("IAX2/vitel-inbound-11", "REALCALLERIDNUM is 6032649104") in new stack
-- Executing [s@macro-user-callerid:7] Set("IAX2/vitel-inbound-11", "AMPUSER=") in new stack
-- Executing [s@macro-user-callerid:8] Set("IAX2/vitel-inbound-11", "AMPUSERCIDNAME=") in new stack
-- Executing [s@macro-user-callerid:9] GotoIf("IAX2/vitel-inbound-11", "1?report") in new stack
-- Goto (macro-user-callerid,s,13)
-- Executing [s@macro-user-callerid:13] NoOp("IAX2/vitel-inbound-11", "TTL:  ARG1: 16032064321") in new stack
-- Executing [s@macro-user-callerid:14] GotoIf("IAX2/vitel-inbound-11", "0?continue") in new stack
-- Executing [s@macro-user-callerid:15] Set("IAX2/vitel-inbound-11", "__TTL=64") in new stack
-- Executing [s@macro-user-callerid:16] GotoIf("IAX2/vitel-inbound-11", "1?continue") in new stack
-- Goto (macro-user-callerid,s,23)
-- Executing [s@macro-user-callerid:23] NoOp("IAX2/vitel-inbound-11", "Using CallerID "Cell Phone   NH" <6032649104>") in new stack
-- Executing [s@macro-exten-vm:2] Set("IAX2/vitel-inbound-11", "FROMCONTEXT=exten-vm") in new stack
-- Executing [s@macro-exten-vm:3] Set("IAX2/vitel-inbound-11", "VMBOX=16032064321") in new stack
-- Executing [s@macro-exten-vm:4] Set("IAX2/vitel-inbound-11", "EXTTOCALL=16032064321") in new stack
-- Executing [s@macro-exten-vm:5] Set("IAX2/vitel-inbound-11", "CFUEXT=") in new stack
-- Executing [s@macro-exten-vm:6] Set("IAX2/vitel-inbound-11", "CFBEXT=") in new stack
-- Executing [s@macro-exten-vm:7] Set("IAX2/vitel-inbound-11", "RT=30") in new stack
-- Executing [s@macro-exten-vm:8] Macro("IAX2/vitel-inbound-11", "record-enable|16032064321|IN") in new stack
-- Executing [s@macro-record-enable:1] GotoIf("IAX2/vitel-inbound-11", "0?2:4") in new stack
-- Goto (macro-record-enable,s,4)
-- Executing [s@macro-record-enable:4] AGI("IAX2/vitel-inbound-11", "recordingcheck|20080115-165706|1200434226.27") in new stack
-- Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck

recordingcheck|20080115-165706|1200434226.27: Inbound recording not enabled
– AGI Script recordingcheck completed, returning 0
– Executing [s@macro-record-enable:5] NoOp(“IAX2/vitel-inbound-11”, “No recording needed”) in new stack
– Executing [s@macro-exten-vm:9] Macro(“IAX2/vitel-inbound-11”, “dial|30|tr|16032064321”) in new stack
– Executing [s@macro-dial:1] GotoIf(“IAX2/vitel-inbound-11”, “1?dial”) in new stack
– Goto (macro-dial,s,3)
– Executing [s@macro-dial:3] AGI(“IAX2/vitel-inbound-11”, “dialparties.agi”) in new stack
– Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager_additional.conf’: Found
== Parsing ‘/etc/asterisk/manager_custom.conf’: Found
== Manager ‘admin’ logged on from 127.0.0.1
dialparties.agi: Caller ID name is ‘Cell Phone NH’ number is '6032649104’
dialparties.agi: USE_CONFIRMATION: 'FALSE’
dialparties.agi: RINGGROUP_INDEX: ''
dialparties.agi: Methodology of ring is ‘none’
– dialparties.agi: Added extension 16032064321 to extension map
– dialparties.agi: Extension 16032064321 cf is disabled
– dialparties.agi: Extension 16032064321 do not disturb is disabled
> dialparties.agi: extnum 16032064321 has: cw: 1; hascfb: 0 [] hascfu: 0 []
> dialparties.agi: ExtensionState: 0
– dialparties.agi: dbset CALLTRACE/16032064321 to 6032649104
== Manager ‘admin’ logged off from 127.0.0.1
– AGI Script dialparties.agi completed, returning 0
– Executing [s@macro-dial:10] Dial(“IAX2/vitel-inbound-11”, “SIP/16032064321|30|tr”) in new stack
– Called 16032064321
– SIP/16032064321-089a9428 is ringing
– Nobody picked up in 30000 ms
– Executing [s@macro-dial:11] Set(“IAX2/vitel-inbound-11”, “DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-exten-vm:10] Set(“IAX2/vitel-inbound-11”, “SV_DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-exten-vm:11] GosubIf(“IAX2/vitel-inbound-11”, “0?docfu|1”) in new stack
– Executing [s@macro-exten-vm:12] GosubIf(“IAX2/vitel-inbound-11”, “0?docfb|1”) in new stack
– Executing [s@macro-exten-vm:13] Set(“IAX2/vitel-inbound-11”, “DIALSTATUS=NOANSWER”) in new stack
– Executing [s@macro-exten-vm:14] NoOp(“IAX2/vitel-inbound-11”, “Voicemail is 16032064321”) in new stack
– Executing [s@macro-exten-vm:15] GotoIf(“IAX2/vitel-inbound-11”, “0?s-NOANSWER|1”) in new stack
– Executing [s@macro-exten-vm:16] NoOp(“IAX2/vitel-inbound-11”, “Sending to Voicemail box 16032064321”) in new stack
– Executing [s@macro-exten-vm:17] Macro(“IAX2/vitel-inbound-11”, “vm|16032064321|NOANSWER”) in new stack
– Executing [s@macro-vm:1] Macro(“IAX2/vitel-inbound-11”, “user-callerid|SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:1] NoOp(“IAX2/vitel-inbound-11”, “user-callerid: Cell Phone NH 6032649104”) in new stack
– Executing [s@macro-user-callerid:2] Set(“IAX2/vitel-inbound-11”, “AMPUSER=6032649104”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“IAX2/vitel-inbound-11”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] GotoIf(“IAX2/vitel-inbound-11”, “1?start”) in new stack
– Goto (macro-user-callerid,s,6)
– Executing [s@macro-user-callerid:6] NoOp(“IAX2/vitel-inbound-11”, “REALCALLERIDNUM is 6032649104”) in new stack
– Executing [s@macro-user-callerid:7] Set(“IAX2/vitel-inbound-11”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:8] Set(“IAX2/vitel-inbound-11”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:9] GotoIf(“IAX2/vitel-inbound-11”, “1?report”) in new stack
– Goto (macro-user-callerid,s,13)
– Executing [s@macro-user-callerid:13] NoOp(“IAX2/vitel-inbound-11”, “TTL: 64 ARG1: SKIPTTL”) in new stack
– Executing [s@macro-user-callerid:14] GotoIf(“IAX2/vitel-inbound-11”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,23)
– Executing [s@macro-user-callerid:23] NoOp(“IAX2/vitel-inbound-11”, “Using CallerID “Cell Phone NH” <6032649104>”) in new stack
– Executing [s@macro-vm:2] Set(“IAX2/vitel-inbound-11”, “VMGAIN=”"") in new stack
– Executing [s@macro-vm:3] GotoIf(“IAX2/vitel-inbound-11”, “1?vmx|1”) in new stack
– Goto (macro-vm,vmx,1)
– Executing [vmx@macro-vm:1] GotoIf(“IAX2/vitel-inbound-11”, “0?s-NOANSWER|1”) in new stack
– Executing [vmx@macro-vm:2] Set(“IAX2/vitel-inbound-11”, “MODE=unavail”) in new stack
– Executing [vmx@macro-vm:3] GotoIf(“IAX2/vitel-inbound-11”, “1?notdirect”) in new stack
– Goto (macro-vm,vmx,5)
– Executing [vmx@macro-vm:5] NoOp(“IAX2/vitel-inbound-11”, "Checking if ext 16032064321 is enabled: ") in new stack
– Executing [vmx@macro-vm:6] GotoIf(“IAX2/vitel-inbound-11”, “1?s-NOANSWER|1”) in new stack
– Goto (macro-vm,s-NOANSWER,1)
– Executing [s-NOANSWER@macro-vm:1] Macro(“IAX2/vitel-inbound-11”, “get-vmcontext|16032064321”) in new stack
– Executing [s@macro-get-vmcontext:1] Set(“IAX2/vitel-inbound-11”, “VMCONTEXT=default”) in new stack
– Executing [s@macro-get-vmcontext:2] GotoIf(“IAX2/vitel-inbound-11”, “0?200:300”) in new stack
– Goto (macro-get-vmcontext,s,300)
– Executing [s@macro-get-vmcontext:300] NoOp(“IAX2/vitel-inbound-11”, “”) in new stack
– Executing [s-NOANSWER@macro-vm:2] VoiceMail(“IAX2/vitel-inbound-11”, “16032064321@default|u”) in new stack
– <IAX2/vitel-inbound-11> Playing ‘/var/spool/asterisk/voicemail/default/16032064321/unavail’ (language ‘en’)
== Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘IAX2/vitel-inbound-11’ in macro ‘vm’
== Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘IAX2/vitel-inbound-11’ in macro ‘exten-vm’
== Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on ‘IAX2/vitel-inbound-11’
– Hungup ‘IAX2/vitel-inbound-11’

error · January 16, 2008, 5:18am

OK, I got into the /var/log/asterisk/full file (why didn’t I think of that before?) and found the apparent problem:

[Jan 15 17:14:19] WARNING[14163] file.c: File vm-intro does not exist in any format
[Jan 15 17:14:19] WARNING[14163] file.c: Unable to open vm-intro (format 0x4 (ulaw)): No such file or directory

Now the only problem with THAT is that as far as I know, I HAVE those files!

ls /var/lib/asterisk/sounds/vm-intro*

/var/lib/asterisk/sounds/vm-intro.alaw
/var/lib/asterisk/sounds/vm-intro.g722
/var/lib/asterisk/sounds/vm-intro.g729
/var/lib/asterisk/sounds/vm-intro.gsm
/var/lib/asterisk/sounds/vm-intro.ulaw
/var/lib/asterisk/sounds/vm-intro.wav

Is asterisk expecting them to be somewhere else, perhaps?

error · January 16, 2008, 6:15pm

I got desperate enough to fix this that I spent half an hour digging around in the asterisk source code. I eventually found that * was looking in the astdatadir, which was set as /usr/share/asterisk. One symlink later and I’m back in business.