[Home]

Summary:ASTERISK-20069: Some events are not logged
Reporter:Xavier Hienne (xhienne)Labels:
Date Opened:2012-06-28 13:41:41Date Closed:2012-07-02 14:35:23
Priority:MajorRegression?
Status:Closed/CompleteComponents:Core/General
Versions:1.8.13.0 10.5.1 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Regularly, I get some PG errors like these ones :

ERROR:  column "data" of relation "queue_log" does not exist at character 63
STATEMENT:  INSERT INTO queue_log (time, callid, queuename, agent, event, data) VALUES (..., 'ENTERQUEUE', ...)
ERROR:  column "data" of relation "queue_log" does not exist at character 63
STATEMENT:  INSERT INTO queue_log (time, callid, queuename, agent, event, data) VALUES (..., 'RINGNOANSWER', ...)
ERROR:  column "data" of relation "queue_log" does not exist at character 63
STATEMENT:  INSERT INTO queue_log (time, callid, queuename, agent, event, data) VALUES (..., 'CONNECT', ...)
ERROR:  column "data" of relation "queue_log" does not exist at character 63
STATEMENT:  INSERT INTO queue_log (time, callid, queuename, agent, event, data) VALUES (..., 'COMPLETECALLER', ...)

Apparently, the problem lies in ast_queue_log(), in main/logger.c : in the "else" part of the "if (logfiles.queue_adaptive_realtime)", there is a reference to a "data" column that does not exist. Shouldn't it be "data1" instead?
Comments:By: Rusty Newton (rnewton) 2012-06-29 14:45:23.652-0500

Xavier,

This could be a configuration error. Talking with Matt Jordan, he mentioned that in order to use the dataX fields, your schema must at least have all of the following:

time: datetime | data1: char | data2: char | data3: char | data4: char | data5: char

Otherwise, queue_log reverts to a simpler schema:

time: datetime | data: char

That behavior appears to be intended.

In Asterisk logs there may be WARNING some place that would alert to incorrect schema

Something like the following from res_config_pgsql):

"Column '%s' is of the incorrect type: (need %s(%d) but saw %s)"



Please double check your schema and provide a full log including VERBOSE and DEBUG levels 5 during the time errors occur.
By: Xavier Hienne (xhienne) 2012-07-02 10:14:53.529-0500

Thank you Rusty for this helpful answer.

My PG schema is as expected. Here is what asterisk logged at logrotate time the day before the problem arose:

[Jun 27 06:25:50] VERBOSE[16606] config.c: [Jun 27 06:25:50]   == Parsing '/etc/asterisk/logger.conf': [Jun 27 06:25:50] VERBOSE[16606] config.c: [Jun 27 06:25:50]   == Found
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'time' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'callid' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'queuename' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'agent' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'event' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'data1' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'data2' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'data3' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'data4' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] res_config_pgsql.c: [Jun 27 06:25:50]        > Found column 'data5' of type 'varchar'
[Jun 27 06:25:50] VERBOSE[16606] logger.c: [Jun 27 06:25:50]  Asterisk Queue Logger restarted
[Jun 27 06:25:50] VERBOSE[16606] asterisk.c: [Jun 27 06:25:50]     -- Remote UNIX connection disconnected

On the other hand, here is what I got the day after (and never got since), when the PG errors occured:

[Jun 28 06:25:52] VERBOSE[14866] config.c: [Jun 28 06:25:52]   == Parsing '/etc/asterisk/logger.conf': [Jun 28 06:25:52] VERBOSE[14866] config.c: [Jun 28 06:25:52]   == Found
[Jun 28 06:25:52] ERROR[14866] res_config_pgsql.c: Failed to query database columns:
[Jun 28 06:25:52] WARNING[14866] res_config_pgsql.c: Table queue_log not found in database.  This table should exist if you're using realtime.
[Jun 28 06:25:52] WARNING[14866] res_config_pgsql.c: PostgreSQL RealTime: Failed to query database. Check debug for more info.
[Jun 28 06:25:52] VERBOSE[14866] logger.c: [Jun 28 06:25:52]  Asterisk Queue Logger restarted
[Jun 28 06:25:52] VERBOSE[14866] asterisk.c: [Jun 28 06:25:52]     -- Remote UNIX connection disconnected

Obviously, something went wrong (note also how the logs are messed up on the first line).

Since that time, quite logically, I have got the reported PG errors each time asterisk had to write to the queue_log table, and until the configuration was reloaded at a later time.

It seems it is a one time event and I don't know (and will certainly never know) what happened. I the problem occur again, I will investigate further and open another issue.

By: Rusty Newton (rnewton) 2012-07-02 14:35:23.565-0500

Strange.. Not sure what happened and can't tell from that log output.  Depending on your system traffic, you may want to run a full log with DEBUG output at level 5 and rotate it so that if it does happen again you'll have extra data that may help us track it down if there is a next time. Be sure to watch your load and disk usage. https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information