You are here

Home » Blogs » Shinguz's blog

MariaDB SQL Error Log Plugin

Thu, 2020-07-30 12:26 — Shinguz

When you are for too long in business you think you know already everything and you are getting lazy. This happened to me again a few weeks ago. A customer asked me about the SQL Error Log Plugin. First I though he was talking about the MariaDB Error Log or the General Query Log. But then I have learned that there is something "new" I did not know yet...

MariaDB introduced in 5.5.22 (March 2012) a new plugin called the SQL Error Log Plugin. This Plugin collects all the errors which were sent from the MariaDB daemon to applications/clients and writes it to a log file.

This Client error log file can be analysed later to find and fix bugs in the application if the applications did not catch the errors themselves.

Installation

The Plugin can be easily installed with:

SQL> INSTALL PLUGIN sql_error_log SONAME 'sql_errlog';

and uninstalled again with:

SQL> UNINSTALL PLUGIN sql_error_log;
Query OK, 0 rows affected, 1 warning (0.002 sec)

The installation and uninstallation informations are persistent and survive a database instance restart.

If you uninstall the plugin you get a warning:

SQL> SHOW WARNINGS;
+---------+------+----------------------------------------------------+
| Level   | Code | Message                                            |
+---------+------+----------------------------------------------------+
| Warning | 1620 | Plugin is busy and will be uninstalled on shutdown |
+---------+------+----------------------------------------------------+

telling you that the plugin is still running until the next database instance restart.

If the plugin currently is installed you can find with the following command:

SQL> SELECT * FROM information_schema.plugins WHERE PLUGIN_TYPE = 'AUDIT'\G
*************************** 1. row ***************************
           PLUGIN_NAME: SQL_ERROR_LOG
        PLUGIN_VERSION: 1.0
         PLUGIN_STATUS: ACTIVE
           PLUGIN_TYPE: AUDIT
   PLUGIN_TYPE_VERSION: 3.2
        PLUGIN_LIBRARY: sql_errlog.so
PLUGIN_LIBRARY_VERSION: 1.14
         PLUGIN_AUTHOR: Alexey Botchkov
    PLUGIN_DESCRIPTION: Log SQL level errors to a file with rotation
        PLUGIN_LICENSE: GPL
           LOAD_OPTION: ON
       PLUGIN_MATURITY: Stable
   PLUGIN_AUTH_VERSION: 1.0

Variables

With the command:

SQL> SHOW GLOBAL VARIABLES LIKE 'sql_error_log%';
+--------------------------+----------------+
| Variable_name            | Value          |
+--------------------------+----------------+
| sql_error_log_filename   | sql_errors.log |
| sql_error_log_rate       | 1              |
| sql_error_log_rotate     | OFF            |
| sql_error_log_rotations  | 9              |
| sql_error_log_size_limit | 1000000        |
+--------------------------+----------------+

you can see the SQL Error Log configuration variables. These variables are NOT shown if the plugin is not installed yet or uninstalled again.

The SQL Error Log is written by default to $datadir/sql_error.log and cannot be change during runtime:/

SQL> SET GLOBAL sql_error_log_filename = '/home/mysql/database_slow/mariadb-105/log/sql_errors.log';
ERROR 1238 (HY000): Variable 'sql_error_log_filename' is a read only variable

Log Rotation

The other four variables are related to log rotation. It is cool, that this is done by the database and has not to be done by O/S means: See also: MariaDB Log Rotation.

On the first look it did not work like expected. But when reading the documentation again: This is the 'write-only' variable. Assigning TRUE to this variable forces the log rotation. it becomes understandable. If you enter:

SQL> SET GLOBAL sql_error_log_rotate=1;
Query OK, 0 rows affected (0.000 sec)

the SQL Error Log is rotated in the background and you can see this in $datadir:

