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

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.3.17, 10.4.7, 10.4.12, 10.6.9, 10.7.4
Fix Version/s: 10.5.28, 10.6.21, 10.11.11, 11.4.5, 11.7.2
Component/s: Server
Labels:
None

Description

There's at least one code path, maybe more, in Log_to_csv_event_handler::log_slow() that logs an error, but does not print an actuall error message so that the cause / reason of the error is unclear.

  /* check that all columns exist */

  if (table->s->fields < 13)

    goto err;

Attachments

Issue Links

relates to

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

Closed

Activity

Ascending order - Click to sort in descending order

Hartmut Holzgraefe created issue - 2019-08-07 18:52

Elena Stepanova made changes - 2019-08-07 20:25

Field	Original Value	New Value
Component/s		Server [ 13907 ]
Fix Version/s		10.3 [ 22126 ]
Fix Version/s		10.4 [ 22408 ]
Assignee		Oleksandr Byelkin [ sanja ]

Oleksandr Byelkin added a comment - 2019-10-11 12:39

table->s->fields < 13 check (if it is users table) mean old system files earlier then 3.23 or the same (do not remember on the top of my head)

Oleksandr Byelkin added a comment - 2019-10-11 12:39 table->s->fields < 13 check (if it is users table) mean old system files earlier then 3.23 or the same (do not remember on the top of my head)

Hartmut Holzgraefe added a comment - 2019-10-11 13:56

sanja

This is current code still found in the 10.4 branch:

https://github.com/MariaDB/server/blob/10.4/sql/log.cc#L907

Hartmut Holzgraefe added a comment - 2019-10-11 13:56 sanja This is current code still found in the 10.4 branch: https://github.com/MariaDB/server/blob/10.4/sql/log.cc#L907

Sergei Golubchik made changes - 2019-10-14 10:36

Description

There's at least one code path, maybe more, in {{Log_to_csv_event_handler::
  log_slow()}} that logs an error, but does not print an actuall error message so that the cause / reason of the error is unclear.

{noformat}
  /* check that all columns exist */
  if (table->s->fields < 13)
    goto err;
{noformat}

There's at least one code path, maybe more, in {{Log_to_csv_event_handler::log_slow()}} that logs an error, but does not print an actuall error message so that the cause / reason of the error is unclear.

{noformat}
  /* check that all columns exist */
  if (table->s->fields < 13)
    goto err;
{noformat}

Wagner Bianchi (Inactive) made changes - 2020-06-26 17:05

Affects Version/s

10.4.12 [ 24019 ]

Hyo Lee made changes - 2020-12-03 09:01

Link

This issue relates to ~~MDEV-24339~~ [ ~~MDEV-24339~~ ]

Sergei Golubchik made changes - 2021-12-06 21:33

Workflow

MariaDB v3 [ 98778 ]

MariaDB v4 [ 141463 ]

Mitchell Lee added a comment - 2022-08-02 03:15

Still here.
on 10.7.4.
It rarely occurred.
And I set the config for slowlog to Table type
on Windows 11.

Mitchell Lee added a comment - 2022-08-02 03:15 Still here. on 10.7.4. It rarely occurred. And I set the config for slowlog to Table type on Windows 11.

Daniel Black made changes - 2022-08-02 04:06

Affects Version/s

10.7.4 [ 27504 ]

Allen Lee (Inactive) made changes - 2022-11-17 02:44

Affects Version/s

10.6.9 [ 27507 ]

Mitchell Lee added a comment - 2022-11-17 09:07

Update,
I havent seen the error with 10.7.6 for a while.
and
The 10.7.7 not yet occured within a week so far.

Mitchell Lee added a comment - 2022-11-17 09:07 Update, I havent seen the error with 10.7.6 for a while. and The 10.7.7 not yet occured within a week so far.

Julien Fritsch made changes - 2023-04-27 14:18

Fix Version/s

10.3 [ 22126 ]

Jira Automation (IT) made changes - 2024-07-04 03:32

Zendesk Related Tickets

153675 181811

Julien Fritsch made changes - 2025-01-10 10:58

Priority

Major [ 3 ]

Minor [ 4 ]

Sergei Golubchik made changes - 2025-01-12 21:17

Priority

Minor [ 4 ]

Major [ 3 ]

Sergei Golubchik made changes - 2025-01-12 21:18

Fix Version/s		10.5 [ 23123 ]
Fix Version/s		10.6 [ 24028 ]
Fix Version/s		10.11 [ 27614 ]
Fix Version/s		11.4 [ 29301 ]

Julien Fritsch made changes - 2025-01-13 08:30

Fix Version/s

