MySQL Bugs: #34417: Assertion failure in Diagnostics_area::set_error

Bug #34417	Assertion failure in Diagnostics_area::set_error_status()
Submitted:	8 Feb 2008 14:20	Modified:	22 May 2008 15:50
Reporter:	Guilhem Bichot	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.1-bk	OS:	Any
Assigned to:	Kristofer Pettersson	CPU Architecture:	Any

Description:
Observed on Linux and Windows, 32-bit.
Running a mysqld with datadir in /dev/shm (limited to 1GB), at some point the log (general log or slow log) cannot be written because /dev/shm is full, and then we see an assertion failure at sql_class.cc:456 with a backtrace like this:
<guilhem> #7  0x081e3ee5 in Diagnostics_area::set_error_status (this=0x8e44ef0, 
<guilhem>     thd=0x8e44248, sql_errno_arg=3, 
<guilhem>     message_arg=0xb2c45748 "Error writing file '/home/mysql_src/mysql-5.1/mysql-test/var/log/master-slow.log' (Errcode: 28)") at sql_class.cc:456
<guilhem> #8  0x081f8e46 in my_message_sql (error=3, 
<guilhem>     str=0xb2c45748 "Error writing file '/home/mysql_src/mysql-5.1/mysql-test/var/log/master-slow.log' (Errcode: 28)", MyFlags=36) at mysqld.cc:2618
<guilhem> #9  0x0849f4ae in my_error (nr=3, MyFlags=36) at my_error.c:102
<guilhem> #10 0x08493943 in my_write (Filedes=15, 
<guilhem>     Buffer=0x8d7d3a6 "lhost [127.0.0.1]\n# Query_time: 29.237976  Lock_time: 0.000321 Rows_sent: 10  Rows_examined: 10\nSET timestamp=1202466643;\nselect `c2`,`c3` from `qa06` limit 10;\nm `qa07` limit 10;\n (4291438729.52059,4"..., 
<guilhem>     Count=161, MyFlags=<value optimized out>) at my_write.c:87
<guilhem> #11 0x0849a20e in my_b_flush_io_cache (info=0x8756f40, 
<guilhem>     need_append_buffer_lock=0) at mf_iocache.c:1751
<guilhem> #12 0x0829dba0 in MYSQL_QUERY_LOG::write (this=0x8756c24, thd=0x8e44248, 
<guilhem>     current_time=1202466643, query_start_arg=1202466614, 
<guilhem>     user_host=0xb2c45b18 "root[root] @ localhost [127.0.0.1]", 
<guilhem>     user_host_len=34, query_utime=29237976, lock_utime=321, is_command=false, 
<guilhem>     sql_text=0xb251f7d8 "select `c2`,`c3` from `qa06` limit 10", 
<guilhem>     sql_text_len=37) at log.cc:2200
<guilhem> #13 0x0829dcb5 in Log_to_file_event_handler::log_slow (this=0x8756830, 
<guilhem>     thd=0x8e44248, current_time=1202466643, query_start_arg=1202466614, 
<guilhem>     user_host=0xb2c45b18 "root[root] @ localhost [127.0.0.1]", 
<guilhem>     user_host_len=34, query_utime=0, lock_utime=0, 
<guilhem>     is_command=<value optimized out>, 
<guilhem>     sql_text=0xb251f7d8 "select `c2`,`c3` from `qa06` limit 10", 
<guilhem>     sql_text_len=37) at log.cc:721
<guilhem> #14 0x0829eaa8 in LOGGER::slow_log_print (this=0x8749d60, thd=0x8e44248, 
<guilhem>     query=0xb251f7d8 "select `c2`,`c3` from `qa06` limit 10", query_length=37, 
<guilhem>     current_utime=1202466643653581) at log.cc:959
<guilhem> #15 0x0829eb15 in slow_log_print (thd=0x8e44248, 
<guilhem>     query=0xb251f7d8 "select `c2`,`c3` from `qa06` limit 10", query_length=37, 
<guilhem>     current_utime=1202466288828416) at log.cc:3783
<guilhem> #16 0x08204c43 in log_slow_statement (thd=0x8e44248) at sql_parse.cc:1545
<guilhem> #17 0x082123de in dispatch_command (command=COM_QUERY, thd=0x8e44248, 
<guilhem>     packet=0xa601c009 "", packet_length=37) at sql_parse.cc:1498
<guilhem> #18 0x08212890 in do_command (thd=0x8e44248) at sql_parse.cc:781
<guilhem> #19 0x08201a8b in handle_one_connection (arg=0x8e44248) at sql_connect.cc:1120

How to repeat:
Start mysqld using mtr: "./mtr --start-and-exit --mem --gdb binlog_killed"
Send many statements to mysqld until /dev/shm is full and the assertion fails.

I got same problem on Linux64 bits with a not full disk.
This happened when running the test system with the test rpl.rpl_err_ignoredtable in row based mode

I wonder if we should raise the priority a bit. I got it today again.

