Digits not playing, strange IVR behavior

Hello all. I’m running AsteriskNow 3.0. We’ve got a PRI coming into our phone system for all inbound calls. What we’re looking to make work has never worked on this system (it’s only about a month old).

First off, the sounds don’t seem to be behaving themselves. When you normally hear “The caller at extension one zero zero or one hundred is unavailable,” you now instead hear “The caller at extension is unavailable.” Likewise, “You are caller number. Your average wait time is minutes” comes up when you’re in the queues with announcements enabled.

I’ve tried reinstalling the asterisk sounds package through yum, changing ownership/permissions on all files (chown -R/chmod 755 -R) to asterisk:asterisk/755 on all sound files. /usr/share/asterisk/sounds and /var/lib/asterisk/sounds are both valid paths to the sound files that are in question. asterisk.conf looks like:

[directories]
astetcdir => /etc/asterisk
astmoddir => /usr/lib64/asterisk/modules
astvarlibdir => /var/lib/asterisk
astagidir => /var/lib/asterisk/agi-bin
astspooldir => /var/spool/asterisk
astrundir => /var/run/asterisk
astlogdir => /var/log/asterisk

[options]
transmit_silence_during_record = yes
languageprefix=yes
execincludes=yes

These are the warnings I’m seeing in my logs:
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] pbx.c: – Executing [14@ext-queues:32] QueueLog(“Local/115@from-queue-00006f92;2”, “14,1387571659.90508,NONE,DID,0380”) in new stack
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] pbx.c: – Executing [14@ext-queues:33] Set(“Local/115@from-queue-00006f92;2”, “QAANNOUNCE=”) in new stack
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] pbx.c: – Executing [14@ext-queues:34] Set(“Local/115@from-queue-00006f92;2”, “VQ_AANNOUNCE=”) in new stack
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] pbx.c: – Executing [14@ext-queues:35] Set(“Local/115@from-queue-00006f92;2”, “QMAXWAIT=”) in new stack
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] pbx.c: – Executing [14@ext-queues:36] Set(“Local/115@from-queue-00006f92;2”, “VQ_MAXWAIT=”) in new stack
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] pbx.c: – Executing [14@ext-queues:37] Queue(“Local/115@from-queue-00006f92;2”, “14,t,”) in new stack
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] res_musiconhold.c: – Started music on hold, class ‘stream’, on channel ‘Local/115@from-queue-00006f92;2’
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] res_musiconhold.c: – Stopped music on hold on Local/115@from-queue-00006f92;2
[2013-12-20 14:35:08] VERBOSE[2259][C-000024ae] file.c: – <Local/115@from-queue-00006f92;2> Playing ‘queue-thereare.ulaw’ (language ‘en’)
[2013-12-20 14:35:09] WARNING[2259][C-000024ae] file.c: File digits/2 does not exist in any format
[2013-12-20 14:35:09] WARNING[2259][C-000024ae] file.c: Unable to open digits/2 (format (ulaw)): No such file or directory
[2013-12-20 14:35:09] VERBOSE[2259][C-000024ae] file.c: – <Local/115@from-queue-00006f92;2> Playing ‘queue-callswaiting.ulaw’ (language ‘en’)
[2013-12-20 14:35:12] VERBOSE[2259][C-000024ae] app_queue.c: – Hold time for 14 is 1 minute(s) 0 seconds
[2013-12-20 14:35:12] VERBOSE[2259][C-000024ae] file.c: – <Local/115@from-queue-00006f92;2> Playing ‘queue-holdtime.ulaw’ (language ‘en’)
[2013-12-20 14:35:14] WARNING[2259][C-000024ae] file.c: File digits/1 does not exist in any format
[2013-12-20 14:35:14] WARNING[2259][C-000024ae] file.c: Unable to open digits/1 (format (ulaw)): No such file or directory
[2013-12-20 14:35:14] VERBOSE[2259][C-000024ae] file.c: – <Local/115@from-queue-00006f92;2> Playing ‘queue-minute.ulaw’ (language ‘en’)
[2013-12-20 14:35:15] VERBOSE[2259][C-000024ae] app_queue.c: – Told Local/115@from-queue-00006f92;2 in 14 their queue position (which was 2)
[2013-12-20 14:35:15] VERBOSE[2259][C-000024ae] file.c: – <Local/115@from-queue-00006f92;2> Playing ‘queue-thankyou.ulaw’ (language ‘en’)

