[Home]

Summary:ASTERISK-15863: [patch] Improve realtime queue logging
Reporter:Miguel Molina (coolmig)Labels:
Date Opened:2010-03-23 11:06:03Date Closed:2010-09-01 13:20:00
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_queue
Versions:Frequency of
Occurrence
Related
Issues:
causesASTERISK-17036 [patch] Output of queue_log stopped after several hours
causesASTERISK-20504 Asterisk 1.8 should use [compat] section in asterisk.conf and behave acconding to the flag pbx_realtime=1.6
Environment:Attachments:( 0) 20100623__issue17082.diff.txt
( 1) 20100625__issue17082.diff.txt
( 2) 20100628__issue17082.diff.txt
( 3) 20100720__issue17082.diff.txt
( 4) patch_issue_17082_ast1.8.0-branch.diff
( 5) patch_realtime_queue_log_ast_1.6.0.26.diff
( 6) patch_realtime_queue_log_ast_trunk_ok_5data_rev1.diff
( 7) patch_realtime_queue_log_ast_trunk_ok_5data.diff
( 8) patch_realtime_queue_log_ast_trunk_ok.diff
( 9) patch_realtime_queue_log_ast_trunk.diff
Description:I was playing with the RT queue log functionality, and found this limitations:

1. If you choose RT queue logging, you won't have the traditional plain text file file log. This file is very useful for backup purposes.
2. The column 'data' stores all the parameters separated by '|', which is not the best way to store it.

I managed to program a patch which overcomes this limitations, and works this way:

1. If you enable RT queue logging, the queue log will still be logged in the plain text file, so you have some backup in case of some database disaster.
2. The parameters are now "exploded", and put in separate fields for each one. The only thing here is that this code must be changed in case that some queue log event delivers more than 4 parameters (the only event that gives 4 parameters is TRANSFER).
3. The calldate is now stored just like the CDR, with a full datetime.
4. The plain text file is left as is, for compatibility purposes.
5. The fieldnames on the table changed a little.

****** ADDITIONAL INFORMATION ******

Given this changes, the proposed queue_log realtime table is this one (for PostgreSQL):

CREATE TABLE "queue_log" (
 "id" SERIAL,
 "eventdate" TIMESTAMP WITH TIME ZONE DEFAULT now() NOT NULL,
 "cdr_uniqueid" VARCHAR(32) DEFAULT ''::character varying NOT NULL,
 "queuename" VARCHAR(32) DEFAULT ''::character varying NOT NULL,
 "agent" VARCHAR(32) DEFAULT ''::character varying NOT NULL,
 "event" VARCHAR(32) DEFAULT ''::character varying NOT NULL,
 "data1" VARCHAR(100) DEFAULT ''::character varying NOT NULL,
 "data2" VARCHAR(100) DEFAULT ''::character varying NOT NULL,
 "data3" VARCHAR(100) DEFAULT ''::character varying NOT NULL,
 "data4" VARCHAR(100) DEFAULT ''::character varying NOT NULL,
 CONSTRAINT "queue_log_pkey" PRIMARY KEY("id")
) WITHOUT OIDS;

I tested this patch on asterisk 1.6.0.26 and works like a charm!
You will find patches for asterisk 1.6.0.26 and latest trunk (SVN r253918)

Just like issue 11625, I hope the community would love this patch! ;-)
Comments:By: Leif Madsen (lmadsen) 2010-03-24 08:43:07

Thanks for the patches!

By: Miguel Molina (coolmig) 2010-06-15 11:57:01

The patch for trunk is reversed, sorry for any inconvenience.

By: Leif Madsen (lmadsen) 2010-06-15 12:01:40

coolmig: may wish to upload a new version then? I could delete the old version after.

By: Paul Belanger (pabelanger) 2010-06-15 12:02:30

Your best to download the proper svn branch located at http://svn.digium.com/svn/asterisk/

then use svn diff to generate your patches.

By: Miguel Molina (coolmig) 2010-06-15 12:27:11

You will find the corrected trunk patch generated with svn diff.

By: Paul Belanger (pabelanger) 2010-06-15 14:11:17

Great thanks! If you also submit this to https://reviewboard.asterisk.org we should have no problem getting this merged.

By: Miguel Molina (coolmig) 2010-06-15 14:36:24

I tried to use post-review but this error appears:

"There was an error creating this review request.

The repository path "http://svn.asterisk.org/svn/asterisk" is not in the
list of known repositories on the server.

