IVR and Queue Problem: Can't get to queues reliably from IVR

Peri · July 16, 2007, 11:24am

I hope the topic is descriptive enough to get people in here.

Here’s some background
I’m running Freepbx 2.2.2 on Asterisk 1.2.21.1 (was 2.2.1 and 1.2.16 when the problem first arose, upgrading didn’t resolve it).
Was running the system for over a month without any changes.

Under normal circumstances here’s how it works

A call comes in, hits the reception ring group which is set to a ringall strat and has 2 extensions.
Failover on non-answer goes to the main IVR with a menu of 8 options, 3 of which direct to queues.
Selecting a queue would normally toss the Queue Welcome Message at you then dump you in the queue with the horrible hold music where you’d wait until your call was answered.

Last Thursday things started breaking down at step 4. Now when you hit a menu option that’s supposed to put you into a queue you get the welcome message, then are promptly dumped back to the main IVR (where step 2 would send you).

The logs aren’t very useful as apparently all info about calls that hit this problem stops being collected as soon as the main IVR is played. Though the hangup at the end of the call (regardless of how many times you’ve looped or how much time you’ve sat there) seems to register to the log and CLI.

To make matters worse, some calls go through the IVR just fine. And in some cases while you’re looping you’re still apparently in queue, as an agent for that queue can have you ring through to their phone.

I’ve tried rolling back to a backup from a week before with no change.

Let me know if you need any clarification or more data.

Peri · July 16, 2007, 11:44am

Small Addendum If someone answers a reception phone and manually transfers the caller to the queue, it works.

plindheimer · July 16, 2007, 12:11pm

If going back through the ivr config, and resubmitting it after careful review, and then going over the queue configs and resubmitting each of them after careful review - does not get it back online, then it sounds like you are going to need to get someone online to your system to review and isolate what is going on - unless you have the patience to start posting cli traces and waiting for others to help review the situation.

try the first steps and see where that takes you.

Peri · July 16, 2007, 12:32pm

Thanks for the idea p_lindheimer, unfortunately resubmitting the configurations doesn’t appear to have done much.

As you can see below the CLI output doesn’t show much. All I’ve done is mask a few numbers, this is the CLI output with a verbose level of 10 for the entire duration of a call.

