[Home]

Summary:ASTERISK-09113: app_queue offers call then grabs it back with a timeout
Reporter:Douglas Lane (douglasl)Labels:
Date Opened:2007-03-27 05:57:52Date Closed:2007-09-12 14:12:19
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_queue
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) log.txt
( 1) queue_timeout.txt
Description:Hi everyone,

Am having a problem with a callcenter using AgentCallbackLogin for the agents. What happens is at random intervals (mainly noted at high call load - 40 or more channels) the queue attempts to call an agent, then quickly grabs it back in the same instance reporting that no one answered the call in 10000ms.

Please see attached log file for a call, as well as a sip trace from a Snom320 phone.

Thanks
Doug
Comments:By: Mark Michelson (mmichelson) 2007-07-11 14:25:52

I've been looking at this over the past several days, and it's not obvious what could be causing this and I've not been able to reproduce the problem myself. The only place I'm seeing in the code that could be problematic is a call to poll() which could be returning 0 even though it apparently has not timed out.

Out of curiosity on what type of system are you running Asterisk? What kernel version are you using? Is it 32 or 64 bit?

I've added a few lines of debug output to the code. Try patching your installation with these. If you have the problem occur again, attach another log so I can see if my hunch was correct. This patch will increase the amount of debug messages that appear on your console, but hopefully they will help prove what I'm after here.

By: Martin Vit (festr) 2007-07-24 17:09:43

hello, i'm testing queues in latest 1.4 (SVN-branch-1.4-r76891) i've some problem with agents call back with many debug messages. I've found no problem yet but i'm trying to figure out why there is so many lines in syslog:

-----
[Jul 24 23:40:35] DEBUG[1382]: chan_agent.c:909 agent_bridgedchannel: Asked for bridged channel on 'SIP/vit-08404f58'/'Agent/1', returning 'Zap/33-1'
[Jul 24 23:40:35] DEBUG[1382]: chan_agent.c:909 agent_bridgedchannel: Asked for bridged channel on 'SIP/vit-08404f58'/'Agent/1', returning 'Zap/33-1'
.
.
----

i've found in log.txt in this ticket that there are also these lines of debug messages. Any suggestion?

By: Martin Vit (festr) 2007-07-24 17:26:32

in chan_local there is a little weird things... in static int local_write(...) function is calling check_bridge function, which calls ast_bridged_channel which finally calls agent_bridgedchannel.

By: Joshua C. Colp (jcolp) 2007-07-25 17:13:44

That's normal. Unless you specify /n at the end of a Local dial line it tries to get itself out of the bridges if possible which involves checking whether a bridge is in progress and masquerading.

By: Douglas Lane (douglasl) 2007-07-26 03:24:14

What seems to happen with this issue is the following:

Queue Calls Agent
Agent calls Local@context
Context calls SIP
SIP is busy
Wait(1)

time so far is 2 seconds...

The repeat process

Time so far is 4 seconds...

Repeat

Time so far is 6 seconds...

Repeat

Time so far is 8 seconds...

Repeat

Whoops... Call just got cut from SIP channel by Queue..

Reason: Timeout

So in affect, if the SIP channel is Busy, and we go to Busy(20)... the queue does not stop the timer on that channel, and will continue to try calling agents while counting up to its Timeout value specified in queues.conf.

By: Mark Michelson (mmichelson) 2007-09-11 14:50:49

douglasl:
I'm having trouble understanding your last note. Could you provide the relevant portion of your dialplan so I can get a better feel for what's happening?

Also is this happening with the latest 1.4 release? There have been many changes since 1.4.1 and this might have been fixed.

By: Douglas Lane (douglasl) 2007-09-12 14:09:08

putnopvut:

I think we can discard this one, timeoutrestart=yes seems to have resolved the issue as I don't see it happening anymore. Upgraded to 1.4.9.

Thanks again for all the assistance.

By: Michiel van Baak (mvanbaak) 2007-09-12 14:12:18

Closing on reporters request.
Thanks for reporting back.