Ask the administrator to add this repository to the Review Board server.
For information on adding repositories, please read
http://www.reviewboard.org/docs/manual/dev/admin/management/repositories/"

Am I missing something?

By: Paul Belanger (pabelanger) 2010-06-15 14:46:04

Ran into this issue before too, you actually need to be using https://origsvn.digium.com, which you don't have access to.  Looks like you will need to use the web interface.

By: Tim Ringenbach at Asteria Solutions Group (tim_ringenbach) 2010-06-15 14:59:03

It looks TRANSFER events actually have 5 data columns.
ast_queue_log(queuename, qe->chan->uniqueid, member->membername, "TRANSFER", "%s|%s|%ld|%ld|%d"

By: Miguel Molina (coolmig) 2010-06-15 14:59:20

Ok, I tried to use the web interface to create the review but this error appears:

"Unable to parse diff revision header '(revision: 270519)'"

By: Miguel Molina (coolmig) 2010-06-16 12:02:50

@tim_ringerbach: You're right, as I originally made the patch for 1.6.0 there were only 4 data columns for TRANSFER event. I will soon update the patch and test it on a 1.6.2.9-rc2 test server (1.6.2.X has the same 5 data columns as trunk).

By: Miguel Molina (coolmig) 2010-06-16 15:42:40

Patch updated and tested with 1.6.2.9-rc2, works great saving all 5 data of the TRANSFER event.

By: Miguel Molina (coolmig) 2010-06-16 15:48:27

@pabelanger: I couldn't create the review request using the web interface or the post-review tool, that's why I'm posting the patch here by now.

By: Paul Belanger (pabelanger) 2010-06-16 16:02:02

Reviewboard created, I also had problems with your patch.  I suspect is was because of a language mismatch.  You should be able to upload new patches directly to reviewboard.

By: Miguel Molina (coolmig) 2010-06-16 16:33:05

Thanks, I made the comments on the reviewboard and posted the patch here. I didn't find how to update the patch on the reviewboard (must be because I'm not the submitter) so you will find the new patch here.

By: Tilghman Lesher (tilghman) 2010-06-23 15:06:31

I took a look at your configuration, and I figured that a much better way to implement this would be to use the adaptive realtime features, plus an additional configuration option, which allows the current behavior to remain, which avoids breaking any existing setups, while at the same time permitting an upgrade to the capabilities that you've described here.

For legacy reasons, I have not altered any fields other than the data fields, though, due to the ability of adaptive realtime, we could model those, as well.

Testing and feedback would be appreciated.

By: Miguel Molina (coolmig) 2010-06-25 17:15:15

Hi Tilghman, I'm testing your patch in trunk, thanks for this better version of the idea.

On the tests I made, it seems like the field checks can't be done because the logger is always loaded before the realtime engine, even if I preload the engine in modules.conf. Looking at the asterisk start with res_config_pgsql.so preloaded:

 == Parsing '/etc/asterisk/asterisk.conf':   == Found
 == Parsing '/etc/asterisk/extconfig.conf':   == Found
 == Binding queue_log to pgsql/bd_general_tests/queue_log
 == Parsing '/etc/asterisk/logger.conf':   == Found
[Jun 25 15:01:58] WARNING[7484]: config.c:2040
find_engine: Realtime mapping for 'queue_log' found to engine 'pgsql', but th
e engine is not available
[Jun 25 15:01:58] WARNING[7484]: config.c:2040
find_engine: Realtime mapping for 'queue_log' found to engine 'pgsql', but th
e engine is not available
[Jun 25 15:01:58] WARNING[7484]: config.c:2040
find_engine: Realtime mapping for 'queue_log' found to engine 'pgsql', but th
e engine is not available
 == Parsing '/etc/asterisk/asterisk.conf':   == Found
 == Manager registered action DataGet
 == Parsing '/etc/asterisk/codecs.conf':   == Found
Asterisk Dynamic Loader Starting:
 == Parsing '/etc/asterisk/modules.conf':   == Found
[Jun 25 15:01:58] NOTICE[7484]: loader.c:1096 l
oad_modules: 1 modules will be loaded.
 == Parsing '/etc/asterisk/res_pgsql.conf':   == Found
 == PostgreSQL RealTime reloaded.
