Querying myisam table metadata while 'alter table..enable keys' is running may corrupt the table

[Andrei Laki]

In MariaDB 5.3.3 tables are reported as corrupted in the server log when metadata queries like "show table status like 'tablename'" or "select ..from information_schemna where table_schema = 'dbname'
       AND a.table_name LIKE 'tablename'" are run while indexes are getting rebuilt with "alter table tablename enable keys".

I can consistently replicate the problem in MariaDB 5.3.3 (mariadb-5.3.3-rc-Linux-x86_64.tar.gz) running on RHEL 5.7 and RHEL 6.1.

An error like

 [ERROR] mysqld: Table './dbname/tablename' is marked as crashed and should be repaired

gets logged in the server log just as the metadata query is getting submitted. The query remains in a "Waiting for table" state and will return only after the "alter table enable keys" query ends.
Running "check table" or "repair table" after "alter table enable keys" won't report any problems.

Use this script to reproduce the problem:

#!/bin/sh

HOST=localhost
PORT=3306
USER=
PASSWORD=
DATABASE=test
MYSQL_CLIENT=/usr/bin/mysql
TABLE=reproducer
DATAFILE=reproducer.txt

function generate_file {
  echo "Generating data file $DATAFILE.."
  for i in {1..100000}
  do
    echo "$i,line number $i" >> $DATAFILE
  done
}

function run_cmd {
  echo "Running -> '$1'"
  $MYSQL_CLIENT --host=$HOST --user=$USER --password=$PASSWORD --database=$DATABASE --exec="$1"
}

generate_file

run_cmd "drop table if exists $TABLE"
run_cmd "create table $TABLE (id int, sometext varchar(100), primary key (id), index(sometext)) ENGINE=myisam"
run_cmd "alter table $TABLE disable keys"
run_cmd "load data local infile '$DATAFILE' into table $TABLE fields terminated by ','"

run_cmd "alter table $TABLE enable keys" &
sleep 1
run_cmd "show table status like '$TABLE'"

[Elena Stepanova (elenst)]

Debug version of the server aborts with the assertion failure.
It is reproducible on 5.1, 5.2, 5.3 with the provided test, although the sleep time might require adjusting. MTR version of the test case is below.

mi_open.c:64: test_if_reopen: Assertion `strcmp(share->unique_file_name,filename) || share->last_version' failed.

#8 0xb759a014 in __assert_fail () from /lib/libc.so.6
#9 0x0855573f in test_if_reopen (filename=0x8fbdb3e0 "/home/elenst/5.3.3-release/data/test/reproducer.MYI") at mi_open.c:63
#10 0x085558f4 in mi_open (name=0x9f3d310 "./test/reproducer", mode=2, open_flags=82) at mi_open.c:112
#11 0x08517b5c in ha_myisam::open (this=0xa049140, name=0x9f3d310 "./test/reproducer", mode=2, test_if_locked=18) at ha_myisam.cc:720
#12 0x08433f7a in handler::ha_open (this=0xa049140, table_arg=0xa048a10, name=0x9f3d310 "./test/reproducer", mode=2, test_if_locked=18)
    at handler.cc:2189
#13 0x0834860c in open_table_from_share (thd=0x9f9d768, share=0x9f3d060, alias=0xa03da10 "reproducer", db_stat=39, prgflag=44, ha_open_flags=16,
    outparam=0xa048a10, is_create_table=false) at table.cc:2369
#14 0x0833629b in open_unireg_entry (thd=0x9f9d768, entry=0xa048a10, table_list=0xa03da20, alias=0xa03da10 "reproducer", cache_key=0x8fbdc241 "test",
    cache_key_length=16, mem_root=0x8fbdc440, flags=0) at sql_base.cc:4102
#15 0x08333d95 in open_table (thd=0x9f9d768, table_list=0xa03da20, mem_root=0x8fbdc440, refresh=0x8fbdc487, flags=2) at sql_base.cc:2974
#16 0x08337655 in open_tables (thd=0x9f9d768, start=0x8fbdc4f4, counter=0x8fbdc4dc, flags=2) at sql_base.cc:4796
#17 0x083384fe in open_normal_and_derived_tables (thd=0x9f9d768, tables=0xa03da20, flags=2, dt_phases=34) at sql_base.cc:5266
#18 0x08475961 in fill_schema_table_by_open (thd=0x9f9d768, is_show_fields_or_keys=false, table=0xa03b460, schema_table=0x8b161f8,
    orig_db_name=0x8fbdcfe8, orig_table_name=0xa039470, open_tables_state_backup=0x8fbdcf58) at sql_show.cc:3580
#19 0x084767aa in get_all_tables (thd=0x9f9d768, tables=0xa038470, cond=0x0) at sql_show.cc:4032
#20 0x08480e09 in get_schema_tables_result (join=0xa042428, executed_place=PROCESSED_BY_JOIN_EXEC) at sql_show.cc:6800
#21 0x08356b7a in JOIN::exec (this=0xa042428) at sql_select.cc:2186
#22 0x083591ad in mysql_select (thd=0x9f9d768, rref_pointer_array=0x9f9f2f4, tables=0xa038470, wild_num=0, fields=..., conds=0x0, og_num=0,
    order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684635648, result=0xa0392f0, unit=0x9f9eed8, select_lex=0x9f9f1b8)
    at sql_select.cc:2931
#23 0x08350ec7 in handle_select (thd=0x9f9d768, lex=0x9f9ee7c, result=0xa0392f0, setup_tables_done_option=0) at sql_select.cc:284
#24 0x082ec31d in execute_sqlcom_select (thd=0x9f9d768, all_tables=0xa038470) at sql_parse.cc:5151
#25 0x082e36f9 in mysql_execute_command (thd=0x9f9d768) at sql_parse.cc:2284
#26 0x082ee958 in mysql_parse (thd=0x9f9d768, rawbuf=0xa0374a8 "show table status like 'reproducer'", length=35, found_semicolon=0x8fbde234)
    at sql_parse.cc:6152
#27 0x082e1339 in dispatch_command (command=COM_QUERY, thd=0x9f9d768, packet=0xa02f449 "show table status like 'reproducer'", packet_length=35)
    at sql_parse.cc:1228
#28 0x082e0...

[Michael Widenius (monty)]

This happens because SHOW commands ignores that table is in FLUSH and tells handler to open a table anyway (which MyISAM can't handle).
Fixed by introducing a new flag in 5.3 when opening a table for status read only.

[Jervin R (revin)]

This bug appears to be present still on 5.3.6 - possibly not during ENABLE|DISABLE keys but immediately before drop. see my.cnf below and Ruby script for test case.

[mysqld]
basedir=/home/revin/Downloads/mariadb-5.3.6-Linux-x86_64/
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=revin
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

collation_server = utf8_unicode_ci
character_set_server = utf8
skip-external-locking
#fast_index_creation = false

# 10MB ramdisk - can be ignored
tmpdir = /tmpfs

key_buffer = 276M
innodb_buffer_pool_size = 276M
max_allowed_packet = 16M
thread_stack = 256K
thread_cache_size = 128
thread_concurrency = 8
max_connections = 512
table_cache = 2048
myisam-recover = BACKUP
query_cache_limit = 1M
query_cache_size = 128M
expire_logs_days = 10
max_binlog_size = 100M

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

[Jason Parrott (jparrott)]

I can confirm that Jervin's reproducer works and produces this error message:

120426 11:32:39 [ERROR] mysqld: Table './test/customer46' is marked as crashed and should be repaired

Elena, would you rather I open a new bug report?

[Elena Stepanova (elenst)]

Hi Jervin, Jason,

Yes, if it's not too much trouble, please do open a new bug report.

[Jason Parrott (jparrott)]

No problem - opened bug #989055 and attached Jervin's code.