[Asterisk-bugs] [Asterisk 0010199]: Random replacement of channel name with other text in queue log entries

[noreply at bugs.digium.com]

A NOTE has been added to this issue. 
====================================================================== 
http://bugs.digium.com/view.php?id=10199 
====================================================================== 
Reported By:                jfitzgibbon
Assigned To:                putnopvut
====================================================================== 
Project:                    Asterisk
Issue ID:                   10199
Category:                   Applications/app_queue
Reproducibility:            random
Severity:                   major
Priority:                   normal
Status:                     assigned
Asterisk Version:           1.4.7.1  
SVN Branch (only for SVN checkouts, not tarball releases): N/A  
SVN Revision (number only!):  
Disclaimer on File?:        No 
Request Review:              
====================================================================== 
Date Submitted:             07-13-2007 08:44 CDT
Last Modified:              07-20-2007 12:20 CDT
====================================================================== 
Summary:                    Random replacement of channel name with other text
in queue log entries
Description: 
On 1.4.5, 1.4.6 and 1.4.7.1, I have observed random replacement of the
channel name with other text in my queue log.  Typically the other text is
part of a manager event, suggesting that a pointer is getting corrupted
somewhere.  It happens on a very small percentage of calls, but there are
consistent elements to the corruption from my observations:

- it only happens on one of my eleven queues.  Of the eleven, four others
are configured almost identically to the queue on which the corruption is
observed (the only differences are queue name and wrapuptime length). The
problem queue is listed second in queues.conf, and does not sort lexically
to the top or bottom of a list of queue names.

- the corruption first appears on the CONNECT event

- the channel name remains corrupted for the duration of the call (i.e.
you never see a good ENTERQUEUE, bad CONNECT, then a good COMPLETECALLER)

- the replacement text is not consistent.  It can differ between the
CONNECT and TRANSFER events (see example 1)

- if the call is transferred to an extension which enqueues the caller to
another queue, the corruption is cleared, and does not typically re-appear
(see example 1)

I cannot reproduce the bug on demand in my lab environment.  On a call
center fielding about 5000 calls per day, I see this on 5-10 of those
calls.  The main impact of this is that queue analysis programs never see
the CONNECT or COMPLETEXXXXXX events, so they think that any corrupted call
is waiting forever.  Having such a large wait time for several calls on a
queue knocks statistics out of whack.

====================================================================== 

---------------------------------------------------------------------- 
 jfitzgibbon - 07-20-07 12:20  
---------------------------------------------------------------------- 
I rarely reload queues throughout the day, as I use AddQueueMember pretty
much exclusively.

Yesterday for example I had no config reloads at all (other than the bogus
one inserted when you do 'logger reload', but I had corruption 5 times. 
There is no automated reload in this system, and I was not in the office,
so nobody else was touching the console all day.

1184832127|NONE|NONE|NONE|CONFIGRELOAD|
1184844997|NONE|NONE|NONE|QUEUESTART|
1184874777|1184874735.5466|sales|dummy at queuemetrics-1246,1'
|CONNECT|14|1184874763.5469
1184876249|1184876169.5907|sales|1f9291b874a9113efee1765fabd6e at 10.1.1.16
CSeq: 103 BYE
User-Agent: XXXXXXX
Max-Forwards: 70
Content-Length: 0

|TRANSFER|7202|from-internal-salesout-manual|14|43
1184878998|1184878476.6525|sales|in MixMonitor Recording Zap/85-1
|COMPLETEAGENT|16|479|1
1184883294|1184883243.8467|sales|
|CONNECT|15|1184883279.8490
1184886423|1184886390.10302|sales|dummy at queuemetrics-81ad,1'
|CONNECT|11|1184886412.10321

The logger reload was at 04:02am

The corruption happened at:

3:52pm
4:17pm
5:03pm
6:14pm
7:07pm

When I do make changes to extensions and sip conf, I tend to reload using
'sip reload' or 'extensions reload' or 'ael reload' - I stay away from a
global 'reload' whenever possible. 

Issue History 
Date Modified   Username       Field                    Change               
====================================================================== 
07-20-07 12:20  jfitzgibbon    Note Added: 0067646                          
======================================================================