Happened under Windows and disk was not full at all. So removing "if log hits disk full" from title.

I'm getting this error in the Maria tree.
There is a changeset in 5.1 (not yet merged into Maria tree) which probably helps:
ChangeSet 1.2512.21.1 2008/02/08 15:53:57 kostja@dipika.(none)
  Silence the slow log errors (they won't make it to the client anyway).
BUT I got the same assertion with a general log write _to_file_:
#7  0x081e3ee5 in Diagnostics_area::set_error_status (this=0x8f07ab0, 
thd=0x8f06e08, sql_errno_arg=3, 
message_arg=0xb2036678 "Error writing file '/home/mysql_src/mysql-5.1/mysql-test/var/log/master.log' (Errcode: 28)") at sql_class.cc:456
#8  0x081f8e46 in my_message_sql (error=3, 
str=0xb2036678 "Error writing file '/home/mysql_src/mysql-5.1/mysql-test/var/log/master.log' (Errcode: 28)", MyFlags=36) at mysqld.cc:2618
#9  0x0849f4fe in my_error (nr=3, MyFlags=36) at my_error.c:102
#10 0x08493993 in my_write (Filedes=17, 
Buffer=0x8d7f3b0 "\t\t   16 Execute\tselect `c3`,`c4` from `qa07` limit 10\nvalues ('\002\177<\016¬Ú\025¹& [½vThÝIç~«£\213\0312øé\227¿Ú\aNÖL\022·ÍPw3ìñT?¢0÷\201#®!\222Ü\f]y6¾às\b(','²B¥\224j\204ûnÀ\016~<ÛÍOÏÅy\237æ\1771X\221Z+§\v°yv¢\226k¢ÐDey\016/\223sC5g.¤\a\001\205Ííg^¬©¾úâ\221õ<\213³D\016\235\227^"..., 
Count=54, MyFlags=<value optimized out>) at my_write.c:87
#11 0x0849a25e in my_b_flush_io_cache (info=0x8756b50, 
need_append_buffer_lock=0) at mf_iocache.c:1751
#12 0x0829d37c in MYSQL_QUERY_LOG::write (this=0x8756834, 
event_time=1202476167, 
user_host=0xb203695c "root[root] @ localhost [127.0.0.1]", 
user_host_len=34, thread_id=16, command_type=0x856a99c "Execute", 
command_type_len=7, 
sql_text=0x8f02858 "select `c3`,`c4` from `qa07` limit 10", 
sql_text_len=37) at log.cc:2048
#13 0x0829d446 in Log_to_file_event_handler::log_general (this=0x8756830, 
thd=0x8f06e08, event_time=1202476167, 
user_host=0xb203695c "root[root] @ localhost [127.0.0.1]", 
user_host_len=34, thread_id=16, command_type=0x856a99c "Execute", 
command_type_len=7, 
sql_text=0x8f02858 "select `c3`,`c4` from `qa07` limit 10", 
sql_text_len=37, client_cs=0x873da40) at log.cc:743
#14 0x0829e7eb in LOGGER::general_log_write (this=0x8749d60, thd=0x8f06e08, 
command=COM_STMT_EXECUTE, 
query=0x8f02858 "select `c3`,`c4` from `qa07` limit 10", query_length=37)
at log.cc:1007
And Konstantin's conclusion was at that time (Feb 08):
<quote>
MYSQL_QUERY_LOG::write method for some reason calls my_write with MY_WME flag.
Well, apparently the error is coming from IO_CACHE operations.
Log writing should be a silent module I believe.
so Silence_log_* handler should be installed there as well.
in a similar fashion it is not installed for Log_to_tables
</quote>
Log-to-file functions need to have the same handler as log-to-tables functions it seems, because log-to-file functions can fail (disk full) as log-to-tables functions can fail (corrupted CSV table because previous run ended in a crash).

Progress report:
I've tried reproducing the bug using gypsy approach and by breaking in MYSQL_QUERY_LOG and filling the ram-disk.

In 6.0 MYSQL_QUERY_LOG::write is using my_b_write, and I'm having difficulty to reproduce the assertion crash:  

080416 17:26:34 [ERROR] Failed to write to mysql.slow_log: Error writing file './mysql/slow_log.CSV' (Errcode: 28)
080416 17:26:34 [ERROR] /home/thek/Development/cpp/bug34417/my60-bug34417/sql/mysqld: Disk is full writing './test/qa06.MYD' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
080416 17:26:34 [ERROR] /home/thek/Development/cpp/bug34417/my60-bug34417/sql/mysqld: Disk is full writing './test/qa07.MYD' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs

Progress report: Verified for 5.1 though:

080416 18:10:29 [ERROR] Failed to write to mysql.general_log: Error writing file './mysql/general_log.CSV' (Errcode: 28)

