[MDEV-24339] "[ERROR] Failed to write to mysql.slow_log:" without reason Created: 2020-12-03  Updated: 2022-11-04  Resolved: 2022-10-17

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.3.17, 10.3.23, 10.2.40
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Hyo Lee Assignee: Oleksandr Byelkin
Resolution: Incomplete Votes: 0
Labels: None
Environment:

Centos7

Issue Links:
Relates
relates to MDEV-20281 "[ERROR] Failed to write to mysql.slo... Open

 Description   

MariaDB is leaving error logs like below, without a cause of the error

2020-12-03 9:04:49 18292544 [ERROR] Failed to write to mysql.slow_log:
2020-12-03 12:45:52 18365665 [ERROR] Failed to write to mysql.slow_log:

There were no such huge queries or load at the given time.

I have no clue why this error occurs.

Please reply if you know anything about it

 Comments   
Comment by Daniel Black [ 2020-12-03 ]

looking at the code there is mean to be an error after these messages. What is the table structure of `show create table mysql.slow_log`?

It should be this structure: https://github.com/MariaDB/server/blob/10.3/scripts/mysql_system_tables.sql#L100

Comment by Hyo Lee [ 2020-12-04 ]

Thank you for the response Daniel Black

This is the table structure

CREATE TABLE `slow_log` (
 
  `start_time` timestamp(6) NOT NULL DEFAULT current_timestamp(6) ON UPDATE current_timestamp(6),
 
  `user_host` mediumtext NOT NULL,
 
  `query_time` time(6) NOT NULL,
 
  `lock_time` time(6) NOT NULL,
 
  `rows_sent` int(11) NOT NULL,
 
  `rows_examined` int(11) NOT NULL,
 
  `db` varchar(512) NOT NULL,
 
  `last_insert_id` int(11) NOT NULL,
 
  `insert_id` int(11) NOT NULL,
 
  `server_id` int(10) unsigned NOT NULL,
 
  `sql_text` mediumtext NOT NULL,
 
  `thread_id` bigint(21) unsigned NOT NULL,
 
  `rows_affected` int(11) NOT NULL,
 
  KEY `slow_log_01` (`start_time`),
 
  KEY `IX_SLOW_LOG_01` (`thread_id`)
 
) ENGINE=MyISAM DEFAULT CHARSET=utf8 COMMENT='Slow log'

I think it is not a table structure problem... but if you think it is, please let me know.

Thanks again

Comment by Alice Sherepa [ 2021-01-29 ]

I guess it might be the same bug as here https://bugs.mysql.com/bug.php?id=71377 (https://bugs.mysql.com/bug.php?id=37132)

Comment by Daniel Black [ 2021-09-14 ]

alice you're probably right. Any of these int fields could quite easily (or time - 35 days - maybe less easily) overflow and caused the error.

Comment by Daniel Black [ 2021-09-14 ]

Reproduced on 10.2

$ mariadblocal --log_output=TABLE --long_query_time=0.00001 --slow_query_log=1
 
Installing MariaDB/MySQL system tables in '/tmp/build-mariadb-server-10.2-datadir' ...
 
2021-09-14 21:11:07 140566304090304 [Note] /home/dan/repos/build-mariadb-server-10.2/sql/mysqld (mysqld 10.2.41-MariaDB) starting as process 2265527 ...
 
 
 
MariaDB [(none)]> set global log_output='FILE'; alter table mysql.slow_log engine=myisam;  set global log_output='TABLE';
 
Query OK, 0 rows affected (0.00 sec)
 
 
 
MariaDB [test]> select sum(seq) from seq_1_to_18446744073709551619 union all select sleep(1);
 
+----------+
 
| sum(seq) |
 
+----------+
 
|        0 |
 
|        0 |
 
+----------+
 
2 rows in set (1.01 sec)
 
 
 
MariaDB [test]> select * from mysql.slow_log ;
 
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+------------------------------------------------------------------------------+-----------+---------------+
 
| start_time                 | user_host                 | query_time      | lock_time       | rows_sent | rows_examined | db   | last_insert_id | insert_id | server_id | sql_text                                                                     | thread_id | rows_affected |
 
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+------------------------------------------------------------------------------+-----------+---------------+
 
