[asterisk-bugs] [Asterisk 0018078]: Wrapuptime sometimes not respected

[Asterisk Bug Tracker]

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=18078 
====================================================================== 
Reported By:                lvl
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   18078
Category:                   Applications/app_queue
Reproducibility:            sometimes
Severity:                   minor
Priority:                   normal
Status:                     acknowledged
Asterisk Version:           1.6.2.13 
JIRA:                        
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-09-30 10:09 CDT
Last Modified:              2010-10-05 11:06 CDT
====================================================================== 
Summary:                    Wrapuptime sometimes not respected
Description: 
Ever since at least asterisk 1.6.2.5 we are experiencing that occasionally
(perhaps every 1 out of 10 calls) our WRAPUPTIME is being ignored. I
finally got around to setting up an environment where we can somewhat
reproduce the issue. This environment runs 1.6.2.13.

First of all, all the relevant parts of our configuration:

--- queues.conf ---
	[general]
	shared_lastcall = yes

	[queue1]
	ringinuse=no
	wrapuptime=60

--- extensions.conf ---
	; we only use dynamic agents, through a local channel because we need to
do AGI processing before and after an agent is called
	; because of the local channel, we specify a custom state interface that
we set INUSE/NOT_INUSE in the phones context
	[login]
	exten =>
s,n(login),AddQueueMember(queue1,Local/${extension}@phones/n,,,,Custom:inuse-${extension})

	[phones]
	exten => _X,1,Gosub(callphone,s,1(${EXTEN}))

	[callphone]           
	exten => s,1,Set(DEVICE_STATE(Custom:inuse-${ARG1})=INUSE)

	exten => s,n,Dial(SIP/phone${ARG1})

	exten => h,1,Set(DEVICE_STATE(Custom:inuse-${ARG1})=NOT_INUSE)
	
Most of the times this works fine. An agent hangs up a call, and gets (at
least) a 60 second pause before another call is offered to him. But
sometimes, RIGHT after an agent's call is hungup (to be exact, it happens
right after the Custom:inuse devstate is set back to NOT_INUSE. at this
time the call hasn't fully terminated yet by asterisk), the agent is
offered another call. See for example:

	[Sep 30 15:06:10] VERBOSE[9694] pbx.c:     -- Executing [h at callphone:1]
ExecIf("Local/99 at phones-78e9;2",
"1?Set(DEVICE_STATE(Custom:inuse-99)=NOT_INUSE)") in new stack
	[Sep 30 15:06:10] VERBOSE[9694] pbx.c:     -- Executing [h at callphone:2]
AGI("Local/99 at phones-78e9;2", "hangup.agi") in new stack

	[Sep 30 15:06:10] VERBOSE[9701] pbx.c:     -- Executing [99 at phones:1]
Gosub("Local/99 at phones-fa31;2", "callphone,s,1(99)") in new stack
	[Sep 30 15:06:10] VERBOSE[9701] pbx.c:     -- Executing [s at callphone:1]
ExecIf("Local/99 at phones-fa31;2",
"1?Set(DEVICE_STATE(Custom:inuse-99)=INUSE)") in new stack

	[Sep 30 15:06:10] VERBOSE[9694] pbx.c:     -- Executing [h at callphone:3]
NoOp("Local/99 at phones-78e9;2", "") in new stack
	[Sep 30 15:06:10] VERBOSE[9694] pbx.c:   == Spawn extension (callphone,
s, 15) exited non-zero on 'Local/99 at phones-78e9;2'
	
When this problem occurs, it always occurs after the previous call has
been hungup: in the same second. Never later than that. Perhaps the
wrapuptime is being ignored when the queue engine tries to offer a call at
exactly the same moment that another call is being hung up. Any clues?
====================================================================== 

---------------------------------------------------------------------- 
 (0127699) lvl (reporter) - 2010-10-05 11:06
 https://issues.asterisk.org/view.php?id=18078#c127699 
---------------------------------------------------------------------- 
I think you are right, I had coincidentally just come to the same
conclusion.

Didn't consider that at first, because the AGI script almost instantly
forks itself, but apparently the small delay it caused between the DEVSTATE
set to NOT_INUSE and the call being hungup (and thus the agent's lastcall
property being set) was enough to frequently cause a problem. I moved the
SET(DEVICE_STATE) to the end of the h extension and the problem seems to
have disappeared.

I believe that we have a good reason for using a custom devstate instead
of the SIP address, but I'll check it over to be sure.

Thanks for your input! 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2010-10-05 11:06 lvl            Note Added: 0127699                          
======================================================================