| Bug #11813 | Server side cursor leads to server crash | ||
|---|---|---|---|
| Submitted: | 8 Jul 2005 12:45 | Modified: | 29 Jul 2005 10:44 |
| Reporter: | Andrey Hristov | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server | Severity: | S1 (Critical) |
| Version: | 5.0.10-beta-200507080400 | OS: | Linux (SLES 9) |
| Assigned to: | Konstantin Osipov | CPU Architecture: | Any |
[8 Jul 2005 12:48]
Andrey Hristov
Backtrace:
(gdb) bt
#0 mem_analyze_corruption (ptr=0x41215068 "\036\217") at mem0dbg.c:791
#1 0x08275007 in check_trx_exists (thd=0x8d606d0) at ha_innodb.cc:747
#2 0x0827bafc in ha_innobase::external_lock (this=0x8d5a820, thd=0x8d606d0, lock_type=2) at ha_innodb.cc:782
#3 0x0819c7c1 in unlock_external (thd=0x8d606d0, table=0x8d58cb4, count=1) at lock.cc:395
#4 0x0819c1e6 in mysql_unlock_tables (thd=0x2e, sql_lock=0x8d58ca0) at lock.cc:227
#5 0x081e12a5 in close_thread_tables (thd=0x8d606d0, lock_in_use=false, skip_derived=false, stopper=0x0)
at sql_base.cc:488
#6 0x081f281d in Cursor::close (this=0x8d96cc0) at sql_select.cc:1897
#7 0x081f28d9 in ~Cursor (this=0x8d96cc0) at sql_select.cc:1918
#8 0x08217aca in ~Prepared_statement (this=0x8d63dd0) at sql_prepare.cc:2431
#9 0x081957a1 in delete_statement_as_hash_key (key=0x2e) at sql_class.cc:1623
#10 0x084cfd76 in hash_free (hash=0x8d61564) at hash.c:93
#11 0x08191da7 in ~THD (this=0x8d606d0) at sql_class.h:894
#12 0x081a1a4e in end_thread (thd=0x8d606d0, put_in_cache=true) at mysqld.cc:1504
#13 0x081b632c in handle_one_connection (arg=0x2e) at sql_parse.cc:1150
#14 0x401739dd in start_thread () from /lib/tls/libpthread.so.0
#15 0x4029effa in clone () from /lib/tls/libc.so.6
(
[8 Jul 2005 13:03]
Andrey Hristov
So, with fast trace session with DDD the error is generated when the connection thread is being destructed and some magic number destroyed. The connection close is lead by an error 1158, "Got an error reading communication packets".
[8 Jul 2005 14:10]
MySQL Verification Team
Testing against a server 5.0.10 (yesterday evening pull) I got the below application error both on Linux and Windows: miguel@hegel:/share/dbs/5.0/bin$ ./bug1183 prep_stmt init done error while preparing 1 C:\temp>bug11813 prep_stmt init done error while preparing 1 I just modified the test case for localhost connection.
[8 Jul 2005 15:27]
Andrey Hristov
Crashes with build from this morning (5.0.10-beta). Jul, 8th, 04am GMT
[8 Jul 2005 15:32]
Heikki Tuuri
Andrey, what does mysqld print to the .err log? Does it print anything? When InnoDB frees the trx struct that it allocated for the thd, InnoDB writes over the magic number in the trx struct. If MySQL tries to free it again, that could explain the bug. Regards, Heikki
[8 Jul 2005 16:11]
MySQL Verification Team
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 196621 (LWP 20110)]
0x082a5930 in check_trx_exists (thd=0x8e042a8) at ha_innodb.cc:749
warning: Source file is more recent than executable.
749 ut_a(0);
(gdb) backtrace full
#0 0x082a5930 in check_trx_exists (thd=0x8e042a8) at ha_innodb.cc:749
trx = (trx_t *) 0x41187868
#1 0x082ae5c7 in ha_innobase::update_thd (this=0x8e05930, thd=0x8e042a8) at ha_innodb.cc:782
prebuilt = (row_prebuilt_t *) 0x41186e68
trx = (trx_t *) 0x860e126
#2 0x082ac734 in ha_innobase::external_lock (this=0x8e05930, thd=0x8e042a8, lock_type=2) at ha_innodb.cc:5967
prebuilt = (row_prebuilt_t *) 0x41186e68
trx = (trx_t *) 0x81c5caf
_db_func_ = 0xbe1ff81c "Lø\037¾]V\034\b¨Bà\bÄzà\b\001"
_db_file_ = 0xbe1ff804 "¶½_\bú¹_\001Lø\037¾\033V\034\b"
_db_level_ = 149097316
_db_framep_ = (char **) 0x827683d
#3 0x081c5cfa in unlock_external (thd=0x8e042a8, table=0x8e07ac4, count=1) at lock.cc:395
error = 148929220
error_code = 0
_db_func_ = 0x81c561b "\203Ä \213E\f\203x\b"
_db_file_ = 0xbe1ff84c "\214ø\037¾á\214 \b¨Bà\b°zà\bpø\037¾xø\037¾\016\024\031@\t"
_db_level_ = 23050746
_db_framep_ = (char **) 0x85fbdb6
#4 0x081c565d in mysql_unlock_tables (thd=0x8e042a8, sql_lock=0x8e07ab0) at lock.cc:227
_db_func_ = 0x85fa100 "sql_base.cc"
_db_file_ = 0x85fa453 "close_thread_tables"
_db_level_ = 136350530
_db_framep_ = (char **) 0xbe1ff88c
#5 0x08208ce1 in close_thread_tables (thd=0x8e042a8, lock_in_use=false, skip_derived=false, stopper=0x0) at sql_base.cc:488
found_old_table = 191
prelocked_mode = NON_PRELOCKED
_db_func_ = 0xbe1ff8cc "ìø\037¾öÁ!\bÈ\210ã\b"
_db_file_ = 0x0
_db_level_ = 1
_db_framep_ = (char **) 0x0
#6 0x0821c0c1 in Cursor::close (this=0x8e388c8, is_active=false) at sql_select.cc:1904
tmp_derived_tables = (TABLE *) 0x0
tmp_lock = (MYSQL_LOCK *) 0x0
thd = (class THD *) 0x8e042a8
_db_func_ = 0xbe1ff8e0 "üø\037¾f)*@À¹5@\fù\037¾NK$\bÈ\210ã\b¨Bà\b,ù\037¾sÀT\b;\001"
_db_file_ = 0x4035b9c0 ""
_db_level_ = 1077262784
_db_framep_ = (char **) 0x40195ff4
---Type <return> to continue, or q <return> to quit---
#7 0x0821c1f6 in ~Cursor (this=0x8e388c8) at sql_select.cc:1921
No locals.
#8 0x08244b4e in ~Prepared_statement (this=0x8e10bd8) at sql_prepare.cc:2448
No locals.
#9 0x081bdef4 in delete_statement_as_hash_key (key=0x8e10bd8) at sql_class.cc:1632
No locals.
#10 0x085558b5 in hash_free_elements (hash=0x8e05144) at hash.c:93
data = (HASH_LINK *) 0x8e05648
end = (HASH_LINK *) 0x8e05648
#11 0x0855486a in hash_free (hash=0x8e05144) at hash.c:114
_db_func_ = 0xbe1ff998 ""
_db_file_ = 0x131 <Address 0x131 out of bounds>
_db_level_ = 139769488
_db_framep_ = (char **) 0xbe1ff99c
#12 0x081bfa83 in ~Statement_map (this=0x8e05144) at sql_class.h:898
No locals.
#13 0x081ba131 in ~THD (this=0x8e042a8) at sql_class.cc:428
_db_func_ = 0x8e042a8 "\b\226[\bh~y\bl~y\b\030\226[\b"
_db_file_ = 0x0
_db_level_ = 139870679
_db_framep_ = (char **) 0xbe1ff9cc
#14 0x081cb11c in end_thread (thd=0x8e042a8, put_in_cache=true) at mysqld.cc:1504
_db_func_ = 0x32 <Address 0x32 out of bounds>
_db_file_ = 0x8e04a1c "øfà\b"
_db_level_ = 23
_db_framep_ = (char **) 0x8e05318
#15 0x081df35e in handle_one_connection (arg=0x8e042a8) at sql_parse.cc:1150
error = 0
net = (NET *) 0x8e04a1c
thd = (class THD *) 0x8e042a8
launch_time = 0
set = {__val = {0 <repeats 32 times>}}
#16 0x4018d54e in pthread_start_thread () from /lib/libpthread.so.0
No symbol table info available.
#17 0x4018d5df in pthread_start_thread_event () from /lib/libpthread.so.0
No symbol table info available.
#18 0x402fab8a in clone () from /lib/libc.so.6
No symbol table info available.
(gdb)
[9 Jul 2005 21:08]
Hakan Küçükyılmaz
Hi Heikki, error.log says: 050709 23:06:07 InnoDB: Error: MySQL is freeing a thd InnoDB: though trx->n_mysql_tables_in_use is 1 InnoDB: and trx->mysql_n_tables_locked is 0. TRANSACTION 0 0, not started, process no 10428, OS thread id 1091696992 mysql tables in use 1, locked 0 MySQL thread id 1959, query id 7755141 localhost root len 1160; hex 065c6e05000000002212830000000000010000000000000001000000000000003f3cd0420000000002000000000000000100000000000000010000000000000000000000000000000000000000000000ffffffffffffffff0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000100000000000000ffffffff00000000ffffffff000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000010000000000000070e569030000000028f26903000000008d1bb100000000000000000000000000221283000000000000000000000000000000000000000000000000000000000060f9114100000000bc28000000000000010000000000000000000000000000000000000000000000000000000000000010270000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000001000000000000004005b000000000000000000000000000b8f017972a0000000a000000000000000100000000000000b87808972a000000010000000000000000000000000000000000000000000000000000000000000010d5690300000000a0047a0300000000a0047a03000000002051b100000000002051b10000000000000000000000000000000000000000000000000000000000000000000000000000000000030000006077830000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000030077a0300000000000000000000000000000000000000000000000000000000d0087a030000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000000000000000000003000000000000000000000000000000000000000000000051728600000000003e0200000000000000000000000000000000000000000000000000000000000028e4790300000000bc020000000000001bb6850000000000780000000000000081f20e0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000025b6850000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000; asc \n " ?< B p i ( i " ` A ( ' @ * x * i z z Q Q `w 0 z z Qr > ( y x % ;InnoDB: Apparent memory corruption: mem dump len 500; hex 000000000000000000004005b00000000000d10e00000000000010c9780300000000405d7d030000000020ff79030000000020ff79030000000003000300000000000000000003000100000000000000000010d56903000000000000000000000000810e000000000000d04f76030000000090b97903000000001805000000000000f63d775f000000009268a5200000000078307472782e6300510000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000f80400000000000000000000000000000000000000000000f804000000000000700000000000000000000000000000001e8fa900000000002212830000000000010000000000000001000000000000003f3cd0420000000002000000000000000100000000000000010000000000000000000000000000000000000000000000ffffffffffffffff0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000100000000000000ffffffff00000000ffff; asc @ x @]} y y i Ov y =w_ h x0trx.c Q p " ?< B ; InnoDB: Scanning backward trying to find previous allocated mem blocks Freed mem block at - 112, file x0trx.c, line 81 Mem block at - 4960, file mysql.c, line 591 Mem block at - 7344, file mysql.c, line 591 Mem block at - 8016, file 0dict.c, line 3628 Mem block at - 10576, file t0mem.c, line 194 Mem block at - 29504, file nodb.cc, line 2944 Mem block at - 29744, file w0sel.c, line 2924 Mem block at - 30000, file t0mem.c, line 194 Mem block at - 34224, file nodb.cc, line 2944 Mem block at - 34480, file t0mem.c, line 47 InnoDB: Scanning forward trying to find next allocated mem blocks Freed mem block at + 1200, file x0trx.c, line 148 Freed mem block at + 1616, file x0trx.c, line 162 Mem block at + 3600, file m0rec.c, line 1218 Mem block at + 4864, file t0mem.c, line 47 Mem block at + 5152, file m0rec.c, line 1218 Mem block at + 5408, file m0rec.c, line 1218 Mem block at + 6352, file mysql.c, line 591 Mem block at + 6992, file 0pcur.c, line 29 Mem block at + 7504, file t0mem.c, line 47 Mem block at + 8320, file t0mem.c, line 47 050709 23:06:07InnoDB: Assertion failure in thread 1091696992 in file ha_innodb.cc line 749 InnoDB: Failing assertion: 0 InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to http://bugs.mysql.com. InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: http://dev.mysql.com/doc/mysql/en/Forcing_recovery.html InnoDB: about forcing recovery. mysqld got signal 11; 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=33554432 read_buffer_size=2093056 max_used_connections=5 max_connections=100 threads_connected=4 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 441967 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Number of processes running now: 0 050709 23:06:07 mysqld restarted 050709 23:06:10 InnoDB: Database was not shut down normally! InnoDB: Starting crash recovery. InnoDB: Reading tablespace information from the .ibd files... InnoDB: Restoring possible half-written data pages from the doublewrite InnoDB: buffer... 050709 23:06:10 InnoDB: Starting log scan based on checkpoint at InnoDB: log sequence number 19 846386472. InnoDB: Doing recovery: scanned up to log sequence number 19 846386472 InnoDB: Last MySQL binlog file position 0 0, file name 050709 23:06:12 InnoDB: Started; log sequence number 19 846386472 050709 23:06:12 [Note] /usr/local/mysql-5.0-debug/libexec/mysqld: ready for connections. Version: '5.0.9-beta-debug' socket: '/tmp/mysql.sock' port: 3306 Source distribution HTH, Hakan
[11 Jul 2005 11:35]
Heikki Tuuri
All,
ALWAYS put the mysqld printout to the bug report. That will often speed up bug resolution.
In this case, InnoDB printed to the .err log the probable reason for the bug.
The bug is apparently that MySQL frees the thd, but continues using the thd. InnoDB sets thrx->magic_n to a new value, so that we can notice it has been freed. That is noticed later, in ha_innodb.cc, and InnoDB asserts.
Regards,
Heikki
trx0trx.c:
if (trx->n_mysql_tables_in_use != 0
|| trx->mysql_n_tables_locked != 0) {
ut_print_timestamp(stderr);
fprintf(stderr,
" InnoDB: Error: MySQL is freeing a thd\n"
"InnoDB: though trx->n_mysql_tables_in_use is %lu\n"
"InnoDB: and trx->mysql_n_tables_locked is %lu.\n",
(ulong)trx->n_mysql_tables_in_use,
(ulong)trx->mysql_n_tables_locked);
trx_print(stderr, trx);
ut_print_buf(stderr, (byte*)trx, sizeof(trx_t));
}
ut_a(trx->magic_n == TRX_MAGIC_N);
trx->magic_n = 11112222;
[20 Jul 2005 16:03]
Bugs System
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/internals/27381
[25 Jul 2005 9:59]
Andrey Hristov
After closing check 11914 whether then the problem still persists. Looks like the same problem there.
[26 Jul 2005 6:56]
Andrey Hristov
after applying patch from http://lists.mysql.com/internals/27467 (still not pushed to the tree as http://lists.mysql.com/internals/27381 is) no crash anymore.
[29 Jul 2005 10:44]
Andrey Hristov
as of today no problems. (probably needs documenting).
Description: Server crashes when executing a prepared statement which is a server side cursor. How to repeat: The table definition: CREATE TABLE "TATOPA" ( "K1C4" varchar(4) collate latin1_bin NOT NULL default ' ', "K2C4" varchar(4) collate latin1_bin NOT NULL default ' ', "K3C4" varchar(4) collate latin1_bin NOT NULL default ' ', "K4N4" varchar(4) collate latin1_bin NOT NULL default '0000', "F1C4" varchar(4) collate latin1_bin NOT NULL default ' ', "F2I4" int(11) NOT NULL default '0', "F3N5" varchar(5) collate latin1_bin NOT NULL default '00000', "F4I4" int(11) NOT NULL default '0', "F5C8" varchar(8) collate latin1_bin NOT NULL default ' ', "F6N4" varchar(4) collate latin1_bin NOT NULL default '0000', "F7F8" double NOT NULL default '0', "F8F8" double NOT NULL default '0', "F9D8" decimal(8,2) NOT NULL default '0.00', PRIMARY KEY ("K1C4","K2C4","K3C4","K4N4") ) ENGINE=InnoDB DEFAULT CHARSET=latin1 COLLATE=latin1_bin The test program: #include "my_global.h" #include "mysql.h" #define SELECT123 "SELECT `K1C4` ,`K2C4` ,`K3C4` ,`K4N4` ,`F1C4` ,`F2I4` ,`F3N5` ,`F4I4` ,`F5C8`, `F6N4` ,`F7F8` ,`F8F8` ,`F9D8` FROM `TATOPA`" int main(int argc, char **argv) { MYSQL *conn; MYSQL_STMT *prep_stmt = NULL; char row_data[]="EINS\0$RT\0\0WORT\0""0400\0"; int res, i; const ulong type= (ulong)CURSOR_TYPE_READ_ONLY; mysql_library_init(argc, argv, NULL); conn = mysql_init(NULL); conn = mysql_real_connect(conn, "10.10.10.10", "root", "hypersecret", "test", 0, NULL, 0); if (!conn) exit(1); prep_stmt= mysql_stmt_init(conn); if (!prep_stmt) { fprintf(stderr, "Out of memory when creating the statement"); exit(2); } printf("prep_stmt init done\n"); if ((res= mysql_stmt_prepare(prep_stmt, SELECT123 , strlen(SELECT123)))) { fprintf(stderr, "error while preparing %d", res); exit(3); } mysql_stmt_attr_set(prep_stmt, STMT_ATTR_CURSOR_TYPE, (const void *)&type); printf("cursor set\n"); if ((res= mysql_stmt_execute(prep_stmt))) { fprintf(stderr, "Error while executing the query %d", res); exit(4); } printf("cursor executed\n"); }