MySQL Bugs: #42640: mysqld crashes when unsafe statements are executed (STRICT_TRANS

Bug #42640	mysqld crashes when unsafe statements are executed (STRICT_TRANS_TABLES mode)
Submitted:	6 Feb 2009 7:17	Modified:	15 May 2009 1:37
Reporter:	Guangbao Ni	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S2 (Serious)
Version:	5.1-bugteam, 5.1	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	INSERT..SELECT..LIMIT, regression, STRICT_TRANS_TABLES MODE

Description:
MySQL server crashes when executing INSERT .. SELECT .. LIMIT clause under STRICT_TRANS_TABLES sql mode.

There are the following error information n the mysqld.err:
CURRENT_TEST: rpl.rpl_alter
090206 17:54:00 [Warning] The syntax '--log' is deprecated and will be removed in MySQL 7.0. Please use '--general_log'/'--general_log_file' instead.
090206 17:54:00 [Warning] The syntax '--log_slow_queries' is deprecated and will be removed in MySQL 7.0. Please use '--slow_query_log'/'--slow_query_log_file' instead.
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
090206 17:54:00  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
090206 17:54:01  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
090206 17:54:01  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
090206 17:54:01  InnoDB: Started; log sequence number 0 0
090206 17:54:01 [Note] Event Scheduler: Loaded 0 events
090206 17:54:01 [Note] /home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld: ready for connections.
Version: '5.1.32-debug-log'  socket: '/home/ngb/mysql/bzr/bugteam-5.1/mysql-test/var/tmp/mysqld.1.sock'  port: 12500  Source distribution
090206 17:54:49 [Warning] Statement is not safe to log in statement format. Statement: insert into t1 select * from t2 limit 1
mysqld: sql_class.cc:436: void Diagnostics_area::set_ok_status(THD*, ha_rows, ulonglong, const char*): Assertion `! is_set()' failed.
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(my_print_stacktrace+0x27)[0x8652d82]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(handle_segfault+0x226)[0x827e2ae]
/lib/tls/i686/libpthread.so.0[0x57a998]
/lib/tls/i686/libc.so.6(abort+0x118)[0x36d0b8]
/lib/tls/i686/libc.so.6(__assert_fail+0xdc)[0x365a5c]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_ZN16Diagnostics_area13set_ok_statusEP3THDyyPKc+0x31)[0x82663f3]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z5my_okP3THDyyPKc+0x29)[0x81b5059]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_ZN13select_insert8send_eofEv+0x4d9)[0x8317d1d]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld[0x82f9549]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_ZN4JOIN4execEv+0x566)[0x82ec8c4]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x2a6)[0x82ee6a8]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z13handle_selectP3THDP6st_lexP13select_resultm+0x166)[0x82e85be]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z21mysql_execute_commandP3THD+0x276f)[0x828f47b]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x1bf)[0x8295ab7]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x8b8)[0x828b6bc]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(_Z10do_commandP3THD+0x228)[0x828abb6]
/home/ngb/mysql/bzr/bugteam-5.1/sql/mysqld(handle_one_connection+0x154)[0x8289324]
/lib/tls/i686/libpthread.so.0[0x5750dd]
/lib/tls/i686/libc.so.6(__clone+0x5e)[0x3fba2e]
090206 17:54:49 - 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.
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.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=151
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 59974 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0xaca0be8
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 = 0xb2b83460 thread_stack 0x30000
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0xacf6220 = insert into t1 select * from t2 limit 1
thd->thread_id=1
thd->killed=KILL_BAD_DATA
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.
Writing a core file

(gdb) bt
#0  0x00578150 in pthread_kill () from /lib/tls/i686/libpthread.so.0
#1  0x08652e06 in my_write_core (sig=6) at stacktrace.c:310
#2  0x0827e46f in handle_segfault (sig=6) at mysqld.cc:2505
#3  <signal handler called>
#4  0x0036bc38 in raise () from /lib/tls/i686/libc.so.6
#5  0x0036d0b8 in abort () from /lib/tls/i686/libc.so.6
#6  0x00365a5c in __assert_fail () from /lib/tls/i686/libc.so.6
#7  0x082663f3 in Diagnostics_area::set_ok_status (this=0xa85099c, thd=0xa84fbf0,
    affected_rows_arg=0, last_insert_id_arg=0,
    message_arg=0xb2ad33b0 "Records: 0  Duplicates: 0  Warnings: 0") at sql_class.cc:436
#8  0x081b5059 in my_ok (thd=0xa84fbf0, affected_rows=0, id=0,
    message=0xb2ad33b0 "Records: 0  Duplicates: 0  Warnings: 0") at sql_class.h:2253
#9  0x08317d1d in select_insert::send_eof (this=0xa8a57d0) at sql_insert.cc:3215
#10 0x08301404 in do_select (join=0xa8a5848, fields=0xa85101c, table=0x0, procedure=0x0)
    at sql_select.cc:10865
#11 0x082ee0e2 in JOIN::exec (this=0xa8a5848) at sql_select.cc:2199
#12 0x082ee6a8 in mysql_select (thd=0xa84fbf0, rref_pointer_array=0xa851080, tables=0xa8a5580,
    wild_num=1, fields=@0xa85101c, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0,
    proc_param=0x0, select_options=3489679872, result=0xa8a57d0, unit=0xa850d18, select_lex=0xa850f88)
    at sql_select.cc:2378
#13 0x082e85be in handle_select (thd=0xa84fbf0, lex=0xa850cbc, result=0xa8a57d0,
    setup_tables_done_option=1073741824) at sql_select.cc:256
#14 0x0828f47b in mysql_execute_command (thd=0xa84fbf0) at sql_parse.cc:3142
#15 0x08295ab7 in mysql_parse (thd=0xa84fbf0, inBuf=0xa8a5228 "insert r1 select * from r2 limit 1",
    length=34, found_semicolon=0xb2ad4268) at sql_parse.cc:5810
---Type <return> to continue, or q <return> to quit---
#16 0x0828b6bc in dispatch_command (command=COM_QUERY, thd=0xa84fbf0,
    packet=0xa896331 "insert r1 select * from r2 limit 1", packet_length=34) at sql_parse.cc:1216
#17 0x0828abb6 in do_command (thd=0xa84fbf0) at sql_parse.cc:857
#18 0x08289324 in handle_one_connection (arg=0xa84fbf0) at sql_connect.cc:1115
#19 0x005750dd in start_thread () from /lib/tls/i686/libpthread.so.0
#20 0x003fba2e in clone () from /lib/tls/i686/libc.so.6

How to repeat:
[gni@dev3-221 bugteam-5.1]$ ./client/mysql -u root -S mysql-test/var/tmp/mysqld.1.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.32-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> use test;
Database changed
mysql> set @@SQL_MODE=STRICT_TRANS_TABLES;
Query OK, 0 rows affected (0.00 sec)

mysql> create table t1 (i int primary key);
Query OK, 0 rows affected (0.01 sec)

mysql> create table t2 (i int primary key);
Query OK, 0 rows affected (0.01 sec)

mysql> insert into t1 select * from t2 limit 1;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>

Suggested fix:
Run normally, don't crash.

Thank you for the report.

I can not repeat described behavior with 5.1-bugteam sources checked out today. Please indicate how you compile mysqld, provide configuration options you use and indicate operating system.

No additional information needed: bug is repeatable if have binlog turned on.

Test case for our test suite:

--source include/have_log_bin.inc
set @@SQL_MODE=STRICT_TRANS_TABLES;

create table t1 (i int primary key);

create table t2 (i int primary key);

insert into t1 select * from t2 limit 1;

Probably related to bug #42634, but backtrace is different.

Bug was introduced after 5.1.31: with 5.1.31 INSERT just fails with "Statement is not safe to log in statement format."

Discussed with Jasonh, here the warning shouldn't be elevated error.

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

2846 Guangbao Ni	2009-03-12
      BUG#42640 mysqld crashes when unsafe statements are executed (STRICT_TRANS_TABLES mode)
      
      Mysql server crashes because unsafe statements warning is wrongly elevated to error,
      which is set the error status of Diagnostics_area of the thread in THD::binlog_query().
      Yet the caller believes that binary logging shouldn't touch the status, so it will 
      set the status also later by my_ok(), my_error() or my_message() seperately 
      according to the execution result of the statement or transaction.
      But the status of Diagnostics_area of the thread is allowed to set only once.
      
      Fixed to clear the error wrongly set by binary logging, but keep the warning message.

Review sent by email.

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

2835 Guangbao Ni	2009-04-02
      Bug #42640  mysqld crashes when unsafe statements are executed (STRICT_TRANS_TABLES mode)
      
      Mysql server crashes because unsafe statements warning is wrongly elevated to error,
      which is set the error status of Diagnostics_area of the thread in THD::binlog_query().
      
      Yet the caller believes that binary logging shouldn't touch the status, so it will 
      set the status also later by my_ok(), my_error() or my_message() seperately 
      according to the execution result of the statement or transaction.
      But the status of Diagnostics_area of the thread is allowed to set only once.
      
      
      Fixed by setting ER_BINLOG_UNSAFE_STATEMENT warning to NOTE level
      modified:
        mysql-test/suite/binlog/r/binlog_stm_ps.result
        mysql-test/suite/binlog/r/binlog_unsafe.result
        mysql-test/suite/binlog/t/binlog_unsafe.test
        sql/sql_class.cc

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

2836 Guangbao Ni	2009-04-03
      for BUG#42640, change unsafe warning to NOTE level
      modified:
        mysql-test/suite/rpl/r/rpl_skip_error.result
        mysql-test/suite/rpl/r/rpl_stm_loadfile.result
        mysql-test/suite/rpl/r/rpl_udf.result

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

2853 Guangbao Ni	2009-04-03
      BUG#42640 mysqld crashes when unsafe statements are executed (STRICT_TRANS_TABLESmode)
      
      Mysql server crashes because unsafe statements warning is wrongly elevated to error,
      which is set the error status of Diagnostics_area of the thread in THD::binlog_query().
      Yet the caller believes that binary logging shouldn't touch the status, so it will
      set the status also later by my_ok(), my_error() or my_message() seperately
      according to the execution result of the statement or transaction.
      But the status of Diagnostics_area of the thread is allowed to set only once.
      
      Fixed to clear the error wrongly set by binary logging, but keep the warning message.
      modified:
        mysql-test/suite/binlog/r/binlog_stm_ps.result
        mysql-test/suite/binlog/r/binlog_unsafe.result
        mysql-test/suite/binlog/t/binlog_unsafe.test
        mysql-test/suite/rpl/r/rpl_skip_error.result
        mysql-test/suite/rpl/r/rpl_stm_loadfile.result
        mysql-test/suite/rpl/r/rpl_udf.result
        sql/sql_class.cc

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

3175 Guangbao Ni	2009-04-03 [merge]
      Merge patch from 5.1-bugteam for bug#42640
      modified:
        mysql-test/suite/binlog/r/binlog_stm_ps.result
        mysql-test/suite/binlog/r/binlog_unsafe.result
        mysql-test/suite/binlog/t/binlog_unsafe.test
        mysql-test/suite/rpl/r/rpl_skip_error.result
        mysql-test/suite/rpl/r/rpl_stm_loadfile.result
        mysql-test/suite/rpl/r/rpl_udf.result
        sql/sql_class.cc

merged into mysql-5.1-bugteam and mysql-6.0-bugteam

Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)

Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:gni@mysql.com-20090403183234-0p092jet7271nwsc) (merge vers: 6.0.11-alpha) (pib:6)

Noted in 5.1.35, 6.0.12 changelogs.

Incorrect elevation of warning messages to error messages for unsafe
statements caused a server crash.

Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)

Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)

Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)

Pushed into 5.1.37 (revid:build@mysql.com-20090710231213-9guqdu0avc0uwdkp) (version source revid:build@mysql.com-20090710231213-9guqdu0avc0uwdkp) (merge vers: 5.1.37) (pib:11)

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090723102221-ps4uaphwbxzj8p0q) (version source revid:joerg@mysql.com-20090721145751-rqqnhv0kage18wfi) (merge vers: 5.4.4-alpha) (pib:11)

Pushed into 5.1.37-ndb-7.0.8 (revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)

Pushed into 5.1.37-ndb-6.3.27 (revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (version source revid:jonas@mysql.com-20090826105955-bkj027t47gfbamnc) (merge vers: 5.1.37-ndb-6.3.27) (pib:11)

Pushed into 5.1.37-ndb-6.2.19 (revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (version source revid:jonas@mysql.com-20090825194404-37rtosk049t9koc4) (merge vers: 5.1.37-ndb-6.2.19) (pib:11)

Pushed into 5.1.35-ndb-7.1.0 (revid:magnus.blaudd@sun.com-20090827163030-6o3kk6r2oua159hr) (version source revid:jonas@mysql.com-20090826132541-yablppc59e3yb54l) (merge vers: 5.1.37-ndb-7.0.8) (pib:11)