[code:1] – Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “FROM_DID=905XXXXXXX”) in new stack
– Executing Gosub(“SIP/66.14x.xxx.xxx-0822a6a0”, “app-blacklist-check|s|1”) in new stack
– Executing LookupBlacklist(“SIP/66.14x.xxx.xxx-0822a6a0”, “”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “0?blacklisted”) in new stack
– Executing Return(“SIP/66.14x.xxx.xxx-0822a6a0”, “”) in new stack
– Executing Goto(“SIP/66.14x.xxx.xxx-0822a6a0”, “timeconditions|7|1”) in new stack
– Goto (timeconditions,7,1)
– Executing GotoIfTime(“SIP/66.14x.xxx.xxx-0822a6a0”, “12:00-17:00||1|jul?ivr-7|s|1") in new stack
– Executing Goto(“SIP/66.14x.xxx.xxx-0822a6a0”, “timeconditions|6|1”) in new stack
– Goto (timeconditions,6,1)
– Executing GotoIfTime(“SIP/66.14x.xxx.xxx-0822a6a0”, "||1|jul?ext-miscdests|5|1") in new stack
– Executing Goto(“SIP/66.14x.xxx.xxx-0822a6a0”, “timeconditions|5|1”) in new stack
– Goto (timeconditions,5,1)
– Executing GotoIfTime(“SIP/66.14x.xxx.xxx-0822a6a0”, "10:00-17:50|sun||?ivr-7|s|1") in new stack
– Executing Goto(“SIP/66.14x.xxx.xxx-0822a6a0”, “timeconditions|4|1”) in new stack
– Goto (timeconditions,4,1)
– Executing GotoIfTime(“SIP/66.14x.xxx.xxx-0822a6a0”, "08:00-19:50|sat||?ivr-7|s|1") in new stack
– Executing Goto(“SIP/66.14x.xxx.xxx-0822a6a0”, “timeconditions|2|1”) in new stack
– Goto (timeconditions,2,1)
– Executing GotoIfTime(“SIP/66.14x.xxx.xxx-0822a6a0”, "08:30-17:50|mon-fri||*?ext-group|500|1”) in new stack
– Goto (ext-group,500,1)
– Executing Macro(“SIP/66.14x.xxx.xxx-0822a6a0”, “user-callerid|”) in new stack
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, “user-callerid: 416881XXXX”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “0?report”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “0?start”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “REALCALLERIDNUM=416881XXXX”) in new stack
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, “REALCALLERIDNUM is 416881XXXX”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “AMPUSER=”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “AMPUSERCIDNAME=”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “1?report”) in new stack
– Goto (macro-user-callerid,s,11)
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, "TTL: ARG1: ") in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “0?continue”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “_TTL=64”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,21)
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, “Using CallerID “” <416881XXXX>”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “1?skipdb”) in new stack
– Goto (ext-group,500,4)
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “__NODEST=”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “__BLKVM_OVERRIDE=BLKVM/500/SIP/66.14x.xxx.xxx-0822a6a0”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “__BLKVM_BASE=500”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “DB(BLKVM/500/SIP/66.14x.xxx.xxx-0822a6a0)=TRUE”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “RRNODEST=”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “__NODEST=500”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “1?REPCID”) in new stack
– Goto (ext-group,500,15)
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, "CALLERID(name) is ") in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “RecordMethod=Group”) in new stack
– Executing Macro(“SIP/66.14x.xxx.xxx-0822a6a0”, “record-enable|221-224|Group”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “0?2:4”) in new stack
– Goto (macro-record-enable,s,4)
– Executing DeadAGI(“SIP/66.14x.xxx.xxx-0822a6a0”, “recordingcheck|20070716-142118|1184610078.2898”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
– AGI Script recordingcheck completed, returning 0
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, “No recording needed”) in new stack
– Executing Set(“SIP/66.14x.xxx.xxx-0822a6a0”, “RingGroupMethod=ringall”) in new stack
– Executing Macro(“SIP/66.14x.xxx.xxx-0822a6a0”, “dial|15|Ttrw|221-224”) in new stack
– Executing DeadAGI(“SIP/66.14x.xxx.xxx-0822a6a0”, “dialparties.agi”) in new stack
– Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
dialparties.agi: Starting New Dialparties.agi
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager_custom.conf’: Found
== Manager ‘admin’ logged on from 127.0.0.1
dialparties.agi: priority is 1
dialparties.agi: Caller ID name is ‘unknown’ number is ‘416881XXXX’
> dialparties.agi: USE_CONFIRMATION: ‘FALSE’
> dialparties.agi: RINGGROUP_INDEX: ''
dialparties.agi: Methodology of ring is ‘ringall’
– dialparties.agi: Added extension 221 to extension map
– dialparties.agi: Added extension 224 to extension map
– dialparties.agi: Extension 221 cf is disabled
– dialparties.agi: Extension 224 cf is disabled
– dialparties.agi: Extension 221 do not disturb is disabled
dialparties.agi: Extension 224 has do not disturb enabled, or followme pre-ring returned busy
> dialparties.agi: extnum: 221
> dialparties.agi: exthascw: 0
> dialparties.agi: exthascfb: 0
> dialparties.agi: extcfb:
> dialparties.agi: exthascfu: 1
> dialparties.agi: extcfu: 19
> dialparties.agi: ExtensionState: 0
dialparties.agi: Extension 221 has ExtensionState: 0
– dialparties.agi: Checking CW and CFB status for extension 221
– dialparties.agi: dbset CALLTRACE/221 to 416881XXXX
> dialparties.agi: NODEST: 500 adding M(auto-blkvm) to dialopts: TtrwM(auto-blkvm)
> dialparties.agi: NODEST: 500 blkvm enabled macro already in dialopts: TtrwM(auto-blkvm)
== Manager ‘admin’ logged off from 127.0.0.1
– AGI Script dialparties.agi completed, returning 0
– Executing Dial(“SIP/66.14x.xxx.xxx-0822a6a0”, “SIP/221|15|TtrwM(auto-blkvm)”) in new stack
– Called 221
– SIP/221-08279eb8 is ringing
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘SIP/66.14x.xxx.xxx-0822a6a0’ in macro ‘dial’
== Spawn extension (macro-dial, s, 10) exited non-zero on ‘SIP/66.14x.xxx.xxx-0822a6a0’
– Executing Macro(“SIP/66.14x.xxx.xxx-0822a6a0”, “hangupcall”) in new stack
– Executing ResetCDR(“SIP/66.14x.xxx.xxx-0822a6a0”, “w”) in new stack
– Executing NoCDR(“SIP/66.14x.xxx.xxx-0822a6a0”, “”) in new stack
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “1?skiprg”) in new stack
– Goto (macro-hangupcall,s,6)
– Executing GotoIf(“SIP/66.14x.xxx.xxx-0822a6a0”, “0?theend”) in new stack
– Executing NoOp(“SIP/66.14x.xxx.xxx-0822a6a0”, “Cleaning Up Block VM Flag: BLKVM/500/SIP/66.14x.xxx.xxx-0822a6a0”) in new stack
– Executing DBdel(“SIP/66.14x.xxx.xxx-0822a6a0”, “BLKVM/500/SIP/66.14x.xxx.xxx-0822a6a0”) in new stack
– DBdel: family=BLKVM, key=500/SIP/66.14x.xxx.xxx-0822a6a0
– Executing Wait(“SIP/66.14x.xxx.xxx-0822a6a0”, “5”) in new stack
== Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/66.14x.xxx.xxx-0822a6a0’ in macro ‘hangupcall’
== Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘SIP/66.14x.xxx.xxx-0822a6a0’
– Registered SIP ‘2450’ at 69.17.169.139 port 2600 expires 600
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager_custom.conf’: Found
== Manager ‘phpagi’ logged on from 127.0.0.1
== Manager ‘phpagi’ logged off from 127.0.0.1
– Registered SIP ‘2480’ at 69.17.172.162 port 1444 expires 600
[/code:1]

Peri · July 18, 2007, 1:20pm

In the end, this turned out to be a hardware problem.