MySQL Bugs: #64345: mysqld crashes on shutdown when slow log is a pipe

Bug #64345	mysqld crashes on shutdown when slow log is a pipe
Submitted:	15 Feb 2012 17:02	Modified:	5 Jun 2012 16:26
Reporter:	Jaroslav Nadenicek	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.5.20	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	5.1.62

Description:
When mysqld is set to log long queries to named pipe, it crashes with signal 11 during shutdown after an attempt to sync slow log file. If slow log file is a regular file, shutdown works as expected.

From error log:

2012-02-15_16:30:38.41990 120215 17:30:38 [Note] /usr/sbin/mysqld: Normal shutdown
2012-02-15_16:30:38.41994 
2012-02-15_16:30:38.42036 120215 17:30:38 [Note] Event Scheduler: Purging the queue. 0 events
2012-02-15_16:30:38.42043 120215 17:30:38 [ERROR] /usr/sbin/mysqld: Can't sync file '/var/log/mysql/slow_query.pipe' to disk (Errcode: 22)
2012-02-15_16:30:38.42046 16:30:38 UTC - mysqld got signal 11 ;
2012-02-15_16:30:38.42047 This could be because you hit a bug. It is also possible that this binary
... skip ...
2012-02-15_16:30:38.42050 
2012-02-15_16:30:38.42051 key_buffer_size=268435456
2012-02-15_16:30:38.42052 read_buffer_size=1048576
2012-02-15_16:30:38.42053 max_used_connections=2
2012-02-15_16:30:38.42054 max_threads=151
2012-02-15_16:30:38.42055 thread_count=0
2012-02-15_16:30:38.42056 connection_count=0
2012-02-15_16:30:38.42057 It is possible that mysqld could use up to 
2012-02-15_16:30:38.42058 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 727734 K  bytes of memory
2012-02-15_16:30:38.42059 Hope that's ok; if not, decrease some variables in the equation.
2012-02-15_16:30:38.42059 
2012-02-15_16:30:38.42060 Thread pointer: 0x0
2012-02-15_16:30:38.42061 Attempting backtrace. You can use the following information to find out
2012-02-15_16:30:38.42062 where mysqld died. If you see no messages after this, something went
2012-02-15_16:30:38.42064 terribly wrong...
2012-02-15_16:30:38.42071 stack_bottom = 0 thread_stack 0x30000
2012-02-15_16:30:38.42097 /usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x7f1f3372193e]
2012-02-15_16:30:38.42118 /usr/sbin/mysqld(handle_fatal_signal+0x493)[0x7f1f335da373]
2012-02-15_16:30:38.42121 /lib/libpthread.so.0(+0xeff0)[0x7f1f32da0ff0]
2012-02-15_16:30:38.42144 /usr/sbin/mysqld(_ZN9MYSQL_LOG5closeEj+0x1f6)[0x7f1f33678856]
2012-02-15_16:30:38.42161 /usr/sbin/mysqld(+0x285079)[0x7f1f33453079]
2012-02-15_16:30:38.42177 /usr/sbin/mysqld(_Z10unireg_endv+0xe)[0x7f1f3345344e]
2012-02-15_16:30:38.42193 /usr/sbin/mysqld(+0x287380)[0x7f1f33455380]
2012-02-15_16:30:38.42210 /usr/sbin/mysqld(kill_server_thread+0xe)[0x7f1f33455a9e]
2012-02-15_16:30:38.42212 /lib/libpthread.so.0(+0x68ca)[0x7f1f32d988ca]
2012-02-15_16:30:38.42222 /lib/libc.so.6(clone+0x6d)[0x7f1f310f986d]
2012-02-15_16:30:38.42223 The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
2012-02-15_16:30:38.42224 information that should help you find out what is causing the crash.

How to repeat:
1. turn on slow query logging and set the filename to named pipe, i.e.
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow_query.pipe

2. run mysqld

/usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306

3. kill -TERM pid
-or-
mysqladmin shutdown

Suggested fix:
mysqld should not attempt to sync files which cannot by synced, or handle failure gracefully

Thank you for the report.

Verified, although mysqld hangs at startup when I try to use pipe, then crashes after I try to read this pipe.

Crash information in 5.5:

./bin/mysqld: Can't seek in file '/tmp/testpipe' (Errcode: 29)
mysqld: /home/sveta/src/mysql-5.5/mysys/mf_iocache.c:180: init_io_cache: Assertion `seek_offset == 0' failed.
12:55:32 UTC - mysqld got signal 6 ;
...
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 = 0 thread_stack 0x20000
./bin/mysqld(my_print_stacktrace+0x35)[0x8ceba1]
./bin/mysqld(handle_fatal_signal+0x408)[0x75931c]
/lib64/libpthread.so.0[0x31d780f520]
/lib64/libc.so.6(gsignal+0x35)[0x31d7432a45]
/lib64/libc.so.6(abort+0x175)[0x31d7434225]
/lib64/libc.so.6(__assert_fail+0xf5)[0x31d742b9d5]
./bin/mysqld(init_io_cache+0x18f)[0x8aff14]
./bin/mysqld(_ZN9MYSQL_LOG4openEjPKc13enum_log_typeS1_10cache_type+0x22c)[0x801cb0]
./bin/mysqld(_ZN15MYSQL_QUERY_LOG13open_slow_logEPKc+0x77)[0x6f3d17]
./bin/mysqld(_ZN25Log_to_file_event_handler4initEv+0x4c)[0x7fed9e]
./bin/mysqld(_ZN6LOGGER15init_log_tablesEv+0x8c)[0x7ff182]
./bin/mysqld[0x55a928]
./bin/mysqld(_Z11mysqld_mainiPPc+0x503)[0x55b582]
./bin/mysqld(main+0x20)[0x5543c4]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x31d741ec9d]
./bin/mysqld[0x5542e9]
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.

Yes, I know that mysqld hangs on startup when slow log is a pipe and no one is reading from it - since man 7 fifo says "Normally, opening the FIFO blocks until the other end is opened also.", I didn't consider it as a bug.

Moreover in my case mysqld starts correctly when I open the pipe for reading (see times in log below) and I'm trying to open the pipe for reading first anyway, so startup behaviour isn't a problem for me.

120216 17:51:16 [Note] Plugin 'FEDERATED' is disabled.
120216 17:51:16 InnoDB: The InnoDB memory heap is disabled
120216 17:51:16 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120216 17:51:16 InnoDB: Compressed tables use zlib 1.2.3.4
120216 17:51:16 InnoDB: Using Linux native AIO
120216 17:51:16 InnoDB: Initializing buffer pool, size = 512.0M
120216 17:51:16 InnoDB: Completed initialization of buffer pool
120216 17:51:16 InnoDB: highest supported file format is Barracuda.
120216 17:51:16  InnoDB: Waiting for the background threads to start
120216 17:51:17 InnoDB: 1.1.8 started; log sequence number 1595675
/usr/sbin/mysqld: Can't seek in file '/var/log/mysql/slow_query.pipe' (Errcode: 29)
120216 17:51:59 [Note] Event Scheduler: Loaded 0 events
120216 17:51:59 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.20-1~dotdeb.0-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)

Noted in 5.6.6 changelog.

The server crashed at shutdown if the slow query log file was a named pipe.