[#MDEV-25498] MySQL 5.7.34 crash with signal 11 when server

Comment by Elena Stepanova [ 2021-04-25 ]

I tried plugin from the current 10.4 (plugin version 1.4.13)

MySQL 5.7.34
#3 <signal handler called>
#4 0x00007fb7ddbb68b3 in get_db_mysql57 (thd=0x7fb78c000e10, name=0x7fb7dc17f940, len=0x7fb7dc17f948) at /data/src/10.4/plugin/server_audit/server_audit.c:2390
#5 0x00007fb7ddbb80a3 in auditing_v4 (thd=0x7fb78c000e10, class=MYSQL_AUDIT_GENERAL_CLASS, ev=0x7fb7dc17fad0) at /data/src/10.4/plugin/server_audit/test_audit_v4.c:68
#6 0x000055a9d6459130 in plugins_dispatch (thd=0x7fb78c000e10, plugin=0x55a9d98a8c90, arg=0x7fb7dc17f9f0) at /data/src/mysql-5.7/sql/sql_audit.cc:1398
#7 0x000055a9d645924b in event_class_dispatch (thd=0x7fb78c000e10, event_class=MYSQL_AUDIT_GENERAL_CLASS, event=0x7fb7dc17fad0) at /data/src/mysql-5.7/sql/sql_audit.cc:1439
#8 0x000055a9d645930f in event_class_dispatch_error (thd=0x7fb78c000e10, event_class=MYSQL_AUDIT_GENERAL_CLASS, event_name=0x55a9d75d3a25 "MYSQL_AUDIT_GENERAL_LOG", event=0x7fb7dc17fad0) at /data/src/mysql-5.7/sql/sql_audit.cc:1461
#9 0x000055a9d645770e in mysql_audit_notify (thd=0x7fb78c000e10, subclass=MYSQL_AUDIT_GENERAL_LOG, subclass_name=0x55a9d75d3a25 "MYSQL_AUDIT_GENERAL_LOG", error_code=0, msg=0x55a9d7681a1e "Connect", msg_len=7) at /data/src/mysql-5.7/sql/sql_audit.cc:478
#10 0x000055a9d6a5c194 in mysql_audit_general_log (thd=0x7fb78c000e10, cmd=0x55a9d7681a1e "Connect", cmdlen=7) at /data/src/mysql-5.7/sql/sql_audit.h:100
#11 0x000055a9d6a6083d in Query_logger::general_log_print (this=0x55a9d8078960 <query_logger>, thd=0x7fb78c000e10, command=COM_CONNECT, format=0x55a9d74b78c8 "%s@%s on %s using %s") at /data/src/mysql-5.7/sql/log.cc:1503
#12 0x000055a9d64682d7 in acl_log_connect (user=0x7fb78c0263d0 "root", host=0x7fb78c00e7d0 "localhost", auth_as=0x7fb7dc1804d8 "root", db=0x7fb78c006488 "", thd=0x7fb78c000e10, command=COM_CONNECT) at /data/src/mysql-5.7/sql/auth/sql_authentication.cc:2143
#13 0x000055a9d64688e9 in acl_authenticate (thd=0x7fb78c000e10, command=COM_CONNECT) at /data/src/mysql-5.7/sql/auth/sql_authentication.cc:2287
#14 0x000055a9d6b24ea6 in check_connection (thd=0x7fb78c000e10) at /data/src/mysql-5.7/sql/sql_connect.cc:691
#15 0x000055a9d6b25033 in login_connection (thd=0x7fb78c000e10) at /data/src/mysql-5.7/sql/sql_connect.cc:747
#16 0x000055a9d6b257e8 in thd_prepare_connection (thd=0x7fb78c000e10) at /data/src/mysql-5.7/sql/sql_connect.cc:899
#17 0x000055a9d6cc22fa in handle_connection (arg=0x55a9d98a8c70) at /data/src/mysql-5.7/sql/conn_handler/connection_handler_per_thread.cc:307
#18 0x000055a9d73cf0fd in pfs_spawn_thread (arg=0x55a9d9921f30) at /data/src/mysql-5.7/storage/perfschema/pfs.cc:2197
#19 0x00007fb7e7598609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#20 0x00007fb7e7174293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

With MySQL 5.7.33 the same plugin library works all right (or at least it doesn't crash on startup).

Comment by Ralf Gebhardt [ 2021-04-27 ]

Hi frelist, could you also reproduce this with issue with MariaDB Server? If yes, please let us know which version you used that we can work on a fix.

Comment by William Wong [ 2021-04-29 ]

Hi Ralf, we cannot reproduce this issue in MariaDB. We have some production DB using MariaDB 10.5.8 without issue.

Comment by Kyle Bresin [ 2021-04-29 ]

The sql_audit.cc stack trace there, along with the following changelog from MySQL 5.7.34:

* Sessions could disable their own auditing. (Bug #31630954)"

got me interested into what exactly MySQL changed...

Here's the change from 5.7.33 => 5.7.34:

--- ./mysql-5.7.33/sql/sql_audit.cc	2020-12-09 21:01:55.000000000 -0600

+++ ./mysql-5.7.34/sql/sql_audit.cc	2021-03-26 01:58:52.000000000 -0500

@@ -1,4 +1,4 @@

-/* Copyright (c) 2007, 2019, Oracle and/or its affiliates. All rights reserved.

+/* Copyright (c) 2007, 2021, Oracle and/or its affiliates.

    This program is free software; you can redistribute it and/or modify

    it under the terms of the GNU General Public License, version 2.0,

@@ -433,7 +433,7 @@ int mysql_audit_notify(THD *thd, mysql_e

   mysql_event_general event;

   char user_buff[MAX_USER_HOST_SIZE];

-  DBUG_ASSERT(thd);

+  assert(thd);

   if (mysql_audit_acquire_plugins(thd, MYSQL_AUDIT_GENERAL_CLASS,

                                   static_cast<unsigned long>(subclass)))

@@ -1215,7 +1215,7 @@ void mysql_audit_init_thd(THD *thd)

 void mysql_audit_free_thd(THD *thd)

   mysql_audit_release(thd);

-  DBUG_ASSERT(thd->audit_class_plugins.empty());

+  assert(thd->audit_class_plugins.empty());

Kind of looks like they were messing with audit log plugin logic? And maybe mariadb is friendly fire?

Comment by Kyle Bresin [ 2021-04-30 ]

Nevermind, looks like they just renamed the debug assertion, I don't think that is the culprit...

Comment by Kyle Bresin [ 2021-04-30 ]

A bit more context.

MySQL 5.7.34 starts up fine with the mariadb server_audit.so plugin installed.

It only crashes upon a client connect:

$ mysql

ERROR 2013 (HY000): Lost connection to MySQL server at 'reading authorization packet', system error: 95

Note, it does this even if the user/pass is invalid:

$ mysql -u noper

ERROR 2013 (HY000): Lost connection to MySQL server at 'reading authorization packet', system error: 95

It also does this even if server_audit_logging=OFF.

Or if connect is removed from server_audit_events.

Comment by minlei sun (Inactive) [ 2021-05-02 ]

This is caused by the problem of get_db_mysql57.

Breakpoint 1, get_db_mysql57 (thd=0x7f0fd8000d80, name=0x7f0feb2927d0, len=0x7f0feb2927d8) at /root/mariadb-10.5.9/plugin/server_audit/server_audit.c:2346

2346      if (debug_server_started)

(gdb) n

2349        db_off= 608;

(gdb)

2350        db_len_off= 616;

(gdb)

2367      *name= *(char **) (((char *) thd) + db_off);

(gdb) p name

$1 = (char **) 0x7f0feb2927d0

(gdb) p *name

$2 = 0x1 <Address 0x1 out of bounds>

(gdb) n

2368      *len= *((size_t *) (((char*) thd) + db_len_off));(gdb)

2369      if (*name && (*name)[*len] != 0)

(gdb) p *len

$3 = 0

So the convenient way is to modify the auditing_v4 function in the test_audit_v4.c file, just comment the get_db_mysql57(...)
such as

 ev_302.general_time= event->general_time;

    ev_302.general_rows= event->general_rows;

    //if (get_db_mysql57(thd, &ev_302.database, &ev_302.database_length))

//{

      ev_302.database= 0;

      ev_302.database_length= 0;

//}

    ev= &ev_302;

    switch (subclass_orig)

Comment by Alexey Botchkov [ 2021-05-03 ]

Looks like MySQL changed the THD structure in the version 5.7.34.
That has to be reflected in the get_db_mysql57 as it tries to get the database name using the offset of the THD::m_db.

Comment by Ralf Gebhardt [ 2021-05-03 ]

holyfoot, as we obviously test the MariaDB Audit Plugin against MariaDB Server we never will catch such changes. If MySQL is doing such changes in a maintenance release, from my point of view it is best to clearly document that the plugin does not support MySQL 5.7 instead of updating offsets whenever MySQL is doing changes.

Comment by Kyle Bresin [ 2021-05-03 ]

I agree with Ralf, that this behavior by MySQL is poor.

That said, the maria side fix would go into a function whose sole purpose seems to be for mysql 5.7 compatibility? (get_db_mysql57).

IMHO, responding to an anti-community action with another anti-community action only harms OS db communities, which (honestly) seems to be the entire goal of Oracle purchasing MySQL...

That said, I totally get that it seems unfair that MySQL made this mess, but seem unwilling to own, or even discuss it.

So I earnestly hope the mariadb community is better than they are.

Comment by Kyle Bresin [ 2021-05-03 ]

minlei, I was able to confirm that your proposed patch worked for me, recompliling mariadb server_audit.so plugin with that fix made the plugin not crash on mysql 5.7.34. Thanks so much for looking into it, I really appreciate it!

Comment by Ralf Gebhardt [ 2021-05-03 ]

kbresin, we for sure still can get added a fix for mysql 5.7 to the MariaDB Audit plugin, as long as it does not do any harm to the use with MariaDB Server. But we cannot state MySQL 5.7 "to be supported", and maybe should add a comment also in the code that this part of the code is not tested.

Comment by Modasir Khan [ 2021-05-21 ]

Thanks - When will a fix be available for this ? Will a server_audit.so compatible with MySQL 5.7.34be available to download ?

Comment by Alexey Botchkov [ 2021-05-21 ]

The fix commenting get_db_mysql57() works correctly most of the time. Though sometimes the database name in log record will be empty.
Guess it's fine for now, bug i'd fix this by fixing the offset for the recent MySQL later.

Comment by Modasir Khan [ 2021-06-06 ]

Any update on when the fix would be available for this issue ?

Comment by Dennis Elling [ 2021-10-12 ]

Like holyfoot said, the THD structure has changed in 5.7.34 with this Fix: "Bug #32628376"

sql/sql_class.h:

  LEX_CSTRING m_query_string;

  String m_normalized_query;

+ volatile int32 m_safe_to_display;

  LEX_CSTRING m_catalog;

  LEX_CSTRING m_db;

Increasing the offset by 8 bytes and recompiling worked for me without commenting the get_db_mysql57 function.
The database name is written in the audit logfile as normally.
Of course the fix is only compatible with MySQL Versions >5.7.33

--- a/plugin/server_audit/server_audit.c

+++ b/plugin/server_audit/server_audit.c

@@ -2377,8 +2377,8 @@ int get_db_mysql57(MYSQL_THD thd, char **name, size_t *len)

   else

 #ifdef __x86_64__

-    db_off= 536;

-    db_len_off= 544;

+    db_off= 544;

+    db_len_off= 552;

 #else

     db_off= 0;

     db_len_off= 0;

[MDEV-25498] MySQL 5.7.34 crash with signal 11 when server_audit.so installed Created: 2021-04-23 Updated: 2023-04-24 Resolved: 2023-04-24
Status:	Closed
Project:	MariaDB Server
Component/s:	Plugin - Audit
Affects Version/s:	N/A
Fix Version/s:	N/A

[MDEV-25498] MySQL 5.7.34 crash with signal 11 when server_audit.so installed Created: 2021-04-23 Updated: 2023-04-24 Resolved: 2023-04-24