[Home]

Summary:ASTERISK-27064: Wrapup doesn't work time-to-time.
Reporter:vladimir shmagin (shmagin)Labels:
Date Opened:2017-06-19 05:13:20Date Closed:2017-06-19 08:40:21
Priority:MinorRegression?
Status:Closed/CompleteComponents:Applications/app_queue
Versions:11.22.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:Centos 6.8, Digium, Inc. Wildcard TE420PAttachments:
Description:Operators complain about absense of wrapup in 5% of calls.
*The following query was used to detect the problem:*
{noformat}
select * from
(select
a.time,a.agent,
min(TIMESTAMPDIFF(SECOND,a.time,b.time)) as dif,
substr(a.time,12,8) as atime,a.event as event1,
substr(b.time,12,8) as btime,b.event as event2 from queue_log b,
(select time,agent,event from queue_log where time between '2017-06-19 11:00' and '2017-06-19 14:59'
and queuename='LoK'
and (event='COMPLETECALLER' or event='COMPLETEAGENT' or event='TRANSFER')) a
where
b.time between '2017-06-19 11:00' and b.time<'2017-06-19 14:59'
and b.queuename='LoK'
and b.agent=a.agent
and b.event not in ('COMPLETECALLER','COMPLETEAGENT','TRANSFER',
'PAUSE','UNPAUSE','PAUSEREASON','INFO','REMOVEMEMBER')
and b.time>a.time
group by a.agent,a.time)
c where dif<19;
{noformat}

*Here are some results:*
{noformat}
+----------------------------+----------------+------+----------+---------------+----------+--------------+
| time                       | agent          | dif  | atime    | event1        | btime    | event2       |
+----------------------------+----------------+------+----------+---------------+----------+--------------+
| 2017-06-13 16:13:39.534337 | SIP/76012:1100 |    3 | 16:13:39 | COMPLETEAGENT | 16:13:42 | CONNECT      |
| 2017-06-13 16:34:57.905027 | SIP/76012:1100 |    1 | 16:34:57 | COMPLETEAGENT | 16:34:59 | CONNECT      |
| 2017-06-13 16:35:34.452925 | SIP/76012:1100 |    1 | 16:35:34 | COMPLETEAGENT | 16:35:36 | CONNECT      |
| 2017-06-13 18:18:49.578981 | SIP/76012:1100 |    1 | 18:18:49 | COMPLETEAGENT | 18:18:51 | CONNECT      |
| 2017-06-13 18:27:05.776445 | SIP/76012:1100 |   15 | 18:27:05 | COMPLETEAGENT | 18:27:20 | RINGNOANSWER |
| 2017-06-14 20:06:29.005467 | SIP/76012:1064 |    6 | 20:06:29 | COMPLETEAGENT | 20:06:35 | CONNECT      |
| 2017-06-14 21:25:19.682858 | SIP/76012:1064 |    2 | 21:25:19 | COMPLETEAGENT | 21:25:22 | CONNECT      |
+----------------------------+----------------+------+----------+---------------+----------+--------------+

+----------------------------+----------------+------+----------+----------------+----------+--------------+
| time                       | agent          | dif  | atime    | event1         | btime    | event2       |
+----------------------------+----------------+------+----------+----------------+----------+--------------+
| 2017-06-15 10:51:41.651903 | SIP/76010:1686 |    1 | 10:51:41 | COMPLETEAGENT  | 10:51:43 | CONNECT      |
| 2017-06-15 12:56:41.267282 | SIP/76010:1686 |    0 | 12:56:41 | COMPLETEAGENT  | 12:56:41 | RINGNOANSWER |
| 2017-06-15 13:44:48.022416 | SIP/76010:1686 |    6 | 13:44:48 | COMPLETEAGENT  | 13:44:54 | CONNECT      |
| 2017-06-15 13:45:58.245652 | SIP/76010:1686 |    2 | 13:45:58 | COMPLETEAGENT  | 13:46:00 | CONNECT      |
| 2017-06-15 14:58:00.714293 | SIP/76010:1686 |    1 | 14:58:00 | COMPLETECALLER | 14:58:02 | CONNECT      |
| 2017-06-15 18:21:29.909289 | SIP/76010:1686 |    5 | 18:21:29 | COMPLETECALLER | 18:21:35 | CONNECT      |
| 2017-06-15 18:22:28.093244 | SIP/76010:1686 |    1 | 18:22:28 | COMPLETEAGENT  | 18:22:30 | CONNECT      |
+----------------------------+----------------+------+----------+----------------+----------+--------------+
{noformat}
As we noted the problems occurs more often when call finishs with event "COMPLETEAGENT". Operators were instructed to wait abonent hangup.
Today  we ran 'core set debug 5 app_queue.so'  to collect more information. *The problem has repeated:*
{noformat}
+----------------------------+----------------+------+----------+---------------+----------+--------------+
| time                       | agent          | dif  | atime    | event1        | btime    | event2       |
+----------------------------+----------------+------+----------+---------------+----------+--------------+
| 2017-06-19 11:33:28.931312 | SIP/76008:8867 |    0 | 11:33:28 | COMPLETEAGENT | 11:33:29 | RINGNOANSWER |
+----------------------------+----------------+------+----------+---------------+----------+--------------+

