Bug #91310 Crash related to sql_print_information / acl_authenticate
Submitted: 19 Jun 2018 6:34 Modified: 21 Jun 2018 16:20
Reporter: Daniël van Eeden (OCA) Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Connection Handling Severity:S3 (Non-critical)
Version:5.7.22 OS:Any
Assigned to: CPU Architecture:Any

[19 Jun 2018 6:34] Daniël van Eeden
Description:
05:02:56 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=268435456
read_buffer_size=131072
max_used_connections=8001
max_threads=8000
thread_count=3566
connection_count=3565
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 9585144 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f0ce02476b0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f0da0acbd30 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xeed26b]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79f2c1]
/lib64/libpthread.so.0(+0xf5e0)[0x7f2689c7d5e0]
/lib64/libc.so.6(+0x86d51)[0x7f2687fedd51]
/lib64/libc.so.6(_IO_vfprintf+0x1338)[0x7f2687faf4b8]
/lib64/libc.so.6(+0x4c431)[0x7f2687fb3431]
/lib64/libc.so.6(_IO_vfprintf+0x1ee)[0x7f2687fae36e]
/lib64/libc.so.6(__fprintf_chk+0xf5)[0x7f2688074945]
/usr/sbin/mysqld[0xc04590]
/usr/sbin/mysqld(_Z21sql_print_informationPKcz+0xa5)[0xc08e95]
/usr/sbin/mysqld(_Z16acl_authenticateP3THD19enum_server_command+0xb25)[0x7a9fc5]
/usr/sbin/mysqld[0xc7ca1d]
/usr/sbin/mysqld(_Z22thd_prepare_connectionP3THD+0x68)[0xc7da68]
/usr/sbin/mysqld(handle_connection+0x263)[0xd80ab3]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x1263904]
/lib64/libpthread.so.0(+0x7e25)[0x7f2689c75e25]
/lib64/libc.so.6(clone+0x6d)[0x7f268805f34d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 43684706
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

From c++filt:
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xeed26b]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79f2c1]
/lib64/libpthread.so.0(+0xf5e0)[0x7f2689c7d5e0]
/lib64/libc.so.6(+0x86d51)[0x7f2687fedd51]
/lib64/libc.so.6(_IO_vfprintf+0x1338)[0x7f2687faf4b8]
/lib64/libc.so.6(+0x4c431)[0x7f2687fb3431]
/lib64/libc.so.6(_IO_vfprintf+0x1ee)[0x7f2687fae36e]
/lib64/libc.so.6(__fprintf_chk+0xf5)[0x7f2688074945]
/usr/sbin/mysqld[0xc04590]
/usr/sbin/mysqld(sql_print_information(char const*, ...)+0xa5)[0xc08e95]
/usr/sbin/mysqld(acl_authenticate(THD*, enum_server_command)+0xb25)[0x7a9fc5]
/usr/sbin/mysqld[0xc7ca1d]
/usr/sbin/mysqld(thd_prepare_connection(THD*)+0x68)[0xc7da68]
/usr/sbin/mysqld(handle_connection+0x263)[0xd80ab3]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x1263904]
/lib64/libpthread.so.0(+0x7e25)[0x7f2689c75e25]
/lib64/libc.so.6(clone+0x6d)[0x7f268805f34d]

How to repeat:
Unknown
[19 Jun 2018 7:40] Shane Bester
IS this a self-built binary?  Can you check stack like this;

addr2line  --demangle --inlines --pretty-print --addresses --basenames --functions --exe=/usr/sbin/mysqld 0xeed26b 0x79f2c1 0xc04590 0xc08e95 0x7a9fc5 0xc7ca1d 0xc7da68 0xd80ab3 0x1263904
[20 Jun 2018 6:33] Daniël van Eeden
$ addr2line  --demangle --inlines --pretty-print --addresses --basenames --functions --exe=/usr/sbin/mysqld 0xeed26b 0x79f2c1 0xc04590 0xc08e95 0x7a9fc5 0xc7ca1d 0xc7da68 0xd80ab3 0x1263904
0x0000000000eed26b: my_print_stacktrace at stacktrace.c:227
0x000000000079f2c1: handle_fatal_signal at signal_handler.cc:150 (discriminator 3)
0x0000000000c04590: error_log_print(loglevel, char const*, __va_list_tag*) [clone .part.131] at log.cc:2100
 (inlined by) error_log_print at log.cc:2118