[Jun 25 15:01:58] NOTICE[7484]: config.c:1983 a
st_config_engine_register: Registered Config Engine pgsql
PostgreSQL RealTime driver loaded.
res_config_pgsql.so => (PostgreSQL RealTime Configuration Driver
)
 == Parsing '/etc/asterisk/dnsmgr.conf':   == Found
 == Parsing '/etc/asterisk/http.conf':   == Found

If the field check fails it will default to the normal behavior where the data field is saved as only one, and setting up the table with the "data" field instead of the 5 ones results in a correct save of the info. So with this condition I can't enable the improved realtime logging. Please correct me if I'm wrong.

One question, do the field check asks for exactly 20 characters for each field or they can be larger? On certain events where channel names are stored this size could be too small.



By: Tilghman Lesher (tilghman) 2010-06-25 17:26:18

That field check just ensures a minimum size.  If the fields are larger, that's fine.  Some drivers even support expanding column widths on the fly.

By: Tilghman Lesher (tilghman) 2010-06-25 19:52:48

Okay, I think I have a solution for this problem, and it got deeper and deeper, while I explored the situation.  What I've done to fix the problem is to create two logger initialization functions, the second of which runs after the preload of modules is done.  I additionally decided that mention of a realtime driver in extconfig should force that module to be preloaded as a requirement.  And, as a consequence of all this, preloaded modules may now additionally request that certain modules be loaded at a somewhat-preload time (prior to the bulk of the modules, but after the initial set).

By: Miguel Molina (coolmig) 2010-06-28 17:41:55

Hi Tilghman, I tried the new patch and the automatic preload of the engine is made perfectly, with no need for an explicit reload, no more complains about the engine not found. :D

I only had a small issue, on the list of types in config.h it seems like the type 'timestamp' is not recognized. Postgresql uses timestamp instead of MySQL's datetime.

Looking at a debugged asterisk start:

[Jun 28 15:29:44] DEBUG[17439]: res_config_pgsql.c:202
m find_table: Query of table structure complete.  Now retrieving results.
      > Found column 'id' of type 'int4'
      > Found column 'time' of type 'timestamp'
      > Found column 'callid' of type 'varchar'
      > Found column 'queuename' of type 'varchar'
      > Found column 'agent' of type 'varchar'
      > Found column 'event' of type 'varchar'
      > Found column 'data1' of type 'varchar'
      > Found column 'data2' of type 'varchar'
      > Found column 'data3' of type 'varchar'
      > Found column 'data4' of type 'varchar'
      > Found column 'data5' of type 'varchar'
[Jun 28 15:29:44] WARNING[17439]: res_config_pgsql.c:117
5 require_pgsql: Possibly unsupported column type 'timestamp' on col
umn 'time'
[Jun 28 15:29:44] DEBUG[17439]: res_config_pgsql.c:1478
pgsql_reconnect: PostgreSQL RealTime: One or more of the parameters
in the config does not pass our validity checks.

So I'm going to try taking away the field 'time' of the ast_realtime_require_field to see if it works, but I think the solution would be adding the new type to config.h and make us recognize it in require_pgsql of res__config__pgsql.c.

I'll keep you posted, thanks again.

By: Miguel Molina (coolmig) 2010-06-28 18:29:46

Yay it works! Without the 'time' field check, it enables the improved behavior and it inserts records in the table like a charm:

id                     time       callid queuename      agent       event            data1        data2 data3 data4 data5
3 28/06/2010 03:44:04 p.m.         NONE      NONE       NONE  QUEUESTART                                                
4 28/06/2010 03:44:09 p.m.         NONE      NONE       NONE  QUEUESTART                                                
5 28/06/2010 03:44:59 p.m.         NONE      NONE       NONE  QUEUESTART                                                
6 28/06/2010 03:46:56 p.m. 1277765200.1      NONE Agent/1001  AGENTLOGIN SIP/100-00000001                              
7 28/06/2010 03:48:47 p.m. 1277765326.2   pruebas       NONE  ENTERQUEUE                           101     1            
8 28/06/2010 03:48:47 p.m. 1277765326.2   pruebas Agent/1001     CONNECT                1 1277765326.3     0            
9 28/06/2010 03:49:00 p.m. 1277765326.2   pruebas Agent/1001    TRANSFER             1101      default     1    13     1
10 28/06/2010 03:50:08 p.m. 1277765200.1      NONE Agent/1001 AGENTLOGOFF SIP/100-00000001          192                  

But... testing the standard queue_log to file, it seems that it does not work regardless of the realtime backend or the settings... I don't know what could be wrong. I'll keep an eye on it.

