[asterisk-bugs] [JIRA] (ASTERISK-27064) Wrapup doesn't work time-to-time.
Michael L. Young (JIRA)
noreply at issues.asterisk.org
Mon Jun 19 08:41:57 CDT 2017
[ https://issues.asterisk.org/jira/browse/ASTERISK-27064?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Michael L. Young closed ASTERISK-27064.
---------------------------------------
Resolution: Won't Fix
> 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