MySQL Bugs: #43490: Falcon internal thread terminate after throwing an instance of 'SQLError'

Bug #43490	Falcon internal thread terminate after throwing an instance of 'SQLError'
Submitted:	9 Mar 8:57	Modified:	8 Sep 13:35
Reporter:	Olav Sandstaa
Status:	Verified
Category:	Server: Falcon	Severity:	S2 (Serious)
Version:	6.0.11-alpha	OS:	Any
Assigned to:	Olav Sandstaa	Target Version:	6.0-beta
Tags:	F_ERROR HANDLING
Triage:	Triaged: D1 (Critical)

Description:
In a run of falcon_ddl Falcon crash with the following error written to the error file:

terminate called after throwing an instance of 'SQLError'
090307  6:27:07 - mysqld got signal 6 ;

The call stack from the terminating thread looks like this:

Core was generated by
`/export/home/pb2/test/sb_1-376233-1236395779.66/mysql-6.0.11-alpha-linux-i686-t'.
Program terminated with signal 6, Aborted.
#0  0x0017e402 in __kernel_vsyscall ()
#0  0x0017e402 in __kernel_vsyscall ()
#1  0x0089f067 in pthread_kill () from /lib/libpthread.so.0
#2  0x0882bea2 in my_write_core (sig=6) at stacktrace.c:309
#3  0x082be912 in handle_segfault (sig=6) at mysqld.cc:2690
#4  <signal handler called>
#5  0x0017e402 in __kernel_vsyscall ()
#6  0x00749d10 in raise () from /lib/libc.so.6
#7  0x0074b621 in abort () from /lib/libc.so.6
#8  0x00a99c60 in __gnu_cxx::__verbose_terminate_handler ()
   from /usr/lib/libstdc++.so.6
#9  0x00a976c5 in std::set_unexpected () from /usr/lib/libstdc++.so.6
#10 0x00a97702 in std::terminate () from /usr/lib/libstdc++.so.6
#11 0x00a977bb in __cxa_rethrow () from /usr/lib/libstdc++.so.6
#12 0x0858281a in Thread::thread (this=0xb6f1cdd0) at Thread.cpp:201
#13 0x085828dd in Thread::thread (parameter=0xb6f1cdd0) at Thread.cpp:145
#14 0x0089a45b in start_thread () from /lib/libpthread.so.0
#15 0x007f1c4e in clone () from /lib/libc.so.6

How to repeat:
I have only seen this once when running falcon_ddl

Suggested fix:
Falcon internal thread should do a better job on handling exceptions.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/77044

2742 Olav.Sandstaa@sun.com	2009-06-24
      Bug #43490 Falcon internal thread terminate after throwing an instance of
'SQLError'
      
      When this error occurs MySQL terminates and all that is written to the log
      file is that there was on uncaught SQLError exception. 
      The Thread class has code for writing out the exception string but unless
      the correct debug flag is specified nothing is written to the log file.
      
      This patch changes the Thread class to use Log::fatal() for writing the
      excpetion's string so that it is more likely that it get written to the log
      before the process is terminated. The patch does not fix the problem but
      will hopefully make it easier to understand what caused this exception
      to occure.

Olav, the patch looks safe to push. I hope it helps in order to figure out what is going
on in these cases.

Patch that improves the error reporting is pushed. Setting status back to "In progress".

With the latest patch in place we now get the following written to the log when this crash
happens when running falcon_ddl:

  Thread::thread: thread 1095825728: can't continue after fatal error
  terminate called after throwing an instance of 'SQLError'

This does not say much about what the actual error causing this was. Still, it gives us
that this is related to a disk IO problem. This exception is only thrown from IO.cpp
during either writing or reading a block to/from the data device.

Seems like there is more room for improvements in how we log information about this in
the error log.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/77310

2748 Olav.Sandstaa@sun.com	2009-06-26
      Bug#43490 Falcon internal thread terminate after throwing an instance of 'SQLError'
      
      The thrown exception contains the error string "can't continue after
      fatal error ". This exception is only thrown by the Falcon IO
      system. It is thrown after a fatal IO error has
      occurred. Unfortunately it gives very little information about what
      the actual error was.
      
      This patch improves the logging of "fatal" IO errors by writing to the
      error log file information about the error when it occurs. With this
      patch a message similar to this example will be written when
      IO::declareFatalError() is called:
      
      Falcon: Fatal IO error occurred in "IO::writePages": file
     
"/home/olav/mysql/develop/falcon-elog/mysql-test/var/mysqld.1/data/falcon_user.fts", page
21: No space left on device (28)
      
      Note that this patch does not fix the problem but only improves the logging
      when the actually error occurs, hopefully making it easier to find the
      real error.

Patch for adding logging to error log for fatal IO errors is pushed to
mysql-6.0-falcon-team. Setting status back to "In progress".

Here is the new output from a new similar crash that includes the extra logging introduced
by the previous patches:

# 19:53:00 Falcon: Fatal IO error occurred in "IO::writePages": file
"/export/home/pb2/test/sb_1-710226-1251307967.68/mysql-6.0.12-alpha-linux-i686-test/vardirs/master-data_recovery/falcon_temporary.fts",
page 1: Input/output error (5)
# 19:53:00 Exception: write error on page 1 (4096/4096/7) of
"/export/home/pb2/test/sb_1-710226-1251307967.68/mysql-6.0.12-alpha-linux-i686-test/vardirs/master-data_recovery/falcon_temporary.fts":
Input/output error (5)
# 19:53:00 Thread::thread: thread -1208513648: write error on page 1 (4096/4096/7) of
"/export/home/pb2/test/sb_1-710226-1251307967.68/mysql-6.0.12-alpha-linux-i686-test/vardirs/master-data_recovery/falcon_temporary.fts":
Input/output error (5)
# 19:53:00 terminate called after throwing an instance of 'SQLError'
# 19:53:00 090826 19:53:00 - mysqld got signal 6 ;