[asterisk-bugs] [JIRA] (ASTERISK-27064) Wrapup doesn't work time-to-time.
vladimir shmagin (JIRA)
noreply at issues.asterisk.org
Mon Jun 19 05:14:57 CDT 2017
vladimir shmagin created ASTERISK-27064:
-------------------------------------------
Summary: Wrapup doesn't work time-to-time.
Key: ASTERISK-27064
URL: https://issues.asterisk.org/jira/browse/ASTERISK-27064
Project: Asterisk
Issue Type: Bug
Security Level: None
Components: Applications/app_queue
Affects Versions: 11.22.0
Environment: Centos 6.8, Digium, Inc. Wildcard TE420P
Reporter: vladimir shmagin
Severity: Minor
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}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list