shell> ls -ltr sql_errors.log*
-rw-rw---- 1 mysql mysql 53994 Jul 30 10:28 sql_errors.log.4
-rw-rw---- 1 mysql mysql     0 Jul 30 10:28 sql_errors.log.3
-rw-rw---- 1 mysql mysql  1517 Jul 30 10:29 sql_errors.log.2
-rw-rw---- 1 mysql mysql     0 Jul 30 10:29 sql_errors.log.1
-rw-rw---- 1 mysql mysql  6337 Jul 30 10:34 sql_errors.log

You should think in the way of: FLUSH SQL_ERROR LOGS;

The variable itself always stays OFF:

SQL> SHOW GLOBAL VARIABLES LIKE 'sql_error_log_rotate';
+----------------------+-------+
| Variable_name        | Value |
+----------------------+-------+
| sql_error_log_rotate | OFF   |
+----------------------+-------+

Status Information

There are currently no status variables available to show how many errors were sent to the application.

Options

There is a configuration option NOT shown in the variable output: sql_error_log. Valid values are OFF, ON, FORCE and FORCE_PLUS_PERMANENT. It looks like that this option can only me used when injected directly into the call of the mysqld (mysqld_safe, systemd unit file, etc.) and thus it is useless for most cases because you do not want to change those things in production (upgrade, etc.).

Enabling/Disabling of the SQL Error Log

You can disable the SQL Error Log with the following command:

SQL> SET GLOBAL sql_error_log_rate = 0;

You enable it again by setting the value greater than 0.

Interpretation of the SQL Error Log

The format of the SQL Error Log looks roughly as follows: timestamp user[user] @ host[host] ERROR nnnn: Error Message : SQL Query

Here some examples:

shell> grep 2020 sql_errors.log 
2020-07-30 10:30:05 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'global_priv' : WITH password_expiration_info AS
  -- All users
2020-07-30 10:36:51 root[root] @ localhost [] ERROR 1064: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'on *.* to fpmmm_agent@'127.0.0.1'' at line 1 : grant binlog_monitor on *.* to fpmmm_agent@'127.0.0.1'
2020-07-30 10:37:05 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1227: Access denied; you need (at least one of) the SUPER, BINLOG MONITOR privilege(s) for this operation : SHOW BINARY LOGS
2020-07-30 10:40:03 [] @ localhost [127.0.0.1] ERROR 1158: Got an error reading communication packets : (null)

This helped us for example to identify easily what privileges were missing for our applications.

Aggregation of the SQL Error Log

A simple way to aggregate the SQL Error Log is the following command:

shell> cat sql_errors.log* | sed 's/users2020/users\n2020/' | grep ^2020 | cut -b21- | sort | uniq -c
     21 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'events_statements_current' : SELECT th.PROCESSLIST_USER AS user
      7 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'events_statements_summary_by_user_by_event_name' : SELECT user, SUM(sum_created_tmp_disk_tables) AS created_tmp_disk_tables
     22 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'global_priv' : WITH password_expiration_info AS
      7 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'threads' : SELECT processlist_user AS user, COUNT(*) AS connections
      7 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'threads' : SELECT th.processlist_user AS user, SUM(trx.trx_rows_locked) AS rows_locked
      7 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'threads' : SELECT trx.trx_started, trx.trx_query
     16 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'user' : SELECT DISTINCT user AS user FROM mysql.user
      8 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'user' : SELECT GROUP_CONCAT(CONCAT(user, "@", host) SEPARATOR ", ") AS account FROM mysql.user WHERE user = ""
      8 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'user' : SELECT GROUP_CONCAT(CONCAT(user, "@", host) SEPARATOR ", ") AS account FROM mysql.user WHERE user != "root" AND create_user_priv = "Y"
      8 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'user' : SELECT GROUP_CONCAT(CONCAT(user, "@", host) SEPARATOR ", ") AS account FROM mysql.user WHERE user != "root" AND grant_priv = "Y"
      8 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'user' : SELECT GROUP_CONCAT(CONCAT(user, "@", host) SEPARATOR ", ") AS account FROM mysql.user WHERE user = "root" AND host NOT IN ("localhost", "127.0.0.1", "::1", "chef")
      8 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1142: SELECT command denied to user 'fpmmm_agent'@'localhost' for table 'user' : SELECT GROUP_CONCAT(CONCAT(user, "@", host) SEPARATOR ", ") AS account FROM mysql.user WHERE user != "root" AND super_priv = "Y"
     20 fpmmm_agent[fpmmm_agent] @ localhost [127.0.0.1] ERROR 1227: Access denied; you need (at least one of) the SUPER, BINLOG MONITOR privilege(s) for this operation : SHOW BINARY LOGS
     32 [] @ localhost [127.0.0.1] ERROR 1158: Got an error reading communication packets : (null)
      1 [] @ localhost [] ERROR 1160: Got an error writing communication packets : (null)
      1 root[root] @ localhost [] ERROR 1049: Unknown database 'bla' : (null)
      1 root[root] @ localhost [] ERROR 1064: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'on *.* to fpmmm_agent@'127.0.0.1'' at line 1 : grant binlog_monitor on *.* to fpmmm_agent@'127.0.0.1'
      1 root[root] @ localhost [] ERROR 1064: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'SONAME 'sql_errlog'' at line 1 : UNINSTALL PLUGIN sql_error_log SONAME 'sql_errlog'
      1 root[root] @ localhost [] ERROR 1193: Unknown system variable 'sql_error_log_rotat' : set global sql_error_log_rotat=on
      1 root[root] @ localhost [] ERROR 1229: Variable 'sql_error_log_rotate' is a GLOBAL variable and should be set with SET GLOBAL : set session sql_error_log_rotate=on
      1 root[root] @ localhost [] ERROR 1238: Variable 'sql_error_log_filename' is a read only variable : set global sql_error_log_filename='/home/mysql/database_slow/mariadb-105/log/sql_errors.log'

