mirror/mariadb
1
0
Fork 0
mirror of https://github.com/MariaDB/server.git synced 2025-01-27 17:33:44 +01:00
Code Issues Projects Releases Packages Wiki Activity Actions

MDEV-20281 "[ERROR] Failed to write to mysql.slow_log:" without error reason

Browse source 
Add "backup" (in case of absence issued by error) reasons for failed logging.
This commit is contained in:
Oleksandr Byelkin 2025-01-24 17:08:04 +01:00
parent d598ee3cf9
commit 47f87c5f88
3 changed files with 280 additions and 6 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

108
mysql-test/main/slowlog_integrity.result Normal file
View file

@ -0,0 +1,108 @@
#
# MDEV-20281 "[ERROR] Failed to write to mysql.slow_log:" without
# error reason
#
call mtr.add_suppression("Failed to write to mysql.slow_log:");
SET @old_slow_query_log= @@global.slow_query_log;
SET @old_log_output= @@global.log_output;
SET @old_long_query_time= @@long_query_time;
SET GLOBAL log_output= "TABLE";
SET GLOBAL slow_query_log= ON;
SET SESSION long_query_time= 0;
select 1 from dual;
1
1
show create table mysql.slow_log;
Table Create Table
slow_log 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` bigint(20) unsigned NOT NULL,
`rows_examined` bigint(20) unsigned 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` bigint(20) unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log'
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= "FILE";
SET GLOBAL slow_query_log= OFF;
drop table mysql.slow_log;
# one field missing
CREATE TABLE mysql.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` bigint(20) unsigned NOT NULL,
`rows_examined` bigint(20) unsigned 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
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log';
SET GLOBAL log_output= "TABLE";
SET GLOBAL slow_query_log= ON;
SET SESSION long_query_time= 0;
select 1 from dual;
1
1
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= "FILE";
SET GLOBAL slow_query_log= OFF;
drop table mysql.slow_log;
# crazy types
CREATE TABLE mysql.slow_log (
`start_time` timestamp(6) NOT NULL DEFAULT current_timestamp(6) ON UPDATE current_timestamp(6),
`user_host` ENUM('apple','orange','pear') NOT NULL,
`query_time` ENUM('apple','orange','pear') NOT NULL,
`lock_time` ENUM('apple','orange','pear') NOT NULL,
`rows_sent` ENUM('apple','orange','pear') NOT NULL,
`rows_examined` ENUM('apple','orange','pear') NOT NULL,
`db` ENUM('apple','orange','pear') NOT NULL,
`last_insert_id` ENUM('apple','orange','pear') NOT NULL,
`insert_id` ENUM('apple','orange','pear') NOT NULL,
`server_id` ENUM('apple','orange','pear') NOT NULL,
`sql_text` ENUM('apple','orange','pear') NOT NULL,
`thread_id` ENUM('apple','orange','pear') NOT NULL,
`rows_affected` ENUM('apple','orange','pear') NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log';
SET GLOBAL log_output= "TABLE";
SET GLOBAL slow_query_log= ON;
SET SESSION long_query_time= 0;
select 1 from dual;
1
1
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= "FILE";
SET GLOBAL slow_query_log= OFF;
drop table mysql.slow_log;
# restore normal slow log table
CREATE TABLE mysql.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` bigint(20) unsigned NOT NULL,
`rows_examined` bigint(20) unsigned 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` bigint(20) unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log';
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= @old_log_output;
SET @@global.slow_query_log= @old_slow_query_log;
FOUND 2 /incorrect number of fields in the log table/ in mysqld.1.err
FOUND 2 /Can't write data \(possible incorrect log table structure\)/ in mysqld.1.err
# End of 10.5 tests

113
mysql-test/main/slowlog_integrity.test Normal file
View file

@ -0,0 +1,113 @@
source include/not_embedded.inc;
--echo #
--echo # MDEV-20281 "[ERROR] Failed to write to mysql.slow_log:" without
--echo # error reason
--echo #
call mtr.add_suppression("Failed to write to mysql.slow_log:");
--disable_ps_protocol
SET @old_slow_query_log= @@global.slow_query_log;
SET @old_log_output= @@global.log_output;
SET @old_long_query_time= @@long_query_time;
SET GLOBAL log_output= "TABLE";
SET GLOBAL slow_query_log= ON;
SET SESSION long_query_time= 0;
select 1 from dual;
show create table mysql.slow_log;
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= "FILE";
SET GLOBAL slow_query_log= OFF;
drop table mysql.slow_log;
--echo # one field missing
CREATE TABLE mysql.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` bigint(20) unsigned NOT NULL,
`rows_examined` bigint(20) unsigned 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
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log';
SET GLOBAL log_output= "TABLE";
SET GLOBAL slow_query_log= ON;
SET SESSION long_query_time= 0;
select 1 from dual;
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= "FILE";
SET GLOBAL slow_query_log= OFF;
drop table mysql.slow_log;
--echo # crazy types
CREATE TABLE mysql.slow_log (
`start_time` timestamp(6) NOT NULL DEFAULT current_timestamp(6) ON UPDATE current_timestamp(6),
`user_host` ENUM('apple','orange','pear') NOT NULL,
`query_time` ENUM('apple','orange','pear') NOT NULL,
`lock_time` ENUM('apple','orange','pear') NOT NULL,
`rows_sent` ENUM('apple','orange','pear') NOT NULL,
`rows_examined` ENUM('apple','orange','pear') NOT NULL,
`db` ENUM('apple','orange','pear') NOT NULL,
`last_insert_id` ENUM('apple','orange','pear') NOT NULL,
`insert_id` ENUM('apple','orange','pear') NOT NULL,
`server_id` ENUM('apple','orange','pear') NOT NULL,
`sql_text` ENUM('apple','orange','pear') NOT NULL,
`thread_id` ENUM('apple','orange','pear') NOT NULL,
`rows_affected` ENUM('apple','orange','pear') NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log';
SET GLOBAL log_output= "TABLE";
SET GLOBAL slow_query_log= ON;
SET SESSION long_query_time= 0;
select 1 from dual;
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= "FILE";
SET GLOBAL slow_query_log= OFF;
drop table mysql.slow_log;
--echo # restore normal slow log table
CREATE TABLE mysql.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` bigint(20) unsigned NOT NULL,
`rows_examined` bigint(20) unsigned 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` bigint(20) unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COLLATE=utf8_general_ci COMMENT='Slow log';
SET @@long_query_time= @old_long_query_time;
SET @@global.log_output= @old_log_output;
SET @@global.slow_query_log= @old_slow_query_log;
--enable_ps_protocol
--let SEARCH_FILE=$MYSQLTEST_VARDIR/log/mysqld.1.err
--let SEARCH_PATTERN=incorrect number of fields in the log table
--source include/search_pattern_in_file.inc
--let SEARCH_PATTERN=Can't write data \(possible incorrect log table structure\)
--source include/search_pattern_in_file.inc
--echo # End of 10.5 tests

65
sql/log.cc
View file

@ -694,6 +694,7 @@ bool Log_to_csv_event_handler::
{ {
TABLE_LIST table_list; TABLE_LIST table_list;
TABLE *table; TABLE *table;
const char *cause= 0;
bool result= TRUE; bool result= TRUE;
bool need_close= FALSE; bool need_close= FALSE;
bool need_pop= FALSE; bool need_pop= FALSE;
@ -728,13 +729,19 @@ bool Log_to_csv_event_handler::
need_pop= TRUE; need_pop= TRUE;
if (!(table= open_log_table(thd, &table_list, &open_tables_backup))) if (!(table= open_log_table(thd, &table_list, &open_tables_backup)))
{
cause= "can't open file";
goto err; goto err;
}
need_close= TRUE; need_close= TRUE;
if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) || if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||
table->file->ha_rnd_init_with_error(0)) table->file->ha_rnd_init_with_error(0))
{
cause= "can't initialize table handler";
goto err; goto err;
}
need_rnd_end= TRUE; need_rnd_end= TRUE;
@ -753,12 +760,20 @@ bool Log_to_csv_event_handler::
/* check that all columns exist */ /* check that all columns exist */
if (table->s->fields < 6) if (table->s->fields < 6)
{
cause= "incorrect number of fields in the log table";
goto err; goto err;
}
DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP); DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);
table->field[0]->store_timestamp( if (table->field[0]->store_timestamp(hrtime_to_my_time(event_time),
hrtime_to_my_time(event_time), hrtime_sec_part(event_time)); hrtime_sec_part(event_time)))
{
cause= "Can't write data (possible incorrect log table structure)";
goto err;
}
/* do a write */ /* do a write */
if (table->field[1]->store(user_host, user_host_len, client_cs) || if (table->field[1]->store(user_host, user_host_len, client_cs) ||
@ -766,7 +781,10 @@ bool Log_to_csv_event_handler::
table->field[3]->store((longlong) global_system_variables.server_id, table->field[3]->store((longlong) global_system_variables.server_id,
TRUE) || TRUE) ||
table->field[4]->store(command_type, command_type_len, client_cs)) table->field[4]->store(command_type, command_type_len, client_cs))
{
cause= "Can't write data (possible incorrect log table structure)";
goto err; goto err;
}
/* /*
A positive return value in store() means truncation. A positive return value in store() means truncation.
@ -774,7 +792,10 @@ bool Log_to_csv_event_handler::
*/ */
table->field[5]->flags|= FIELDFLAG_HEX_ESCAPE; table->field[5]->flags|= FIELDFLAG_HEX_ESCAPE;
if (table->field[5]->store(sql_text, sql_text_len, client_cs) < 0) if (table->field[5]->store(sql_text, sql_text_len, client_cs) < 0)
{
cause= "Can't write data (possible incorrect log table structure)";
goto err; goto err;
}
/* mark all fields as not null */ /* mark all fields as not null */
table->field[1]->set_notnull(); table->field[1]->set_notnull();
@ -790,14 +811,22 @@ bool Log_to_csv_event_handler::
} }
if (table->file->ha_write_row(table->record[0])) if (table->file->ha_write_row(table->record[0]))
{
cause= "Can't write record";
goto err; goto err;
}
result= FALSE; result= FALSE;
err: err:
if (result && !thd->killed) if (result && !thd->killed)
{
const char *msg= error_handler.message();
if (!msg || !msg[0])
msg= cause;
sql_print_error("Failed to write to mysql.general_log: %s", sql_print_error("Failed to write to mysql.general_log: %s",
error_handler.message()); msg);
}
if (need_rnd_end) if (need_rnd_end)
{ {
@ -850,6 +879,8 @@ bool Log_to_csv_event_handler::
{ {
TABLE_LIST table_list; TABLE_LIST table_list;
TABLE *table; TABLE *table;
const char *cause= 0;
const char *msg;
bool result= TRUE; bool result= TRUE;
bool need_close= FALSE; bool need_close= FALSE;
bool need_rnd_end= FALSE; bool need_rnd_end= FALSE;
@ -874,13 +905,19 @@ bool Log_to_csv_event_handler::
TL_WRITE_CONCURRENT_INSERT); TL_WRITE_CONCURRENT_INSERT);
if (!(table= open_log_table(thd, &table_list, &open_tables_backup))) if (!(table= open_log_table(thd, &table_list, &open_tables_backup)))
{
cause= "can't open file";
goto err; goto err;
}
need_close= TRUE; need_close= TRUE;
if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) || if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||
table->file->ha_rnd_init_with_error(0)) table->file->ha_rnd_init_with_error(0))
{
cause= "can't initialize table handler";
goto err; goto err;
}
need_rnd_end= TRUE; need_rnd_end= TRUE;
@ -891,12 +928,19 @@ bool Log_to_csv_event_handler::
/* check that all columns exist */ /* check that all columns exist */
if (table->s->fields < 13) if (table->s->fields < 13)
{
cause= "incorrect number of fields in the log table";
goto err; goto err;
}
// It can be used in 13 places below so assign it here
cause= "Can't write data (possible incorrect log table structure)";
/* store the time and user values */ /* store the time and user values */
DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP); DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);
table->field[0]->store_timestamp( if(table->field[0]->store_timestamp(hrtime_to_my_time(current_time),
hrtime_to_my_time(current_time), hrtime_sec_part(current_time)); hrtime_sec_part(current_time)))
goto err;
if (table->field[1]->store(user_host, user_host_len, client_cs)) if (table->field[1]->store(user_host, user_host_len, client_cs))
goto err; goto err;
@ -976,9 +1020,13 @@ bool Log_to_csv_event_handler::
(longlong) thd->get_stmt_da()->affected_rows() : (longlong) thd->get_stmt_da()->affected_rows() :
0, TRUE)) 0, TRUE))
goto err; goto err;
cause= 0; // just for safety
if (table->file->ha_write_row(table->record[0])) if (table->file->ha_write_row(table->record[0]))
{
cause= "Can't write record";
goto err; goto err;
}
result= FALSE; result= FALSE;
@ -986,8 +1034,13 @@ err:
thd->pop_internal_handler(); thd->pop_internal_handler();
if (result && !thd->killed) if (result && !thd->killed)
{
msg= error_handler.message();
if (!msg || !msg[0])
msg= cause;
sql_print_error("Failed to write to mysql.slow_log: %s", sql_print_error("Failed to write to mysql.slow_log: %s",
error_handler.message()); msg);
}
if (need_rnd_end) if (need_rnd_end)
{ {