[#MDEV-23511] shutdown_server 10 times out, causing server kill at shutdown

Occasionally, during a test that is restarting the server, a SIGABRT will be sent to the server even though there is no hang. I think that I have seen this happen on buildbot, but I do not know how to efficiently search for this in the cross-reference. The most recent occurrence was in a different CI environment:

mariadb-10.3.24 with some changes
binlog_encryption.encryption_combo 'mix' w8 [ fail ] Found warnings/errors in server log file!
Test ended at 2020-08-18 13:32:30
line
Attempting backtrace. You can use the following information to find out
^ Found warnings in /var/tmp/mtr/8/log/mysqld.1.err

According to the server error log file, the signal is triggered during the second shutdown that the test is initiating (by executing the statement shutdown_server 10):

Version: '10.3.24-8-MariaDB-enterprise-log'  socket: '/var/tmp/mtr/tmp/8/mysqld.1.sock'  port: 16120  MariaDB Enterprise Server

2020-08-18 13:32:11 0 [Note] /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown

2020-08-18 13:32:11 0 [Note] Event Scheduler: Purging the queue. 0 events

2020-08-18 13:32:11 0 [Note] InnoDB: FTS optimize thread exiting.

2020-08-18 13:32:11 0 [Note] InnoDB: Starting shutdown...

2020-08-18 13:32:11 0 [Note] InnoDB: Dumping buffer pool(s) to /var/tmp/mtr/8/mysqld.1/data/ib_buffer_pool

2020-08-18 13:32:11 0 [Note] InnoDB: Instance 0, restricted to 127 pages due to innodb_buf_pool_dump_pct=25

2020-08-18 13:32:11 0 [Note] InnoDB: Buffer pool(s) dump completed at 200818 13:32:11

2020-08-18 13:32:21 0 [Note] InnoDB: Shutdown completed; log sequence number 1629902; transaction id 28

200818 13:32:21 [ERROR] mysqld got signal 6 ;

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.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help

diagnose the problem, but since we have already crashed,

something is definitely wrong and this may fail.

Server version: 10.3.24-8-MariaDB-enterprise-log

key_buffer_size=1048576

read_buffer_size=131072

max_used_connections=1

max_threads=153

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63225 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0

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 = 0x0 thread_stack 0x49000

2020-08-18 13:32:22 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

/home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld(my_print_stacktrace+0x2e)[0x55ec00bcaa7e]

mysys/stacktrace.c:271(my_print_stacktrace)[0x55ec00656775]

/lib/x86_64-linux-gnu/libpthread.so.0(+0x12890)[0x7fa061392890]

linux/futex-internal.h:88(futex_wait_cancelable)[0x7fa06138d9f3]

2020-08-18 13:32:22 0 [Note] /home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld: Shutdown complete

psi/mysql_thread.h:1177(inline_mysql_cond_wait)[0x55ec003bc6b1]

/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7)[0x7fa060889b97]

/home/jenkins/workspace/10.3e-DEV-NORMAL/BuildType/RelWithDebInfo/label/ubuntu-1804/bin/mysqld(_start+0x2a)[0x55ec003ae5fa]

The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains

information that should help you find out what is causing the crash.

Writing a core file...

In the above output, we can see that the InnoDB shutdown almost completed within those 10 seconds. The last messages are interleaved with the stack trace output.

In the core dump, only two threads exist: the signal handler, and the main thread. The SIGABRT is delivered to the signal_hand() thread that is executing a syscall inside the following:

while ((error=my_sigwait(&set,&sig)) == EINTR) ;

  mysql_mutex_lock(&LOCK_thread_count);

  while (!ready_to_exit)

    mysql_cond_wait(&COND_thread_count, &LOCK_thread_count);

  mysql_mutex_unlock(&LOCK_thread_count);

I think that the 10-second timeout is unreasonably short for some CI environments. Many tests are using a 30-second timeout (which is on the border of being questionably short for debug builds), and the default timeout value is 60 seconds.

Since this change in MariaDB 10.3.1, shutdown timeouts will result in prominent failures, due to a SIGABRT being sent before a final SIGKILL.

Please fix all tests to use a more reasonable timeout than 10 seconds, and also consider replacing the 30-second timeouts with 60-second ones.

[MDEV-23511] shutdown_server 10 times out, causing server kill at shutdown Created: 2020-08-19 Updated: 2020-10-06 Resolved: 2020-08-21
Status:	Closed
Project:	MariaDB Server
Component/s:	Replication, Tests
Affects Version/s:	10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s:	10.2.35, 10.3.26, 10.4.16, 10.5.7

[MDEV-23511] shutdown_server 10 times out, causing server kill at shutdown Created: 2020-08-19 Updated: 2020-10-06 Resolved: 2020-08-21