[Home]

Summary:ASTERISK-29360: Asterisk, Mysql, Odbc (Unknown column 'data' in 'field list')
Reporter:Maksim (maxim.dogonov)Labels:
Date Opened:2021-03-22 02:22:34Date Closed:
Priority:MajorRegression?
Status:Open/NewComponents:Core/Logging
Versions:16.15.1 Frequency of
Occurrence
Related
Issues:
Environment:CentOS Linux release 8.3.2011 Your MySQL connection id is 108 Server version: 5.5.62 MySQL Community Server (GPL)Attachments:
Description:Hi,

We use for logging queuelog events to mysql database use odbc driver.
When first start asterisk and after started mysqlDB we have trouble with queuelog logging.

WARNING[1995]: res_odbc.c:538 ast_odbc_print_errors: SQL Prepare returned an error: 42S22: [MySQL][ODBC 8.0(w) Driver][mysqld-5.7.28-log]Unknown column 'data' in 'field list'
WARNING[1995]: res_config_odbc.c:122 custom_prepare: SQL Prepare failed! [INSERT INTO queue_log (time, data, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?)]  

after I run command asterisk -rx "core reload" is temp fixed.

I try add that column data to my sql sheme:
ALTER TABLE queuelog ADD data varchar(40) COLLATE utf8_general_ci NOT NULL DEFAULT '' AFTER event;

and I don't get error, but column data1, data2, data3, data4 is empty.
Asterisk write all volumes to data fields like "|11-9873630826|11"

after asterisk -rx "core reload"
Comments:By: Asterisk Team (asteriskteam) 2021-03-22 02:22:36.631-0500

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. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

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].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.