+-----------+----------------------------+------------------+-----------+----------------+---------------+-------+-------
| id        | time                       | callid           | queuename | agent          | event         | data1 | data2
+-----------+----------------------------+------------------+-----------+----------------+---------------+-------+-------
| 225402899 | 2017-06-19 11:33:28.931312 | 1497860837.9768  | LoK       | SIP/76008:8867 | COMPLETEAGENT | 9     | 346  
| 225402902 | 2017-06-19 11:33:29.258446 | 1497861158.10136 | LoK       | SIP/76008:8867 | RINGNOANSWER  | 0     |      
+-----------+----------------------------+------------------+-----------+----------------+---------------+-------+-------
{noformat}

*Device state log is the following:*
{noformat}
[Jun 19 11:27:40] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '6' (Ringing)
[Jun 19 11:27:42] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '3' (Busy)
[Jun 19 11:30:40] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '3' (Busy)
[Jun 19 11:33:29] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '1' (Not in use)
[Jun 19 11:33:29] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '6' (Ringing)
[Jun 19 11:33:29] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '1' (Not in use)
{noformat}

*The part of call trace is the following:*
{noformat}
[Jun 19 11:27:40] VERBOSE[19891][C-00000ee1] app_queue.c:     -- SIP/76008-00001cff is ringing
[Jun 19 11:27:42] VERBOSE[19891][C-00000ee1] app_queue.c:     -- SIP/76008-00001cff answered DAHDI/i2/9818262527-3e4
[Jun 19 11:27:42] DEBUG[19891][C-00000ee1] app_queue.c: Next is 'SIP/76027' with metric 1027
[Jun 19 11:27:42] VERBOSE[19891][C-00000ee1] res_musiconhold.c:     -- Stopped music on hold on DAHDI/i2/9818262527-3e4
[Jun 19 11:27:42] DEBUG[19891][C-00000ee1] app_queue.c: Queue 'LoK' Leave, Channel 'DAHDI/i2/9818262527-3e4'
[Jun 19 11:27:42] DEBUG[19891][C-00000ee1] app_queue.c: Marked member SIP/76008:8867 as in_call
[Jun 19 11:33:29] DEBUG[19891][C-00000ee1] app_queue.c: Marked member SIP/76008:8867 as NOT in_call. Lastcall time: 1497861209
+-----------------------------+
| FROM_UNIXTIME('1497861209') |
+-----------------------------+
| 2017-06-19 11:33:29         |
+-----------------------------+
{noformat}
*Then we see the next try to call 76008:*
{noformat}
[Jun 19 11:33:29] DEBUG[20475][C-00000f55] app_queue.c: Trying 'SIP/76017' with metric 25
[Jun 19 11:33:29] DEBUG[20475][C-00000f55] app_queue.c: SIP/76017 not available, can't receive call
[Jun 19 11:33:29] DEBUG[20475][C-00000f55] app_queue.c: Trying 'SIP/76008' with metric 26
[Jun 19 11:33:29] VERBOSE[20475][C-00000f55] netsock2.c:   == Using SIP RTP CoS mark 5
[Jun 19 11:33:29] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '6' (Ringing)
[Jun 19 11:33:29] DEBUG[31277] app_queue.c: Device 'Queue:LoK_avail' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 19 11:33:29] VERBOSE[31251][C-00000f55] chan_sip.c:     -- Got SIP response 486 "Busy Here" back from 172.30.0.92:5060
[Jun 19 11:33:29] VERBOSE[20475][C-00000f55] app_queue.c:     -- SIP/76008-00001e71 is busy
[Jun 19 11:33:29] VERBOSE[20475][C-00000f55] app_queue.c:     -- Nobody picked up in 0 ms
[Jun 19 11:33:29] DEBUG[31277] app_queue.c: Device 'SIP/76008' changed to state '1' (Not in use)
{noformat}

Comments:By: Asterisk Team (asteriskteam) 2017-06-19 05:13:21.805-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: vladimir shmagin (shmagin) 2017-06-19 06:42:29.006-0500

I'm sorry: fogot to add queue configuration:
{noformat}
[LoK]
ringinuse = no
strategy = rrmemory
timeout = 15
retry = 1
context = eqkc01
wrapuptime = 20
joinempty = no
leavewhenempty = yes
announce-position=no
announce-holdtime=no
announce-frequency=38
min-announce-frequency=20
periodic-announce-frequency=120
;announce-holdtime=yes
announce-round-seconds=0
reportholdtime=no
;queue-holdtime = expectedtime
queue-minutes =
queue-minute =
queue-seconds =
queue-thankyou =
periodic-announce = sorry_for_waiting
membermacro = agentnum
servicelevel = 60
{noformat}
By: Michael L. Young (elguero) 2017-06-19 08:38:37.048-0500

Per the Asterisk versions page [1], the maintenance (bug fix) support for the Asterisk branch you are using has ended. For continued maintenance support please move to a supported branch of Asterisk. After testing with a supported branch, if you find this problem has not been resolved, please open a new issue against the latest version of that Asterisk branch.

Thanks!

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions

You might also check out these issues that deal with wrap-up time.  They have already been fixed in newer versions of Asterisk.

ASTERISK-26399
ASTERISK-26400
ASTERISK-26715
ASTERISK-26975