[Home]

Summary:ASTERISK-25713: Queue produces large number of undesired cdr records
Reporter:George Keretchashvili (telvo)Labels:
Date Opened:2016-01-22 10:24:23.000-0600Date Closed:2016-07-12 12:35:02
Priority:MajorRegression?
Status:Closed/CompleteComponents:Applications/app_queue CDR/General
Versions:13.4.0 13.7.0 Frequency of
Occurrence
Related
Issues:
Environment:CentOS 7Attachments:( 0) debug_log_25713.txt
( 1) dialplan.ael.txt
( 2) queuerules.conf.txt
( 3) queues.conf.txt
( 4) queues.jpg
( 5) queues.sql.csv.txt
( 6) queues.sql.readable.txt
Description:Queue produces large number of undesired CDR records as a result of CDR behavior 12 version change.

For example 1067 incoming calls to the system that have entered the queue, have produced 11672 CDR records. Beside that, I already have separate logging for queues and have 13624 records and use it for generating statistical data.

CDR logs for each queue member retry when they're busy (in our case) are absolutely unnecessary for us and bring lots of trouble with generating statistics from CDR -  I find it hard even to calculate how many real incoming calls I have received during a day. Another problem is that the CDR table grows up very quickly.

I am looking for a way to disable this behavior and have one CDR per call as before version 12.