10.4(EOL) [ 22408 ]

Julien Fritsch made changes - 2025-01-13 09:41

Priority

Major [ 3 ]

Critical [ 2 ]

Oleksandr Byelkin made changes - 2025-01-24 09:07

Labels

need_feedback

Julien Fritsch made changes - 2025-01-24 09:45

Status

Open [ 1 ]

Needs Feedback [ 10501 ]

Julien Fritsch made changes - 2025-01-24 09:45

Labels

need_feedback

Sergei Golubchik made changes - 2025-01-24 10:17

Status

Needs Feedback [ 10501 ]

Open [ 1 ]

Oleksandr Byelkin made changes - 2025-01-24 10:18

Status

Open [ 1 ]

In Progress [ 3 ]

Oleksandr Byelkin added a comment - 2025-01-24 12:14

it whould be nice to have some way to repeat... I made fix with a lot of reasons, but how to test I have not so much ideas

diff --git a/sql/log.cc b/sql/log.cc

index 32a1436f9a6..a34710b9a13 100644

--- a/sql/log.cc

+++ b/sql/log.cc

@@ -694,6 +694,7 @@ bool Log_to_csv_event_handler::

   TABLE_LIST table_list;

   TABLE *table;

+  char *cause= 0;

   bool result= TRUE;

   bool need_close= FALSE;

   bool need_pop= FALSE;

@@ -728,13 +729,19 @@ bool Log_to_csv_event_handler::

   need_pop= TRUE;

   if (!(table= open_log_table(thd, &table_list, &open_tables_backup)))

+  {

+    cause= (char *)"can't open file";

     goto err;

+  }

   need_close= TRUE;

   if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||

       table->file->ha_rnd_init_with_error(0))

+  {

+    cause= (char *)"can't initialize table handler";

     goto err;

+  }

   need_rnd_end= TRUE;

@@ -753,12 +760,20 @@ bool Log_to_csv_event_handler::

   /* check that all columns exist */

   if (table->s->fields < 6)

+  {

+    cause= (char *)"incorrect number of fields in the table";

     goto err;

+  }

   DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);

-  table->field[0]->store_timestamp(

-                  hrtime_to_my_time(event_time), hrtime_sec_part(event_time));

+  if (table->field[0]->store_timestamp(hrtime_to_my_time(event_time),

+                                       hrtime_sec_part(event_time)))

+  {

+    cause= (char *)"Can't write data (possible incorrect table structure)";

+    goto err;

+  }

   /* do a write */

   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,

                              TRUE) ||

       table->field[4]->store(command_type, command_type_len, client_cs))

+  {

+    cause= (char *)"Can't write data (possible incorrect table structure)";

     goto err;

+  }

/*

     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;

   if (table->field[5]->store(sql_text, sql_text_len, client_cs) < 0)

+  {

+    cause= (char *)"Can't write data (possible incorrect table structure)";

     goto err;

+  }

   /* mark all fields as not null */

   table->field[1]->set_notnull();

@@ -790,14 +811,20 @@ bool Log_to_csv_event_handler::

   if (table->file->ha_write_row(table->record[0]))

+  {

+    cause= (char *)"Can't write record";

     goto err;

+  }

   result= FALSE;

 err:

   if (result && !thd->killed)

-    sql_print_error("Failed to write to mysql.general_log: %s",

+  {

+    sql_print_error("Failed to write to mysql.general_log (%s): %s",

+                    cause,

                     error_handler.message());

+  }

   if (need_rnd_end)

@@ -850,6 +877,7 @@ bool Log_to_csv_event_handler::

   TABLE_LIST table_list;

   TABLE *table;

+  char *cause= 0;

   bool result= TRUE;

   bool need_close= FALSE;

   bool need_rnd_end= FALSE;

@@ -874,13 +902,19 @@ bool Log_to_csv_event_handler::

                             TL_WRITE_CONCURRENT_INSERT);

   if (!(table= open_log_table(thd, &table_list, &open_tables_backup)))

+  {

+    cause= (char *)"can't open file";

     goto err;

+  }

   need_close= TRUE;

   if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) ||

       table->file->ha_rnd_init_with_error(0))

+  {

+    cause= (char *)"can't initialize table handler";

     goto err;

+  }

   need_rnd_end= TRUE;

@@ -891,14 +925,18 @@ bool Log_to_csv_event_handler::

   /* check that all columns exist */

   if (table->s->fields < 13)

+  {

+    cause= (char *)"incorrect number of fields in the table";

     goto err;

+  }

   /* store the time and user values */

   DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);

-  table->field[0]->store_timestamp(

-             hrtime_to_my_time(current_time), hrtime_sec_part(current_time));

