Bug #43698 Gopher crashes due to wrong page type when reading page into page cache
Submitted: 17 Mar 2009 12:33 Modified: 25 Mar 2009 14:32
Reporter: Olav Sandstå Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Falcon storage engine Severity:S2 (Serious)
Version:6.0.10,6.0.11-falcon-team OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: F_PAGE IO, pushbuild

[17 Mar 2009 12:33] Olav Sandstå
Description:
When running the falcon_bug_34351_C test (from the falcon_team suite) the server crashes due to the following error:

[Falcon] Error: page 54/1 wrong page type, expected 7 got 11

The call stack for the failing Gopher looks like:

  [11] Error::debugBreak(), line 94 in "Error.cpp"
  [12] Error::error(string = 0xfe6112 "page %d/%d wrong page type, expected %d g
ot %d\n", ...), line 71 in "Error.cpp"
  [13] Cache::fetchPage(this = 0x1631030, dbb = 0x17d08b0, pageNumber = 54, page
Type = PAGE_data, lockType = Exclusive), line 314 in "Cache.cpp"
  [14] Dbb::fetchPage(this = 0x17d08b0, pageNumber = 54, pageType = PAGE_data, l
ockType = Exclusive), line 219 in "Dbb.cpp"
  [15] RecordLocatorPage::deleteDataPages(this = 0x20c1000, dbb = 0x17d08b0, tra
nsId = 0), line 436 in "RecordLocatorPage.cpp"
  [16] Section::deleteSectionLevel(dbb = 0x17d08b0, pageNumber = 4, transId = 0)
, line 983 in "Section.cpp"
  [17] Section::deleteSection(dbb = 0x17d08b0, sectionId = 0, transId = 0), line
 953 in "Section.cpp"
  [18] SRLDropTable::commit(this = 0xfffffd7ffe184800), line 99 in "SRLDropTable
.cpp"
  [19] SerialLogTransaction::commit(this = 0x4ad1500), line 92 in "SerialLogTran
saction.cpp"
  [20] SerialLogTransaction::doAction(this = 0x4ad1500), line 158 in "SerialLogT
ransaction.cpp"
  [21] Gopher::gopherThread(this = 0x183c200), line 71 in "Gopher.cpp"
  [22] Gopher::gopherThread(arg = 0x183c200), line 37 in "Gopher.cpp"
  [23] Thread::thread(this = 0x1845cd8), line 166 in "Thread.cpp"
  [24] Thread::thread(parameter = 0x1845cd8), line 145 in "Thread.cpp"
  [25] _thr_setup(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff11fd7b 
  [26] _lwp_start(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff11ffb0 
current thread: t@1
=>[1] __pollsys(0xfffffd7fffdf97f0, 0x2, 0x0, 0x0, 0xfffffd7fff14e7c8, 0xfffffd7
fffdfbc08), at 0xfffffd7fff122cca 
  [2] _pollsys(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff114245 
  [3] _pselect(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff0ce474 
  [4] _select(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff0ce742 
  [5] handle_connections_sockets(), line 5188 in "mysqld.cc"
  [6] main(argc = 8, argv = 0xfffffd7fffdfdcb8), line 4696 in "mysqld.cc"

How to repeat:
Happened once after running falcon_bug_34351_C about 40 times

Suggested fix:
Do not crash.
[17 Mar 2009 12:42] Vladislav Vaintroub
pagetype requested == PAGE_data, got pagetype  == PAGE_free
[17 Mar 2009 12:57] Olav Sandstå
The user thread that most likely produced the log record that the Gopher is processing has the following call stack:

=>[1] lwp_yield(0xfffffd7ffede7a00, 0x9, 0x0, 0xfffffd7ffeda61f0, 0xfffffd7ffeda
61f0, 0x0), at 0xfffffd7fff1200aa 
  [2] preempt(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff117bb7 
  [3] _private_mutex_unlock(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff119456
 
  [4] Synchronize::wake(this = 0x1845de8), line 235 in "Synchronize.cpp"
  [5] Gopher::wakeup(this = 0x183c1c0), line 154 in "Gopher.cpp"
  [6] SerialLog::wakeup(this = 0x1791930), line 801 in "SerialLog.cpp"
  [7] Transaction::commit(this = 0x725dc68), line 307 in "Transaction.cpp"
  [8] Connection::commit(this = 0x187b708), line 272 in "Connection.cpp"
  [9] StorageTableShare::unRegisterTable(this = 0x187f530), line 702 in "Storage
TableShare.cpp"
  [10] StorageTableShare::deleteTable(this = 0x187f530, storageConnection = 0x18
81150), line 255 in "StorageTableShare.cpp"
  [11] StorageTable::deleteTable(this = 0x42fa538), line 88 in "StorageTable.cpp
"
  [12] StorageInterface::delete_table(this = 0x41e3a98, tableName = 0xfffffd7ffd
347660 "./test/t1"), line 1086 in "ha_falcon.cpp"
  [13] handler::ha_delete_table(this = 0x41e3a98, name = 0xfffffd7ffd347660 "./t
est/t1"), line 3296 in "handler.cc"
  [14] ha_delete_table(thd = 0x3d73110, table_type = 0x15878e8, path = 0xfffffd7
ffd347660 "./test/t1", db = 0x41e35f0 "test", alias = 0x41e3248 "t1", generate_w
arning = true), line 1934 in "handler.cc"
  [15] mysql_rm_table_part2(thd = 0x3d73110, tables = 0x41e3280, if_exists = fal
se, drop_temporary = false, drop_view = false, dont_log_query = false), line 176
2 in "sql_table.cc"
  [16] mysql_rm_table(thd = 0x3d73110, tables = 0x41e3280, if_exists = '\0', dro
p_temporary = '\0'), line 1512 in "sql_table.cc"
  [17] mysql_execute_command(thd = 0x3d73110), line 3343 in "sql_parse.cc"
  [18] mysql_parse(thd = 0x3d73110, inBuf = 0x41e2f68 "DROP TABLE t1", length = 
13U, found_semicolon = 0xfffffd7ffd34abe8), line 5763 in "sql_parse.cc"
  [19] dispatch_command(command = COM_QUERY, thd = 0x3d73110, packet = 0x3dcd111
 "DROP TABLE t1", packet_length = 13U), line 1009 in "sql_parse.cc"
  [20] do_command(thd = 0x3d73110), line 691 in "sql_parse.cc"
  [21] handle_one_connection(arg = 0x3d73110), line 1146 in "sql_connect.cc"
  [22] _thr_setup(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff11fd7b 
  [23] _lwp_start(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff11ffb0 
current thread: t@18

The SQL this is executing is "DROP TABLE t1" which is most likely the very last statement this test is doing (as part of clean-up).
[17 Mar 2009 13:16] Olav Sandstå
Setting this to verified based on seeing it a second time when running the same test.

This time the test fails with:

  [Falcon] Error: page 0/1 wrong page type, expected 7 got 1

which according to Vlad is very wrong given that page 0 never should be a data page (7) but a page header page (1 - which we also got when reading it from disk)
[17 Mar 2009 13:23] Olav Sandstå
The call stack for the second crash is identical to the first crash:

  [11] Error::debugBreak(), line 94 in "Error.cpp"
  [12] Error::error(string = 0xfe6112 "page %d/%d wrong page type, expected %d g
ot %d\n", ...), line 71 in "Error.cpp"
  [13] Cache::fetchPage(this = 0x1631030, dbb = 0x17f1ec8, pageNumber = 0, pageT
ype = PAGE_data, lockType = Exclusive), line 314 in "Cache.cpp"
  [14] Dbb::fetchPage(this = 0x17f1ec8, pageNumber = 0, pageType = PAGE_data, lo
ckType = Exclusive), line 219 in "Dbb.cpp"
  [15] RecordLocatorPage::deleteDataPages(this = 0x2051000, dbb = 0x17f1ec8, tra
nsId = 0), line 436 in "RecordLocatorPage.cpp"
  [16] Section::deleteSectionLevel(dbb = 0x17f1ec8, pageNumber = 4, transId = 0)
, line 983 in "Section.cpp"
  [17] Section::deleteSection(dbb = 0x17f1ec8, sectionId = 0, transId = 0), line
 953 in "Section.cpp"
  [18] SRLDropTable::commit(this = 0xfffffd7ffe184800), line 99 in "SRLDropTable
.cpp"
  [19] SerialLogTransaction::commit(this = 0x6701910), line 92 in "SerialLogTran
saction.cpp"
  [20] SerialLogTransaction::doAction(this = 0x6701910), line 158 in "SerialLogT
ransaction.cpp"
  [21] Gopher::gopherThread(this = 0x183c200), line 71 in "Gopher.cpp"
  [22] Gopher::gopherThread(arg = 0x183c200), line 37 in "Gopher.cpp"
  [23] Thread::thread(this = 0x1845cd8), line 166 in "Thread.cpp"
  [24] Thread::thread(parameter = 0x1845cd8), line 145 in "Thread.cpp"
  [25] _thr_setup(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff11fd7b 
  [26] _lwp_start(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff11ffb0
[17 Mar 2009 21:28] Olav Sandstå
I suspected this to be a recent regression since I had not seen it earlier. But it is possible to reproduce this failure using the falcon_bug_34351_C test for older versions. I have tried several versions from mysql-6.0-falcon-team tree and it is possible to reproduce it at least back to 2009-01-01.
[25 Mar 2009 14:32] Olav Sandstå
This bug is a duplicate of Bug#39890 Falcon Error: page 0/1 wrong page type, expected 7 got 1