{noformat:title=CDR log for 1 call, 20 rows}
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b794","Queue","mozo","2016-01-21 10:28:29","2016-01-21 10:28:29","2016-01-21 10:28:46","16","16","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78916"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b795","Queue","mozo","2016-01-21 10:28:46","2016-01-21 10:28:46","2016-01-21 10:28:46","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78928"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b796","Queue","mozo","2016-01-21 10:28:51","2016-01-21 10:28:51","2016-01-21 10:28:51","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78930"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b797","Queue","mozo","2016-01-21 10:28:51","2016-01-21 10:28:51","2016-01-21 10:28:51","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78932"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b79a","Queue","mozo","2016-01-21 10:28:56","2016-01-21 10:28:56","2016-01-21 10:28:56","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78936"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b79b","Queue","mozo","2016-01-21 10:28:56","2016-01-21 10:28:56","2016-01-21 10:28:57","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78938"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b79d","Queue","mozo","2016-01-21 10:29:02","2016-01-21 10:29:02","2016-01-21 10:29:02","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78941"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b79e","Queue","mozo","2016-01-21 10:29:02","2016-01-21 10:29:02","2016-01-21 10:29:02","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78943"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b79f","Queue","mozo","2016-01-21 10:29:07","2016-01-21 10:29:07","2016-01-21 10:29:07","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78945"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b7a0","Queue","mozo","2016-01-21 10:29:07","2016-01-21 10:29:07","2016-01-21 10:29:07","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78947"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b7a1","Queue","mozo","2016-01-21 10:29:12","2016-01-21 10:29:12","2016-01-21 10:29:12","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78949"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b7a2","Queue","mozo","2016-01-21 10:29:12","2016-01-21 10:29:12","2016-01-21 10:29:12","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78951"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b7a3","Queue","mozo","2016-01-21 10:29:17","2016-01-21 10:29:17","2016-01-21 10:29:17","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78953"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b7a4","Queue","mozo","2016-01-21 10:29:17","2016-01-21 10:29:17","2016-01-21 10:29:17","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78955"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b7a5","Queue","mozo","2016-01-21 10:29:22","2016-01-21 10:29:22","2016-01-21 10:29:23","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78957"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b7a6","Queue","mozo","2016-01-21 10:29:23","2016-01-21 10:29:23","2016-01-21 10:29:23","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78959"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b7a7","Queue","mozo","2016-01-21 10:29:28","2016-01-21 10:29:28","2016-01-21 10:29:28","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78961"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-420-0000b7a8","Queue","mozo","2016-01-21 10:29:28","2016-01-21 10:29:28","2016-01-21 10:29:28","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-420","78963"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-418-0000b7aa","Queue","mozo","2016-01-21 10:29:33","2016-01-21 10:29:33","2016-01-21 10:29:33","0","0","BUSY","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-418","78966"
"2500550","90558778549","s","MOZO_IVR","""995558778549"" <90558778549>","SIP/GEONET-0000b78c","SIP/mozo-419-0000b7ab","Queue","mozo","2016-01-21 10:29:33","2016-01-21 10:29:33","2016-01-21 10:31:31","117","117","ANSWERED","DOCUMENTATION",NULL,"1453357709.46988","1453357709.46988","mozo-419","78968"
{noformat}

{noformat:title=queue_log for the same call, 22 rows}
"2016-01-21 10:28:46.363882","1453357709.46988","mozo","NONE","ENTERQUEUE",,"90558778549","1",,
"2016-01-21 10:28:46.394437","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:28:46.482651","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:28:51.581619","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:28:51.672426","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:28:56.761529","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:28:57.023727","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","1000",,,,
"2016-01-21 10:29:02.111538","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:29:02.222512","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:29:07.321435","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:29:07.412420","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:29:12.502565","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:29:12.682368","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:29:17.761432","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:29:17.932532","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:29:23.011526","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","1000",,,,
"2016-01-21 10:29:23.122461","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:29:28.252452","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:29:28.441435","1453357709.46988","mozo","SIP/mozo-420","RINGNOANSWER","0",,,,
"2016-01-21 10:29:33.571692","1453357709.46988","mozo","SIP/mozo-418","RINGNOANSWER","0",,,,
"2016-01-21 10:29:35.228784","1453357709.46988","mozo","SIP/mozo-419","CONNECT","49","1453357773.47019","1",,
"2016-01-21 10:31:31.530847","1453357709.46988","mozo","SIP/mozo-419","COMPLETECALLER","49","116","1",,
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2016-01-22 10:24:24.756-0600

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: Rusty Newton (rnewton) 2016-01-22 15:58:35.218-0600

Please attach your queues.conf and queuerules.conf as .txt files. Also any relevant queue related dialplan. Thanks!
By: George Keretchashvili (telvo) 2016-01-23 03:11:14.891-0600

queues.conf.txt: file config
queues.sql.csv.txt: realtime config
queuerules.conf.txt: file config
dialplan.ael.txt: excerpt from AEL file. Nothing special, I don't even use parameters in queue() app



By: Rusty Newton (rnewton) 2016-01-26 17:47:22.616-0600

re-attaching your csv.txt in a readable format.
By: Rusty Newton (rnewton) 2016-01-26 17:49:06.989-0600

Grab a debug log for one of the calls so we can get a bit more information about when the CDR entries are made.

Please follow the instructions on the wiki [1] for how to collect debugging information from Asterisk. For expediency, where possible, attach the debug with a '.txt' file extension so that the debug will be usable for further analysis.

Thanks!

[1] https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information


By: Matt Jordan (mjordan) 2016-01-27 07:59:48.074-0600

I understand that you may not like the behaviour, but this isn't a bug. CDRs now show the pairing of all attempted calls; ironically, this was done specifically for Queues, as many people running call centers explicitly wanted to see which agents didn't answer in their logs.

I'd recommend this be closed as "Not a Bug", as there are no plans to change this behaviour without a patch.
By: Asterisk Team (asteriskteam) 2016-02-10 12:00:21.524-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: George Keretchashvili (telvo) 2016-02-18 16:30:16.115-0600

Attaching debug log file (debug_log_25713.txt) for a call. Hopefully I have sanitized file properly and removed unrelated debug output. Some unrelated data might be left as this is a production system with number of connections.

As seen in the file, queue_log row is inserted right after each try, cdr rows are inserted at the end of the call.

The following scenario is not present in this file, however is seen in bug description CDR log: when call is answered after several agent attempts, first CDR row shows 16 secs in 'duration' and 'billsec' fields (that is for the first attempt) and the last row shows talk time with an agent. That makes very difficult to extract even simple data from the CDR - total length of the call.

To track queues there is queue_log feature, which logs everything related to queues very well. I was able to use and extract information from CDR logs and queue_logs as expected for years. Now, CDR is all messed up and unusable in the name of 'people asked for it' and 'everything should be logged'. I understand logging is vital, however I don't understand how come this happened that CDR became real mess by default and without an fallback option because of people that do not bother to use perfectly designed queue_logs? Okay, I might be missing something, but at least there should an option to switch back to previous behavior of CDRs to be able to extract and manipulate data like number of calls, lengths of calls etc. Besides the size of CDR now grows like crazy and for me it will hold gigs of useless data after could of months.
By: George Keretchashvili (telvo) 2016-02-18 16:41:19.932-0600

To demonstrate how well the queue data can be extracted from queue_log, without involving any CDR, I am attaching another file - queues.jpg.
By: Asterisk Team (asteriskteam) 2016-02-18 16:41:20.758-0600

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Matt Jordan (mjordan) 2016-07-12 12:35:02.378-0500

Still closing out as "Won't Fix", per the previous comments.

If someone would like to provide a patch that modifies the CDR behavior for Queus while still preserving the functionality for all other scenarios, and writes tests that verify that, then this issue can be reopened.

Note that there are both unit tests and tests in the Asterisk Test Suite to help guide a developer on their way on this issue.