+  if(table->field[0]->store_timestamp(hrtime_to_my_time(current_time),

+                                      hrtime_sec_part(current_time)))

+    goto store_err;

   if (table->field[1]->store(user_host, user_host_len, client_cs))

-    goto err;

+    goto store_err;

/*

     A TIME field can not hold the full longlong range; query_time or

@@ -911,23 +949,23 @@ bool Log_to_csv_event_handler::

   /* fill in query_time field */

   calc_time_from_sec(&t, query_time, query_time_micro);

   if (table->field[2]->store_time(&t))

-    goto err;

+    goto store_err;

   /* lock_time */

   calc_time_from_sec(&t, lock_time, lock_time_micro);

   if (table->field[3]->store_time(&t))

-    goto err;

+    goto store_err;

   /* rows_sent */

   if (table->field[4]->store((longlong) thd->get_sent_row_count(), TRUE))

-    goto err;

+    goto store_err;

   /* rows_examined */

   if (table->field[5]->store((longlong) thd->get_examined_row_count(), TRUE))

-    goto err;

+    goto store_err;

   /* fill database field */

   if (thd->db.str)

     if (table->field[6]->store(thd->db.str, thd->db.length, client_cs))

-      goto err;

+      goto store_err;

     table->field[6]->set_notnull();

@@ -937,7 +975,7 @@ bool Log_to_csv_event_handler::

         field[7]->store((longlong)

                         thd->first_successful_insert_id_in_prev_stmt_for_binlog,

                         TRUE))

-      goto err;

+      goto store_err;

     table->field[7]->set_notnull();

@@ -952,12 +990,12 @@ bool Log_to_csv_event_handler::

     if (table->

         field[8]->store((longlong)

           thd->auto_inc_intervals_in_cur_stmt_for_binlog.minimum(), TRUE))

-      goto err;

+      goto store_err;

     table->field[8]->set_notnull();

   if (table->field[9]->store((longlong)global_system_variables.server_id, TRUE))

-    goto err;

+    goto store_err;

   table->field[9]->set_notnull();

/*

@@ -966,19 +1004,22 @@ bool Log_to_csv_event_handler::

     Still logging a message in the log in this case.

*/

   if (table->field[10]->store(sql_text, sql_text_len, client_cs) < 0)

-    goto err;

+    goto store_err;

   if (table->field[11]->store((longlong) thd->thread_id, TRUE))

-    goto err;

+    goto store_err;

   /* Rows_affected */

   if (table->field[12]->store(thd->get_stmt_da()->is_ok() ?

                               (longlong) thd->get_stmt_da()->affected_rows() :

                               0, TRUE))

-    goto err;

+    goto store_err;

   if (table->file->ha_write_row(table->record[0]))

+  {

+    cause= (char *)"Can't write record";

     goto err;

+  }

   result= FALSE;

@@ -986,7 +1027,8 @@ bool Log_to_csv_event_handler::

   thd->pop_internal_handler();

   if (result && !thd->killed)