0x0000000000c08e95: sql_print_information(char const*, ...) at log.cc:2171
0x00000000007a9fc5: acl_authenticate(THD*, enum_server_command) at sql_authentication.cc:2544
0x0000000000c7ca1d: check_connection(THD*) at sql_connect.cc:686
0x0000000000c7da68: thd_prepare_connection(THD*) at sql_connect.cc:741
 (inlined by) thd_prepare_connection(THD*) at sql_connect.cc:892
0x0000000000d80ab3: handle_connection at connection_handler_per_thread.cc:294
0x0000000001263904: pfs_spawn_thread at pfs.cc:2193

The binary is a re-build RPM with no code changes, but with OpenSSL instead of YaSSL
[21 Jun 2018 8:22] Shane Bester
Hm, line 2544 seems off.  We'll need to get the disassembly from your mysqld binary at and around address 0x00000000007a9fc5

gdb /usr/sbin/mysqld
disas 0x00000000007a9fc5
[21 Jun 2018 11:51] Daniël van Eeden
gdb disas output

Attachment: 91310_disas_0x00000000007a9fc5.txt (text/plain), 71.35 KiB.

[21 Jun 2018 11:53] Daniël van Eeden
0x00000000007a9fc0 <+2848>:	callq  0x7a6980 <login_failed_error(int, MPVIO_EXT*, MPVIO_EXT*)>
   0x00000000007a9fc5 <+2853>:	mov    %r13,%rdi
[21 Jun 2018 16:20] Shane Bester
So it was one of the two sql_print_information calls from this login_failed_error function that crashed...

But I am unable to guess why.  Say the mpvio->auth_info struct was broken/corrupted,  then the previous calls to my_error would have crashed first?!

A core file would be nice to have.

/**
  a helper function to report an access denied error in all the proper places
*/
static void login_failed_error(MPVIO_EXT *mpvio, int passwd_used)
{
  THD *thd= current_thd;
  if (passwd_used == 2)
  {
    my_error(ER_ACCESS_DENIED_NO_PASSWORD_ERROR, MYF(0),
             mpvio->auth_info.user_name,
             mpvio->auth_info.host_or_ip);
    query_logger.general_log_print(thd, COM_CONNECT,
                                   ER(ER_ACCESS_DENIED_NO_PASSWORD_ERROR),
                                   mpvio->auth_info.user_name,
                                   mpvio->auth_info.host_or_ip);
    /*
      Log access denied messages to the error log when log-warnings = 2
      so that the overhead of the general query log is not required to track
      failed connections.
    */
    sql_print_information(ER(ER_ACCESS_DENIED_NO_PASSWORD_ERROR),
                          mpvio->auth_info.user_name,
                          mpvio->auth_info.host_or_ip);
  }
  else
  {
    my_error(ER_ACCESS_DENIED_ERROR, MYF(0),
             mpvio->auth_info.user_name,
             mpvio->auth_info.host_or_ip,
             passwd_used ? ER(ER_YES) : ER(ER_NO));
    query_logger.general_log_print(thd, COM_CONNECT, ER(ER_ACCESS_DENIED_ERROR),
                                   mpvio->auth_info.user_name,
                                   mpvio->auth_info.host_or_ip,
                                   passwd_used ? ER(ER_YES) : ER(ER_NO));
    /*
      Log access denied messages to the error log when log-warnings = 2
      so that the overhead of the general query log is not required to track
      failed connections.
    */
    sql_print_information(ER(ER_ACCESS_DENIED_ERROR),
                          mpvio->auth_info.user_name,
                          mpvio->auth_info.host_or_ip,
                          passwd_used ? ER(ER_YES) : ER(ER_NO));
  }
}