Debug assertion `thd == _current_thd()' failed with audit_log plugin turned on when "too many connections" error occured

[Roel Van de Paar]

2016-10-13 16:17:04 31523 [Note] /sda/COMP8-PS131016-percona-server-5.6.33-78.0-linux-x86_64-debug/bin/mysqld: ready for connections.
Version: '5.6.33-78.0-debug-log' socket: '/dev/shm/454302/283/socket.sock' port: 52004 MySQL Community Server (GPL)
mysqld: /git/COMP-PS-5.6.33_dbg/sql/sql_plugin.cc:3114: void plugin_thdvar_safe_update(THD*, st_mysql_sys_var*, char**, const char*): Assertion `thd == _current_thd()' failed.
05:17:04 UTC - mysqld got signal 6 ;

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/sda/COMP8-PS131016-percona-server-5.6.33-78.0-linux-x86_64-debug/bin/mysqld --'.
Program terminated with signal 6, Aborted.
#0 0x00007f1b81708741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
61 val = INTERNAL_SYSCALL (tgkill, err, 3, THREAD_GETMEM (THREAD_SELF, pid),
(gdb) bt
+bt
#0 0x00007f1b81708741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x0000000000ac271a in my_write_core (sig=6) at /git/COMP-PS-5.6.33_dbg/mysys/stacktrace.c:422
#2 0x0000000000736903 in handle_fatal_signal (sig=6) at /git/COMP-PS-5.6.33_dbg/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x00007f1b7fa9f5f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5 0x00007f1b7faa0ce8 in __GI_abort () at abort.c:90
#6 0x00007f1b7fa98566 in __assert_fail_base (fmt=0x7f1b7fbe8ce8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0xedb75b "thd == _current_thd()", file=file@entry=0xedad30 "/git/COMP-PS-5.6.33_dbg/sql/sql_plugin.cc", line=line@entry=3114, function=function@entry=0xedbf60 <plugin_thdvar_safe_update::__PRETTY_FUNCTION__> "void plugin_thdvar_safe_update(THD*, st_mysql_sys_var*, char**, const char*)") at assert.c:92
#7 0x00007f1b7fa98612 in __GI___assert_fail (assertion=0xedb75b "thd == _current_thd()", file=0xedad30 "/git/COMP-PS-5.6.33_dbg/sql/sql_plugin.cc", line=3114, function=0xedbf60 <plugin_thdvar_safe_update::__PRETTY_FUNCTION__> "void plugin_thdvar_safe_update(THD*, st_mysql_sys_var*, char**, const char*)") at assert.c:101
#8 0x00000000008026ea in plugin_thdvar_safe_update (thd=0x7f1b52e52000, var=0x7f1b31bf5860 <mysql_sysvar_local>, dest=0x7f1b7d83cec0, value=0x7f1b31bf61a0 <thd_local_init_buf> '\001' <repeats 407 times>) at /git/COMP-PS-5.6.33_dbg/sql/sql_plugin.cc:3114
#9 0x00007f1b319eea1f in get_thd_local (thd=0x7f1b52e52000) at /git/COMP-PS-5.6.33_dbg/plugin/audit_log/audit_log.c:1528
#10 0x00007f1b319eea95 in get_record_buffer (thd=0x7f1b52e52000, size=0) at /git/COMP-PS-5.6.33_dbg/plugin/audit_log/audit_log.c:1543
#11 0x00007f1b319ee145 in audit_log_notify (thd=0x7f1b52e52000, event_class=1, event=0x7fff0d69bbc0) at /git/COMP-PS-5.6.33_dbg/plugin/audit_log/audit_log.c:1015
#12 0x00000000007723e9 in plugins_dispatch (thd=0x7f1b52e52000, plugin=0x7f1b693fc580, arg=0x7fff0d69bb70) at /git/COMP-PS-5.6.33_dbg/sql/sql_audit.cc:455
#13 0x0000000000772487 in event_class_dispatch (thd=0x7f1b52e52000, event_class=1, event=0x7fff0d69bbc0) at /git/COMP-PS-5.6.33_dbg/sql/sql_audit.cc:491
#14 0x0000000000771bee in connection_class_handler(THD *, uint, typedef __va_list_tag __va_list_tag *) (thd=0x7f1b52e52000, event_subclass=1, ap=0x7fff0d69bc60) at /git/COMP-PS-5.6.33_dbg/sql/sql_audit.cc:114
#15 0x0000000000771ed3 in mysql_audit_notify (thd=0x7f1b52e52000, event_class=1, event_subtype=1) at /git/COMP-PS-5.6.33_dbg/sql/sql_audit.cc:217
#16 0x000000000062b165 in close_connection (thd=0x7f1b52e52000, sql_errno=1040) at /git/COMP-PS-5.6.33_dbg/sql/mysqld.cc:2897
#17 0x0000000000631891 in create_new_thread (thd=0x7f1b52e52000) at /git/COMP-PS-5.6.33_dbg/sql/mysqld.cc:6580
#18 0x00000000006322db in handle_connections_sockets () at /git/COMP-PS-5.6.33_dbg/sql/mysqld.cc:6899
#19 0x0000000000630e82 in mysqld_main (argc=41, argv=0x7f1b7d834448) at /git/COMP-PS-5.6.33_dbg/sql/mysqld.cc:6111
#20 0x0000000000625210 in main (argc=41, argv=0x7fff0d69c2b8) at /git/COMP-PS-5.6.33_dbg/sql/main.cc:25

Multithreaded run, 20 threads

[Roel Van de Paar (roel11)]

From Sergei; "Probably when MySQL notifies audit plugin about too many connections error it doesn't set `current_thd`... ok. It is clear to me how to reproduce."

[Roel Van de Paar (roel11)]

Sergei mentions it is debug assert and it should not affect users from what he sees in plugin_thdvar_safe_update.

[Sergei Glushchenko (sergei.glushchenko)]

Audit plugin is notified about "too many connections (error 1040)". Most likely current_thd is not set by server at this moment, but plugin_thdvar_safe_update contains debug assert "thd == current_thd" (thread-local variable should be updated by the owner thread).

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/1188
https://github.com/percona/percona-server/pull/1189

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1019