Secondly, we’re getting some strange behavior from our IVR. Most of the time, calls come in and get routed fine. Occasionally, someone will call up and will not get any announcement played; after the timeout period, the phone starts ringing instead of hanging up as it should. I’ve had callers say they’ve gotten random extensions’ voicemails as a result, though in my experience it just rang for a while (10-20 secs) and then gave me a busy signal. Log from one of these calls is below:

[2013-12-20 14:26:47] VERBOSE[2724][C-000024a6] sig_pri.c: – Accepting call from ‘7152049598’ to ‘0380’ on channel 0/1, span 1
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [0380@from-digital:1] NoOp(“DAHDI/i1/7152049598-2322”, “Catch-All DID Match - Found 0380 - You probably want a DID for this.”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [0380@from-digital:2] Set(“DAHDI/i1/7152049598-2322”, “__FROM_DID=0380”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [0380@from-digital:3] Goto(“DAHDI/i1/7152049598-2322”, “ext-did,s,1”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Goto (ext-did,s,1)
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:1] ExecIf(“DAHDI/i1/7152049598-2322”, “0?Set(__FROM_DID=s)”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:2] Set(“DAHDI/i1/7152049598-2322”, “CIDSFSCHEME=QUxMfEFMTA==”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:3] AGI(“DAHDI/i1/7152049598-2322”, “/var/www/html/admin/modules/superfecta/agi/superfecta.agi”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: – Launched AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta is Answering the Channel
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Scheme is ALL
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The DID passed from Asterisk is: s
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The number passed from Asterisk is: 7152049598
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: The CID name passed from Asterisk is: unknown
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Executing Scheme…
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: CID Determined to be: ‘STEVENS PT, WI’
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Attempting to set lookupcid
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: /var/www/html/admin/modules/superfecta/agi/superfecta.agi: CID Superfecta: Success!
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] res_agi.c: – <DAHDI/i1/7152049598-2322>AGI Script /var/www/html/admin/modules/superfecta/agi/superfecta.agi completed, returning 0
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:4] Set(“DAHDI/i1/7152049598-2322”, “CALLERID(name)=STEVENS PT, WI”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:5] Set(“DAHDI/i1/7152049598-2322”, “CDR(did)=0380”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:6] Gosub(“DAHDI/i1/7152049598-2322”, “cidlookup,cidlookup_2,1()”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [cidlookup_2@cidlookup:1] GotoIf(“DAHDI/i1/7152049598-2322”, “0?cidlookup,cidlookup_return,1”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [cidlookup_2@cidlookup:2] Set(“DAHDI/i1/7152049598-2322”, “DB(cidname/7152049598)=STEVENS PT, WI”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [cidlookup_2@cidlookup:3] Return(“DAHDI/i1/7152049598-2322”, “”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:7] ExecIf(“DAHDI/i1/7152049598-2322”, “0 ?Set(CALLERID(name)=7152049598)”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:8] Set(“DAHDI/i1/7152049598-2322”, “CHANNEL(musicclass)=stream”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:9] Set(“DAHDI/i1/7152049598-2322”, “__MOHCLASS=stream”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:10] Ringing(“DAHDI/i1/7152049598-2322”, “”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:11] Set(“DAHDI/i1/7152049598-2322”, “__CALLINGPRES_SV=allowed”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:12] Set(“DAHDI/i1/7152049598-2322”, “CALLERPRES()=allowed_not_screened”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ext-did:13] Goto(“DAHDI/i1/7152049598-2322”, “timeconditions,1,1”) in new stack
[2013-12-20 14:26:47] VERBOSE[32505][C-000024a6] pbx.c: – Goto (timeconditions,1,1)
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [1@timeconditions:1] GotoIf(“DAHDI/i1/7152049598-2322”, “0?truegoto”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [1@timeconditions:2] ExecIf(“DAHDI/i1/7152049598-2322”, “0?Set(DB(TC/1)=)”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [1@timeconditions:3] GotoIf(“DAHDI/i1/7152049598-2322”, “1?ivr-1,s,1”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Goto (ivr-1,s,1)
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:1] Set(“DAHDI/i1/7152049598-2322”, “_IVR_CONTEXT_ivr-1=”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:2] Set(“DAHDI/i1/7152049598-2322”, “_IVR_CONTEXT=ivr-1”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:3] Set(“DAHDI/i1/7152049598-2322”, “__IVR_RETVM=”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:4] GotoIf(“DAHDI/i1/7152049598-2322”, “0?skip”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:5] Answer(“DAHDI/i1/7152049598-2322”, “”) in new stack
[2013-12-20 14:26:48] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:6] Wait(“DAHDI/i1/7152049598-2322”, “1”) in new stack
[2013-12-20 14:26:49] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:7] Set(“DAHDI/i1/7152049598-2322”, “IVR_MSG=custom/Greeting090407”) in new stack
[2013-12-20 14:26:49] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:8] Set(“DAHDI/i1/7152049598-2322”, “TIMEOUT(digit)=3”) in new stack
[2013-12-20 14:26:49] VERBOSE[32505][C-000024a6] func_timeout.c: – Digit timeout set to 3.000
[2013-12-20 14:26:49] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:9] ExecIf(“DAHDI/i1/7152049598-2322”, “1?Background(custom/Greeting090407)”) in new stack
[2013-12-20 14:26:49] VERBOSE[32505][C-000024a6] file.c: – <DAHDI/i1/7152049598-2322> Playing ‘custom/Greeting090407.slin’ (language ‘en’)
[2013-12-20 14:27:04] VERBOSE[32505][C-000024a6] pbx.c: – Executing [s@ivr-1:10] WaitExten(“DAHDI/i1/7152049598-2322”, “10,”) in new stack
[2013-12-20 14:27:14] VERBOSE[32505][C-000024a6] pbx.c: – Timeout on DAHDI/i1/7152049598-2322, going to ‘t’
[2013-12-20 14:27:14] VERBOSE[32505][C-000024a6] pbx.c: – Executing [t@ivr-1:1] Playback(“DAHDI/i1/7152049598-2322”, “sorry-youre-having-problems”) in new stack
[2013-12-20 14:27:14] VERBOSE[32505][C-000024a6] file.c: – <DAHDI/i1/7152049598-2322> Playing ‘sorry-youre-having-problems.gsm’ (language ‘en’)
[2013-12-20 14:27:16] VERBOSE[32505][C-000024a6] pbx.c: – Executing [t@ivr-1:2] Goto(“DAHDI/i1/7152049598-2322”, “hang,1”) in new stack
[2013-12-20 14:27:16] VERBOSE[32505][C-000024a6] pbx.c: – Goto (ivr-1,hang,1)
[2013-12-20 14:27:16] VERBOSE[32505][C-000024a6] pbx.c: – Executing [hang@ivr-1:1] Playback(“DAHDI/i1/7152049598-2322”, “vm-goodbye”) in new stack
[2013-12-20 14:27:16] VERBOSE[32505][C-000024a6] file.c: – <DAHDI/i1/7152049598-2322> Playing ‘vm-goodbye.ulaw’ (language ‘en’)
[2013-12-20 14:27:17] VERBOSE[32505][C-000024a6] pbx.c: – Executing [hang@ivr-1:2] Hangup(“DAHDI/i1/7152049598-2322”, “”) in new stack
[2013-12-20 14:27:17] VERBOSE[32505][C-000024a6] pbx.c: == Spawn extension (ivr-1, hang, 2) exited non-zero on ‘DAHDI/i1/7152049598-2322’
[2013-12-20 14:27:17] VERBOSE[32505][C-000024a6] pbx.c: – Executing [h@ivr-1:1] Hangup(“DAHDI/i1/7152049598-2322”, “”) in new stack
[2013-12-20 14:27:17] VERBOSE[32505][C-000024a6] pbx.c: == Spawn extension (ivr-1, h, 1) exited non-zero on ‘DAHDI/i1/7152049598-2322’
[2013-12-20 14:27:17] VERBOSE[32505][C-000024a6] chan_dahdi.c: – Hungup ‘DAHDI/i1/7152049598-2322’

Kinda stumped now.

Hey all. Thanks for all the suggestions so far. :stuck_out_tongue:

I was able to resolve the sound issue; I needed to symlink /usr/share/asterisk/sounds to /var/lib/asterisk/sounds, and merge the files originally from /var/lib/asterisk/sounds into the linked folder. After that, I was able to hear digits playing. I’ve seen that solution before, but I thought I had already merged/copied the files I needed in; when I saw things were goofed up I implemented this and things started working. Maybe somebody can answer the more important question: Why do I have to do this?

On the strange IVR/answering behavior, I’m wondering if this scenario might cause something like that: Carrier provides echo cancellation; hardware echo cancellation is also turned on on the PRI interface card. I disabled echo cancellation by altering chan-dahdi.conf and changing echocancellation from =yes to =no.

Still accepting ideas for troubleshooting this IVR issue; I haven’t been able to test the echo cancellation part, but I will today.