Please note that by submitting data, code, or documentation to Sangoma through JIRA, you accept the Terms of Use present at [https://www.asterisk.org/terms-of-use/|https://www.asterisk.org/terms-of-use/].
By: Maksim (maxim.dogonov) 2021-03-22 02:40:28.924-0500

it seems need to be check logic in ./main/logger.c  line num 877
{code}
      if (ast_check_realtime("queue_log")) {
               tv = ast_tvnow();
               ast_localtime(&tv, &tm, logfiles.queue_log_realtime_use_gmt ? "GMT" : NULL);
               ast_strftime(time_str, sizeof(time_str), "%F %T.%6q", &tm);
               va_start(ap, fmt);
               vsnprintf(qlog_msg, sizeof(qlog_msg), fmt, ap);
               va_end(ap);
               if (logfiles.queue_adaptive_realtime) {
                       AST_DECLARE_APP_ARGS(args,
                               AST_APP_ARG(data)[5];
                       );
                       AST_NONSTANDARD_APP_ARGS(args, qlog_msg, '|');
                       /* Ensure fields are large enough to receive data */
                       ast_realtime_require_field("queue_log",
                               "data1", RQ_CHAR, strlen(S_OR(args.data[0], "")),
                               "data2", RQ_CHAR, strlen(S_OR(args.data[1], "")),
                               "data3", RQ_CHAR, strlen(S_OR(args.data[2], "")),
                               "data4", RQ_CHAR, strlen(S_OR(args.data[3], "")),
                               "data5", RQ_CHAR, strlen(S_OR(args.data[4], "")),
                               SENTINEL);

                       /* Store the log */
                       ast_store_realtime("queue_log", "time", time_str,
                               "callid", callid,
                               "queuename", queuename,
                               "agent", agent,
                               "event", event,
                               "data1", S_OR(args.data[0], ""),
                               "data2", S_OR(args.data[1], ""),
                               "data3", S_OR(args.data[2], ""),
                               "data4", S_OR(args.data[3], ""),
                               "data5", S_OR(args.data[4], ""),
                               SENTINEL);
               } else {
                       ast_store_realtime("queue_log", "time", time_str,
                               "callid", callid,
                               "queuename", queuename,
                               "agent", agent,
                               "event", event,
                               "data", qlog_msg,
                               SENTINEL);
               }
{code}
By: George Joseph (gjoseph) 2021-03-22 08:27:50.241-0500

Can you verify that your queue_log table looks like this...
{code}
CREATE TABLE `queue_log` (
 `id` bigint(20) NOT NULL AUTO_INCREMENT,
 `time` datetime DEFAULT NULL,
 `callid` varchar(80) DEFAULT NULL,
 `queuename` varchar(256) DEFAULT NULL,
 `agent` varchar(80) DEFAULT NULL,
 `event` varchar(32) DEFAULT NULL,
 `data1` varchar(100) DEFAULT NULL,
 `data2` varchar(100) DEFAULT NULL,
 `data3` varchar(100) DEFAULT NULL,
 `data4` varchar(100) DEFAULT NULL,
 `data5` varchar(100) DEFAULT NULL,
 PRIMARY KEY (`id`),
 UNIQUE KEY `id` (`id`)
)
{code}

Also, can you see if just running {{logger reload}} instead of {{core reload}} fixes the issue?


By: Maksim (maxim.dogonov) 2021-03-23 06:27:06.665-0500

Hi, My SQL queuelog table sheme
CREATE TABLE `queuelog` (
 `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
 `time` datetime NOT NULL,
 `callid` varchar(80) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `queuename` varchar(20) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `serverid` varchar(20) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `agent` varchar(80) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `event` varchar(32) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `data1` varchar(100) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `data2` varchar(100) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `data3` varchar(100) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `data4` varchar(100) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 `data5` varchar(100) COLLATE utf8_general_ci NOT NULL DEFAULT '',
 PRIMARY KEY (`id`),
 FULLTEXT KEY `queue` (`queuename`),
 FULLTEXT KEY `callindex` (`callid`),
 FULLTEXT KEY `event` (`event`),
 KEY `timeindex` (`time`)
) ENGINE=InnoDB AUTO_INCREMENT=21708908 DEFAULT CHARSET=utf8mb4 COLLATE=utf8_general_ci;

but that issue happened when asterisk started first and mysql started second. After when make core reload issue is fixed.
I will try make logger reload

By: George Joseph (gjoseph) 2021-03-23 07:13:01.871-0500

Yeah try the logger reload instead of core reload.  The reason I ask is that I think there's a race condition between logger.c  trying to determine logfiles.queue_adaptive_realtime and odbc being fully initialized.  If you do a logger reload and the issue corrects itself then that points to the race being the cause.


By: Maksim (maxim.dogonov) 2021-03-23 15:20:06.537-0500

Yes, now I restarted my asterisk system, and when I try dial to the queue I got error like:
[2021-03-23 23:13:48] WARNING[11859][C-00000001]: res_odbc.c:538 ast_odbc_print_errors: SQL Prepare returned an error: 42S22: [MySQL][ODBC 5.2(w) Driver][mysqld-5.5.62]Unknown column 'data' in 'field list'
[2021-03-23 23:13:48] WARNING[11859][C-00000001]: res_config_odbc.c:122 custom_prepare: SQL Prepare failed! [INSERT INTO queuelog (time, data, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?)]
[2021-03-23 23:13:48] WARNING[11859][C-00000001]: res_odbc.c:538 ast_odbc_print_errors: SQL Prepare returned an error: 42S22: [MySQL][ODBC 5.2(w) Driver][mysqld-5.5.62]Unknown column 'data' in 'field list'
[2021-03-23 23:13:48] WARNING[11859][C-00000001]: res_config_odbc.c:122 custom_prepare: SQL Prepare failed! [INSERT INTO queuelog (time, data, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?)]

after that I run logger reload, and make dial to the queue. without problem record added to table queuelog.
By: George Joseph (gjoseph) 2021-03-24 07:21:34.497-0500

Can you try something as a work-around?
Add the following to the cli.conf file...\
{code}
[startup_commands]
logger reload = yes
{code}
This will do an immediate logger reload after startup, hopefully after odbc is fully initialized.  
By: Maksim (maxim.dogonov) 2021-03-24 13:44:32.099-0500

Hi, George  

I create file cli.conf
and add lines:  
    [startup_commands]
    logger reload = yes


After restart full system, and dial to the queue and get same errors:

  -- Executing [s@Gosub-INBOUND-ROUTES:11] Queue("SIP/268-22-30-00000000", "6901,rtTc,,,,,,,6901") in new stack
[2021-03-24 21:39:01] WARNING[16351][C-00000001]: res_odbc.c:538 ast_odbc_print_errors: SQL Prepare returned an error: 42S22: [MySQL][ODBC 5.2(w) Driver][mysqld-5.5.62]Unknown column 'data' in 'field list'
[2021-03-24 21:39:01] WARNING[16351][C-00000001]: res_config_odbc.c:122 custom_prepare: SQL Prepare failed! [INSERT INTO queuelog (time, data, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?)]
      > 0x7f5a8c08ced0 -- Strict RTP learning complete - Locking on source address 10.200.24.55:31210
[2021-03-24 21:39:05] WARNING[16351][C-00000001]: res_odbc.c:538 ast_odbc_print_errors: SQL Prepare returned an error: 42S22: [MySQL][ODBC 5.2(w) Driver][mysqld-5.5.62]Unknown column 'data' in 'field list'
[2021-03-24 21:39:05] WARNING[16351][C-00000001]: res_config_odbc.c:122 custom_prepare: SQL Prepare failed! [INSERT INTO queuelog (time, data, event, agent, queuename, callid) VALUES (?, ?, ?, ?, ?, ?)]
 == Spawn extension (Gosub-INBOUND-ROUTES, s, 11) exited non-zero on 'SIP/268-22-30-00000000'


By: George Joseph (gjoseph) 2021-03-25 06:39:42.425-0500

OK.  I guess the processing of cli.conf is still too early.  I've opened an internal issue for this and it's in the queue.

By: Maksim (maxim.dogonov) 2021-03-30 04:09:41.329-0500

Hi, Do you have any feedback about our issue?

By: Joshua C. Colp (jcolp) 2021-03-30 04:15:54.088-0500

The issue has been opened and accepted. There is no time frame on when it would get looked into or resolved.