By: Tilghman Lesher (tilghman) 2010-06-28 20:41:12

Okay, in the latest patch, I 1) changed where qlog is opened, which may be the cause of the problem with queue_log_to_file, and 2) added handling of the "timestamp" column type to the Postgres driver.

By: Miguel Molina (coolmig) 2010-07-02 18:08:06

I will be away for the next week, so I will continue testing this after July 13th. I think all is going to work OK with the last changes.

By: Tilghman Lesher (tilghman) 2010-07-20 12:00:14

It's been a week since July 13th.  What are your testing results?

By: Tilghman Lesher (tilghman) 2010-07-20 12:36:12

Additionally, I've refactored the patch now, because we're going to use self-assigned priorities to establish proper load order.

By: Digium Subversion (svnbot) 2010-07-20 18:23:24

Repository: asterisk
Revision: 278307

U   trunk/CHANGES
U   trunk/configs/logger.conf.sample
A   trunk/contrib/realtime/mysql/queue_log.sql
U   trunk/main/logger.c
U   trunk/res/res_config_pgsql.c

------------------------------------------------------------------------
r278307 | tilghman | 2010-07-20 18:23:24 -0500 (Tue, 20 Jul 2010) | 8 lines

Separate queue_log arguments into separate fields, and allow the text file to be used, even when realtime is used.

(closes issue ASTERISK-15863)
Reported by: coolmig
Patches:
      20100720__issue17082.diff.txt uploaded by tilghman (license 14)
Tested by: coolmig

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=278307

By: Miguel Molina (coolmig) 2010-08-19 17:52:28

Hi Tilghman, thanks for the effort made to include this cool feature to asterisk 1.8. I tested this on asterisk-1.8.0-beta3 but require_pgsql in res_config_pgsql.c kept complaining about the timestamp type being not known.

You'll find a patch made for the SVN 1.8 branch that solves the issue for me. It all works fine, even the queue_log_to_file option in logger.conf works like a charm!

By: Digium Subversion (svnbot) 2010-09-01 13:13:36

Repository: asterisk
Revision: 284472

U   branches/1.6.2/res/res_config_pgsql.c

------------------------------------------------------------------------
r284472 | tilghman | 2010-09-01 13:13:36 -0500 (Wed, 01 Sep 2010) | 5 lines

Don't warn on floats and timestamps

(closes issue ASTERISK-15863)
Reported by: coolmig

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=284472

By: Digium Subversion (svnbot) 2010-09-01 13:16:38

Repository: asterisk
Revision: 284473

_U  branches/1.8/
U   branches/1.8/res/res_config_pgsql.c

------------------------------------------------------------------------
r284473 | tilghman | 2010-09-01 13:16:38 -0500 (Wed, 01 Sep 2010) | 12 lines

Merged revisions 284472 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.6.2

........
 r284472 | tilghman | 2010-09-01 13:13:35 -0500 (Wed, 01 Sep 2010) | 5 lines
 
 Don't warn on floats and timestamps
 
 (closes issue ASTERISK-15863)
 Reported by: coolmig
........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=284473

By: Digium Subversion (svnbot) 2010-09-01 13:19:13

Repository: asterisk
Revision: 284474

_U  trunk/
U   trunk/res/res_config_pgsql.c

------------------------------------------------------------------------
r284474 | tilghman | 2010-09-01 13:19:13 -0500 (Wed, 01 Sep 2010) | 19 lines

Merged revisions 284473 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

................
 r284473 | tilghman | 2010-09-01 13:16:37 -0500 (Wed, 01 Sep 2010) | 12 lines
 
 Merged revisions 284472 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ........
   r284472 | tilghman | 2010-09-01 13:13:35 -0500 (Wed, 01 Sep 2010) | 5 lines
   
   Don't warn on floats and timestamps
   
   (closes issue ASTERISK-15863)
   Reported by: coolmig
 ........
................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=284474

By: Eugene (varnav) 2013-01-13 03:28:43.264-0600

Hello! Does this table structure for PostgreSQL queue_log appear somewhere in the docs? Maybe it worth putting it to /contrib/realtime/postgresql
I see there a file /contrib/realtime/mysql/queue_log.sql for MySQL but nothing for PostgreSQL

By: Matt Jordan (mjordan) 2013-01-13 14:35:50.498-0600

If you'd like to create a patch containing the SQL statements needed to create the queue_log table for PostgreSQL, please open a new issue, sign a contributor license agreement, and attached the patch.  Thanks!