The sed command was needed because it looks like not every new entry starts at the beginning of a new line (bug?).

How to get warnings

The default sql_mode in MariaDB 10.5 is set to:

SQL> SHOW GLOBAL VARIABLES LIKE 'sql_mode';
+---------------+-------------------------------------------------------------------------------------------+
| Variable_name | Value                                                                                     |
+---------------+-------------------------------------------------------------------------------------------+
| sql_mode      | STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION |
+---------------+-------------------------------------------------------------------------------------------+

by adding TRADITIONAL to the sql_mode:

SQL> SET SESSION sql_mode=concat(@@sql_mode, ',TRADITIONAL');

you can make the SQL Error Log plugin also aware of warnings:

SQL> insert into test.test values (null, 'Some data', '2020-02-31');
Query OK, 1 row affected, 1 warning (0.001 sec)

SQL> set session sql_mode=traditional;

SQL> insert into test.test values (null, 'Some data', '2020-02-31');
ERROR 1292 (22007): Incorrect datetime value: '2020-02-31' for column `test`.`test`.`ts` at row 1

Just for curiosity, this query was never logged to the SQL Error Log:

SQL> SELECT 5/0;
+------+
| 5/0  |
+------+
| NULL |
+------+
1 row in set, 1 warning (0.000 sec)

But this seems to be more of a parser issue?

Logging comments

Comments are also logged. But the MariaDB client by default strips comments away. When you run the MariaDB client with the --comment option they are present to the server:

shell> mariadb --user=root --comment test
SQL> /* some comment to find the problem */ insert into test.test values (5/0, 'Some data', '2020-02-31'); -- blub
ERROR 1365 (22012): Division by 0

And it will be shown in the SQL Error Log:

2020-07-30 11:23:31 root[root] @ localhost [] ERROR 1365: Division by 0 : insert into test.test values (5/0, 'Some data', '2020-02-31')
2020-07-30 11:23:08 root[root] @ localhost [] ERROR 1365: Division by 0 : /* some comment to find the problem */ insert into test.test values (5/0, 'Some data', '2020-02-31') -- blub

Summary

The SQL Error Log is a cool plugin which helps us to identify problems and bugs in the application. This is similar functionality like in MariaDB/MySQL PERFORMANCE_SCHEMA: Finding syntactically wrong/erroneous MySQL queries.

Taxonomy upgrade extras: 
mariadb
sql
error
logging
error log
syntax