-    sql_print_error("Failed to write to mysql.slow_log: %s",

+    sql_print_error("Failed to write to mysql.slow_log (%s): %s",

+                    cause,

                     error_handler.message());

   if (need_rnd_end)

@@ -998,6 +1040,9 @@ bool Log_to_csv_event_handler::

     close_log_table(thd, &open_tables_backup);

   thd->time_zone_used= save_time_zone_used;

   DBUG_RETURN(result);

+store_err: // spagetty, but reduce size of the code

+    cause= (char *)"Can't write data (possible incorrect table structure)";

+    goto err;

 int Log_to_csv_event_handler::

Oleksandr Byelkin added a comment - 2025-01-24 12:14 it whould be nice to have some way to repeat... I made fix with a lot of reasons, but how to test I have not so much ideas diff --git a/sql/log.cc b/sql/log.cc index 32a1436f9a6..a34710b9a13 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -694,6 +694,7 @@ bool Log_to_csv_event_handler:: { TABLE_LIST table_list; TABLE *table; + char *cause= 0; bool result= TRUE; bool need_close= FALSE; bool need_pop= FALSE; @@ -728,13 +729,19 @@ bool Log_to_csv_event_handler:: need_pop= TRUE; if (!(table= open_log_table(thd, &table_list, &open_tables_backup))) + { + cause= (char *)"can't open file"; goto err; + } need_close= TRUE; if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) || table->file->ha_rnd_init_with_error(0)) + { + cause= (char *)"can't initialize table handler"; goto err; + } need_rnd_end= TRUE; @@ -753,12 +760,20 @@ bool Log_to_csv_event_handler:: /* check that all columns exist */ if (table->s->fields < 6) + { + cause= (char *)"incorrect number of fields in the table"; goto err; + } DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP); - table->field[0]->store_timestamp( - hrtime_to_my_time(event_time), hrtime_sec_part(event_time)); + if (table->field[0]->store_timestamp(hrtime_to_my_time(event_time), + hrtime_sec_part(event_time))) + { + cause= (char *)"Can't write data (possible incorrect table structure)"; + goto err; + } + /* do a write */ 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, TRUE) || table->field[4]->store(command_type, command_type_len, client_cs)) + { + cause= (char *)"Can't write data (possible incorrect table structure)"; goto err; + } /* 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; if (table->field[5]->store(sql_text, sql_text_len, client_cs) < 0) + { + cause= (char *)"Can't write data (possible incorrect table structure)"; goto err; + } /* mark all fields as not null */ table->field[1]->set_notnull(); @@ -790,14 +811,20 @@ bool Log_to_csv_event_handler:: } if (table->file->ha_write_row(table->record[0])) + { + cause= (char *)"Can't write record"; goto err; + } result= FALSE; err: if (result && !thd->killed) - sql_print_error("Failed to write to mysql.general_log: %s", + { + sql_print_error("Failed to write to mysql.general_log (%s): %s", + cause, error_handler.message()); + } if (need_rnd_end) { @@ -850,6 +877,7 @@ bool Log_to_csv_event_handler:: { TABLE_LIST table_list; TABLE *table; + char *cause= 0; bool result= TRUE; bool need_close= FALSE; bool need_rnd_end= FALSE; @@ -874,13 +902,19 @@ bool Log_to_csv_event_handler:: TL_WRITE_CONCURRENT_INSERT); if (!(table= open_log_table(thd, &table_list, &open_tables_backup))) + { + cause= (char *)"can't open file"; goto err; + } need_close= TRUE; if (table->file->extra(HA_EXTRA_MARK_AS_LOG_TABLE) || table->file->ha_rnd_init_with_error(0)) + { + cause= (char *)"can't initialize table handler"; goto err; + } need_rnd_end= TRUE; @@ -891,14 +925,18 @@ bool Log_to_csv_event_handler:: /* check that all columns exist */ if (table->s->fields < 13) + { + cause= (char *)"incorrect number of fields in the table"; goto err; + } /* store the time and user values */ DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP); - table->field[0]->store_timestamp( - hrtime_to_my_time(current_time), hrtime_sec_part(current_time)); + if(table->field[0]->store_timestamp(hrtime_to_my_time(current_time), + hrtime_sec_part(current_time))) + goto store_err; if (table->field[1]->store(user_host, user_host_len, client_cs)) - goto err; + goto store_err; /* A TIME field can not hold the full longlong range; query_time or @@ -911,23 +949,23 @@ bool Log_to_csv_event_handler:: /* fill in query_time field */ calc_time_from_sec(&t, query_time, query_time_micro); if (table->field[2]->store_time(&t)) - goto err; + goto store_err; /* lock_time */ calc_time_from_sec(&t, lock_time, lock_time_micro); if (table->field[3]->store_time(&t)) - goto err; + goto store_err; /* rows_sent */ if (table->field[4]->store((longlong) thd->get_sent_row_count(), TRUE)) - goto err; + goto store_err; /* rows_examined */ if (table->field[5]->store((longlong) thd->get_examined_row_count(), TRUE)) - goto err; + goto store_err; /* fill database field */ if (thd->db.str) { if (table->field[6]->store(thd->db.str, thd->db.length, client_cs)) - goto err; + goto store_err; table->field[6]->set_notnull(); } @@ -937,7 +975,7 @@ bool Log_to_csv_event_handler:: field[7]->store((longlong) thd->first_successful_insert_id_in_prev_stmt_for_binlog, TRUE)) - goto err; + goto store_err; table->field[7]->set_notnull(); } @@ -952,12 +990,12 @@ bool Log_to_csv_event_handler:: if (table-> field[8]->store((longlong) thd->auto_inc_intervals_in_cur_stmt_for_binlog.minimum(), TRUE)) - goto err; + goto store_err; table->field[8]->set_notnull(); } if (table->field[9]->store((longlong)global_system_variables.server_id, TRUE)) - goto err; + goto store_err; table->field[9]->set_notnull(); /* @@ -966,19 +1004,22 @@ bool Log_to_csv_event_handler:: Still logging a message in the log in this case. */ if (table->field[10]->store(sql_text, sql_text_len, client_cs) < 0) - goto err; + goto store_err; if (table->field[11]->store((longlong) thd->thread_id, TRUE)) - goto err; + goto store_err; /* Rows_affected */ if (table->field[12]->store(thd->get_stmt_da()->is_ok() ? (longlong) thd->get_stmt_da()->affected_rows() : 0, TRUE)) - goto err; + goto store_err; if (table->file->ha_write_row(table->record[0])) + { + cause= (char *)"Can't write record"; goto err; + } result= FALSE; @@ -986,7 +1027,8 @@ bool Log_to_csv_event_handler:: thd->pop_internal_handler(); if (result && !thd->killed) - sql_print_error("Failed to write to mysql.slow_log: %s", + sql_print_error("Failed to write to mysql.slow_log (%s): %s", + cause, error_handler.message()); if (need_rnd_end) @@ -998,6 +1040,9 @@ bool Log_to_csv_event_handler:: close_log_table(thd, &open_tables_backup); thd->time_zone_used= save_time_zone_used; DBUG_RETURN(result); +store_err: // spagetty, but reduce size of the code + cause= (char *)"Can't write data (possible incorrect table structure)"; + goto err; } int Log_to_csv_event_handler::

Oleksandr Byelkin made changes - 2025-01-24 12:25

Status

In Progress [ 3 ]

Stalled [ 10000 ]

Oleksandr Byelkin made changes - 2025-01-24 12:55

Status

Stalled [ 10000 ]

In Progress [ 3 ]

Oleksandr Byelkin added a comment - 2025-01-24 16:14 - edited

commit 6a4b85ce1cca8ec07be460ddfeddfcd1908492fd (HEAD -> bb-10.5-MDEV-20281, origin/bb-10.5-MDEV-20281)

Author: Oleksandr Byelkin <sanja@mariadb.com>

Date:   Fri Jan 24 17:08:04 2025 +0100

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

    Add "backup" (in case of absence issued by error) reasons for failed logging.

Oleksandr Byelkin added a comment - 2025-01-24 16:14 - edited commit 6a4b85ce1cca8ec07be460ddfeddfcd1908492fd (HEAD -> bb-10.5-MDEV-20281, origin/bb-10.5-MDEV-20281) Author: Oleksandr Byelkin <sanja@mariadb.com> Date: Fri Jan 24 17:08:04 2025 +0100 MDEV-20281 "[ERROR] Failed to write to mysql.slow_log:" without error reason Add "backup" (in case of absence issued by error) reasons for failed logging.

Oleksandr Byelkin made changes - 2025-01-24 16:25

Assignee	Oleksandr Byelkin [ sanja ]	Sergei Golubchik [ serg ]
Status	In Progress [ 3 ]	In Review [ 10002 ]

Sergei Golubchik added a comment - 2025-01-25 15:45 - edited

ok to push after fixing as in the email review.

https://lists.mariadb.org/hyperkitty/list/developers@lists.mariadb.org/thread/VUY632VX6RQLQCWDDP7CHPK65SVBXFKM/

Sergei Golubchik added a comment - 2025-01-25 15:45 - edited ok to push after fixing as in the email review. https://lists.mariadb.org/hyperkitty/list/developers@lists.mariadb.org/thread/VUY632VX6RQLQCWDDP7CHPK65SVBXFKM/

Sergei Golubchik made changes - 2025-01-25 15:45

Assignee	Sergei Golubchik [ serg ]	Oleksandr Byelkin [ sanja ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Oleksandr Byelkin made changes - 2025-01-25 20:06

Fix Version/s		10.5.28 [ 29952 ]
Fix Version/s	10.5 [ 23123 ]
Fix Version/s	10.6 [ 24028 ]
Fix Version/s	10.11 [ 27614 ]
Fix Version/s	11.4 [ 29301 ]

Oleksandr Byelkin made changes - 2025-01-25 20:07

issue.field.resolutiondate

2025-01-25 20:07:20.0

2025-01-25 20:07:20.204

Oleksandr Byelkin made changes - 2025-01-25 20:07

Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

JiraAutomate made changes - 2025-01-25 20:07

Fix Version/s		10.6.21 [ 29953 ]
Fix Version/s		10.11.11 [ 29954 ]
Fix Version/s		11.4.5 [ 29956 ]
Fix Version/s		11.7.2 [ 29914 ]

People

Assignee:: Oleksandr Byelkin

Reporter:: Hartmut Holzgraefe

Votes:: 1 Vote for this issue

Watchers:: 10 Start watching this issue

Dates

Created:: 2019-08-07 18:52

Updated:: 2025-01-25 20:07

Resolved:: 2025-01-25 20:07

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration