Bug #44516 Invalid Archive table handler if opened from cached share.
Submitted: 28 Apr 2009 13:23 Modified: 26 May 2009 16:38
Reporter: Rafal Somla Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Archive storage engine Severity:S3 (Non-critical)
Version:6.0 OS:Any
Assigned to: CPU Architecture:Any

[28 Apr 2009 13:23] Rafal Somla
Description:
Assume an empty table is present in the server, and we want to do the following:

TABLE_LIST tl;
open_and_lock_tables(thd, &tl);

handler *hdl= tl.table->file;

hdl->ha_rnd_init();
int res= hdl->rnd_next(tl.table->record[0]);
hdl->ha_rnd_end();

Since table is empty, rnd_next() should return HA_ERR_END_OF_FILE. However, if it 
is an Archive table, and if table's share is present in the cache, then 
open_table() (which in that case calls open_table_from_share()) creates a wrongly 
initialized handler and then rnd_next() returns -1, which is wrong.

How to repeat:
I shall add a repeatable test case soon.
[29 Apr 2009 11:45] Rafal Somla
Patch to demonstrate the issue.

Attachment: sql_parse.diff (application/octet-stream, text), 1.77 KiB.

[29 Apr 2009 11:48] Rafal Somla
To see the problem, modify the server with the attached sql_parse.diff patch and then run the following test case:

--------------------------8<--------------------------------
CREATE DATABASE db1;
CREATE TABLE db1.t1 (a int) ENGINE=Archive;
BEGIN;
-------------------------->8--------------------------------

The test will crash on assertion if rnd_next() returns wrong result.
[29 Apr 2009 11:52] Rafal Somla
REFINED PROBLEM DESCRIPTION
---------------------------
After openning the table and initializing rnd scan, rnd_next() returns 
HA_ERR_CRASHED_ON_USAGE instead of HA_ERR_END_OF_FILE (the table is empty).

The error is detected in ha_archive::unpack_row() which is called like this:

#0  ha_archive::unpack_row (this=0x99c4c50, file_to_read=0x99c4db4, record=0x98d8930 '¥' <repeats 16 times>, "H\211\215\t") at ha_archive.cc:1058
#1  0x0862e8b0 in ha_archive::get_row_version3 (this=0x99c4c50, file_to_read=0x99c4db4, buf=0x98d8930 '¥' <repeats 16 times>, "H\211\215\t") at ha_archive.cc:1090
#2  0x0862e955 in ha_archive::get_row (this=0x99c4c50, file_to_read=0x99c4db4, buf=0x98d8930 '¥' <repeats 16 times>, "H\211\215\t") at ha_archive.cc:1023
#3  0x0862eb9d in ha_archive::rnd_next (this=0x99c4c50, buf=0x98d8930 '¥' <repeats 16 times>, "H\211\215\t") at ha_archive.cc:1115
#4  0x0837a9c1 in mysql_execute_command (thd=0x9978ab0) at sql_parse.cc:4161

This is the place where error is detected (ha_archive.cc):

1067  if (error || read == 0)
1068  {
1069    DBUG_RETURN(HA_ERR_CRASHED_ON_USAGE);
1070  }

Error is reported because read==0 which is because azread_row() called before 
did not read any bytes as the file is empty.

Normally, ha_archive::get_row() which calls unpack_row() should not be called 
from within rnd_next() because of this logic (ha_archive.cc):

1101 int ha_archive::rnd_next(uchar *buf)
1102 {
1103   int rc;
1104   DBUG_ENTER("ha_archive::rnd_next");
1105
1106   if (share->crashed)
1107       DBUG_RETURN(HA_ERR_CRASHED_ON_USAGE);
1108
1109   if (!scan_rows)
1110     DBUG_RETURN(HA_ERR_END_OF_FILE);
1111   scan_rows--;
1112
1113   ha_statistic_increment(&SSV::ha_read_rnd_next_count);
1114   current_position= aztell(&archive);
1115   rc= get_row(&archive, buf);

My hypothesis is that in normal circumstances, scan_rows is always 0 for an 
empty table and thus HA_ERR_END_OF_FILE is returned at line 1110 without 
calling get_row(). 

I observed that usually, when table is opened, scan_rows is set to 0 in 
ha_archive::info() which is called somewhere in the process. But in the situation created in the test, table is opened with  open_table_from_share() at 
sql_base.cc:2770, and then scan_rows is not initialized. This is most probably 
the cause of the problem.

To trigger this situation 2 conditions must be met:

1. Table share should be present in the cache (e.g. because the table was 
already opened once). In the test this is achieved by using serialization 
service from si_objects which leaves table share in the cache.

2. Table itself should not be cached, so that open_table_from_share() will be 
called. In the test this is achieved by calling flush_tables(). But even without 
an explicit flush, table can be removed from the cache when it is cleaned.
[26 May 2009 16:38] MySQL Verification Team
Thank you for the bug report. Verified as described:

090526 13:36:10 [Note] 6.0\bin\mysqld-debug: ready for connections.
Version: '6.0.12-alpha-Win X64-debug-log'  socket: ''  port: 3600  Source distribution
xx: serializing table t1
xx: openning table t1
xx: scanning table t1
xx: rnd_next() should return 137 and returned 145
Assertion failed: res == 137, file .\sql_parse.cc, line 4207
090526 13:36:47 - mysqld got exception 0x80000003 ;
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=8384512
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 338239 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x7194590
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...
00000001408305B5    mysqld-debug.exe!my_sigabrt_handler()[my_thr_init.c:510]
000000014000BB21    mysqld-debug.exe!raise()[winsig.c:597]
000000014000F5A3    mysqld-debug.exe!__crtMessageWindowA()[dbgrpt.c:434]
000000014001787C    mysqld-debug.exe!_VCrtDbgReportA()[dbgrptt.c:420]
000000014000EFE3    mysqld-debug.exe!_CrtDbgReportV()[dbgrpt.c:301]
000000014000EF7D    mysqld-debug.exe!_CrtDbgReport()[dbgrpt.c:317]
000000014000945B    mysqld-debug.exe!_NMSG_WRITE()[crt0msg.c:197]
00000001400140D7    mysqld-debug.exe!abort()[abort.c:68]
00000001407F4E94    mysqld-debug.exe!_wassert()[assert.c:212]
0000000140212099    mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:4207]
0000000140217D3B    mysqld-debug.exe!mysql_parse()[sql_parse.cc:6032]
00000001402094DF    mysqld-debug.exe!dispatch_command()[sql_parse.cc:1068]
0000000140208AF8    mysqld-debug.exe!do_command()[sql_parse.cc:748]
00000001400D5346    mysqld-debug.exe!handle_one_connection()[sql_connect.cc:1146]
000000014082FBAB    mysqld-debug.exe!pthread_start()[my_winthread.c:62]
000000014095A815    mysqld-debug.exe!_callthreadstartex()[threadex.c:348]
000000014095A7E4    mysqld-debug.exe!_threadstartex()[threadex.c:331]
000000007781C3BD    kernel32.dll!BaseThreadInitThunk()
0000000077C74581    ntdll.dll!RtlUserThreadStart()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 00000000071B72F8=BEGIN
thd->thread_id=1
thd->killed=NOT_KILLED
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.