[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