#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7dab875 in raise () from /lib/tls/i686/cmov/libc.so.6
#2  0xb7dad201 in abort () from /lib/tls/i686/cmov/libc.so.6
#3  0xb7da4b6e in __assert_fail () from /lib/tls/i686/cmov/libc.so.6
#4  0x081ecde7 in Diagnostics_area::set_ok_status (this=0x86fcf2c, 
    thd=0x86fc198, affected_rows_arg=1, last_insert_id_arg=1, message_arg=0x0)
    at sql_class.cc:397
#5  0x0813ab19 in my_ok (thd=0x86fc198, affected_rows=1, id=1, message=0x0)
    at sql_class.h:2146
#6  0x082a8b27 in mysql_insert (thd=0x86fc198, table_list=0x87ef4c0, 
    fields=@0x86fd78c, values_list=@0x86fd7b0, update_fields=@0x86fd7a4, 
    update_values=@0x86fd798, duplic=DUP_ERROR, ignore=false)
    at sql_insert.cc:949
#7  0x0821856f in mysql_execute_command (thd=0x86fc198) at sql_parse.cc:2934
#8  0x0821ed9e in mysql_parse (thd=0x86fc198, 
    inBuf=0x87ef0d0 "insert into `qa05`(`c1`,`c2`) values ('Cçµ£Á·l$Á·Ù£%ç µÑà«
¸Ë\217Î¤=à\232\212Lî\212\236ì¯©Ì§Ò£Á\202Õ\214@eî\222±\004ì\235°Ì\216ë¢«ç\213ª\tÏ
\214ì°²æ\207\221Å âª\215á³¬Zë\232®è£¤É\227å\211¸ê\225\236B\037Ê\216é\204½&á\230§
é\203Q\tÌ\233á\222\221Á\215i\\\\â®\233Ø\231Ü\211Ò \026\006ã\203¯\\rê´¸Ú\217Ù\22
0æ¯\224\017å¢µË±nÛ\234ç\215 á¾ªV"..., length=436, found_semicolon=0xb6a2f064)
    at sql_parse.cc:5631
#9  0x0821face in dispatch_command (command=COM_QUERY, thd=0x86fc198, 
    packet=0x87b1579 "insert into `qa05`(`c1`,`c2`) values ('Cçµ£Á·l$Á·Ù£%ç µÑà
---Type <return> to continue, or q <return> to quit--- 
«¸Ë\217Î¤=à\232\212Lî\212\236ì¯©Ì§Ò£Á\202Õ\214@eî\222±\004ì\235°Ì\216ë¢«ç\213ª\tÏ\214ì°²æ\207\221Å âª\215á³¬Zë\232®è£¤É\227å\211¸ê\225\236B\037Ê\216é\204½&á\230§é\203Q\tÌ\233á\222\221Á\215i\\\\â®\233Ø\231Ü\211Ò \026\006ã\203¯\\rê´¸Ú\217Ù\220æ¯\224\017å¢µË±nÛ\234ç\215 á¾ªV"..., packet_length=436) at sql_parse.cc:1121
#10 0x08220ec6 in do_command (thd=0x86fc198) at sql_parse.cc:781

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/45507

ChangeSet@1.2590, 2008-04-16 18:25:37+02:00, thek@adventure.(none) +1 -0
  Bug#34417 Assertion failure in Diagnostics_area::set_error_status()
  
  The Diagnostic_area caused an assertion failure in debug mode when
  the disk was full.
  
  By setting the internal error handler to ignore errors caused by
  underlying logging methods, the error is avoided.

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/45764

ChangeSet@1.2590, 2008-04-21 15:58:21+02:00, thek@adventure.(none) +1 -0
  Bug#34417 Assertion failure in Diagnostics_area::set_error_status()
  
  The Diagnostic_area caused an assertion failure in debug mode when
  the disk was full.
  
  By setting the internal error handler to ignore errors caused by
  underlying logging methods, the error is avoided.

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/45811

ChangeSet@1.2563, 2008-04-22 12:45:39+02:00, thek@adventure.(none) +1 -0
  Bug#34417 Assertion failure in Diagnostics_area::set_error_status()
    
  The Diagnostic_area caused an assertion failure in debug mode when
  the disk was full.
    
  By setting the internal error handler to ignore errors caused by
  underlying logging methods, the error is avoided.

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/45818

ChangeSet@1.2590, 2008-04-22 14:01:32+02:00, thek@adventure.(none) +1 -0
  Bug#34417 Assertion failure in Diagnostics_area::set_error_status()
  
  The Diagnostic_area caused an assertion failure in debug mode when
  the disk was full.
  
  By setting the internal error handler to ignore errors caused by
  underlying logging methods, the error is avoided.

Patch approved by Kostja

Queued to 5.1-runtime

Pushed into 6.0.6-alpha

No changelog entry needed.

Pushed into 5.1.27  (revid:joerg@mysql.com-20080626161101-h5hsaluwtf05xdr2) (version source revid:joerg@mysql.com-20080626161101-h5hsaluwtf05xdr2) (pib:3)