| 2021-09-14 21:32:03.287764 | root[root] @ localhost [] | 00:00:00.000164 | 00:00:00.000000 |         0 |             0 |      |              0 |         0 |         1 | truncate table mysql.slow_log                                                |        20 |             0 |
 
| 2021-09-14 21:32:07.477644 | root[root] @ localhost [] | 00:00:00.000201 | 00:00:00.000000 |         0 |             0 |      |              0 |         0 |         1 | show create table mysql.slow_log                                             |        20 |             0 |
 
| 2021-09-14 21:32:10.395192 | root[root] @ localhost [] | 00:00:00.000051 | 00:00:00.000000 |         0 |          NULL |      |              0 |         0 |         1 | set global log_output='TABLE'                                                |        20 |             0 |
 
| 2021-09-14 21:32:25.007978 | root[root] @ localhost [] | 00:00:00.000116 | 00:00:00.000000 |         0 |          NULL |      |              0 |         0 |         1 | select sum(seq) from seq_1_to_18446744073709551619                           |        20 |             0 |
 
| 2021-09-14 21:32:28.586502 | root[root] @ localhost [] | 00:00:00.000048 | 00:00:00.000000 |         1 |          NULL |      |              0 |         0 |         1 | SELECT DATABASE()                                                            |        20 |             0 |
 
| 2021-09-14 21:32:28.587404 | root[root] @ localhost [] | 00:00:00.000102 | 00:00:00.000033 |         4 |          NULL | test |              0 |         0 |         1 | show databases                                                               |        20 |             0 |
 
| 2021-09-14 21:32:28.587562 | root[root] @ localhost [] | 00:00:00.000051 | 00:00:00.000019 |         0 |          NULL | test |              0 |         0 |         1 | show tables                                                                  |        20 |             0 |
 
| 2021-09-14 21:32:29.699222 | root[root] @ localhost [] | 00:00:00.000235 | 00:00:00.000099 |         1 |          NULL | test |              0 |         0 |         1 | select sum(seq) from seq_1_to_18446744073709551619                           |        20 |             0 |
 
| 2021-09-14 21:33:00.803729 | root[root] @ localhost [] | 00:00:00.000021 | 00:00:00.000000 |         0 |          NULL |      |              0 |         0 |         1 | KILL QUERY 20                                                                |        21 |             0 |
 
| 2021-09-14 21:33:21.390550 | root[root] @ localhost [] | 00:00:01.000593 | 00:00:00.000139 |         2 |          NULL | test |              0 |         0 |         1 | select sum(seq) from seq_1_to_18446744073709551619 union all select sleep(1) |        20 |             0 |
 
| 2021-09-14 21:33:40.134965 | root[root] @ localhost [] | 00:00:00.000051 | 00:00:00.000000 |         0 |          NULL | test |              0 |         0 |         1 | set global log_output='TABLE'                                                |        20 |             0 |
 
| 2021-09-14 21:33:44.595045 | root[root] @ localhost [] | 00:00:01.000540 | 00:00:00.000136 |         2 |          NULL | test |              0 |         0 |         1 | select sum(seq) from seq_1_to_18446744073709551619 union all select sleep(1) |        20 |             0 |
 
| 2021-09-14 21:34:46.141738 | root[root] @ localhost [] | 00:00:00.000155 | 00:00:00.000000 |         0 |          NULL | test |              0 |         0 |         1 | show create table mysql.slow_log                                             |        20 |             0 |
 
+----------------------------+---------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+------------------------------------------------------------------------------+-----------+---------------+
 
13 rows in set (0.00 sec)
 
 
 
 
 
 
 
error log:
 
 
 
Version: '10.2.41-MariaDB-log'  socket: '/tmp/build-mariadb-server-10.2.sock'  port: 0  Source distribution
 
2021-09-14 21:33:00 139666930255424 [ERROR] Failed to write to mysql.slow_log:

Comment by Daniel Black [ 2021-09-14 ]

actually test case above is not the reproductions. It may have been the alter table to myisam.

Generated at Thu Feb 08 09:29:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.