Bug #39375 Online backup crashes with simple combination of tables/triggers and SP
Submitted: 10 Sep 2008 17:52 Modified: 11 Feb 2009 3:26
Reporter: Omer Barnir (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Backup Severity:S3 (Non-critical)
Version:6.0.5 / 6.0.8 OS:Any
Assigned to: Rafal Somla CPU Architecture:Any

[10 Sep 2008 17:52] Omer Barnir
Description:
Server crashes with signal 6 when running online backup on an idle system that includes a combination of simple tables triggers and stored procedures (to see details of the schema created see init.test file attached).

After running the backup command the master.err file includes the following:

080910  7:25:17 [Note] Backup: Starting backup process
080910  7:25:17 [Note] Backup: Backing up selected databases
mysqld: item_cmpfunc.cc:3820: virtual longlong Item_func_in::val_int(): Assertion `fixed == 1' failed.
/home/omer/my_bzr/src-60/sql/mysqld(my_print_stacktrace+0x26)[0x8945fd5]
/home/omer/my_bzr/src-60/sql/mysqld(handle_segfault+0x2cd)[0x832b1fb]
[0xffffe420]
/lib/libc.so.6(abort+0x101)[0xb7c381e1]
/lib/libc.so.6(__assert_fail+0xee)[0xb7c2fc1e]
/home/omer/my_bzr/src-60/sql/mysqld(_ZN12Item_func_in7val_intEv+0x35)[0x82a4b67]
/home/omer/my_bzr/src-60/sql/mysqld(_Z14get_all_tablesP3THDP10TABLE_LISTP4Item+0x5ca)[0x84a46b2]
/home/omer/my_bzr/src-60/sql/mysqld[0x851c8ee]
/home/omer/my_bzr/src-60/sql/mysqld(_ZN3obs25InformationSchemaIterator16prepare_is_tableEP3THDPP8st_tablePP7handlerPPj18enum_schema_tables4ListI19st_mysql_lex_stringE+0x172)[0x851caca]
/home/omer/my_bzr/src-60/sql/mysqld(_ZN3obs18create_is_iteratorINS_15DbViewsIteratorEEEPT_P3THD18enum_schema_tablesPK6String+0xbb)[0x8520655]
/home/omer/my_bzr/src-60/sql/mysqld(_ZN3obs12get_db_viewsEP3THDPK6String+0x20)[0x851cd76]
/home/omer/my_bzr/src-60/sql/mysqld(_ZN11Backup_info12add_db_itemsERN6backup10Image_info2DbE+0x37a)[0x8a04554]
/home/omer/my_bzr/src-60/sql/mysqld(_ZN11Backup_info7add_dbsER4ListI19st_mysql_lex_stringE+0x151)[0x8a04b6d]
/home/omer/my_bzr/src-60/sql/mysqld(_Z22execute_backup_commandP3THDP6st_lexP6String+0x310)[0x89ede2a]
/home/omer/my_bzr/src-60/sql/mysqld(_Z21mysql_execute_commandP3THD+0xbe0)[0x833da76]
/home/omer/my_bzr/src-60/sql/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x22f)[0x83464bb]
/home/omer/my_bzr/src-60/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x8a4)[0x8346eec]
/home/omer/my_bzr/src-60/sql/mysqld(_Z10do_commandP3THD+0x23b)[0x834820b]
/home/omer/my_bzr/src-60/sql/mysqld(handle_one_connection+0x11d)[0x83345ff]
/lib/libpthread.so.0[0xb7eae192]
/lib/libc.so.6(clone+0x5e)[0xb7cd002e]
080910  7:25:17 - 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
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 = 60039 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x9ba52a0
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 = 0xb298bfa8 thread_stack 0x30c00
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x9c05c38 = backup database systest1 to '/tmp/omer_backup.kck'
thd->thread_id=5
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.
Writing a core file

How to repeat:
Start the mysql server using  
   perl ./mysql-test-run.pl --mysqld=--innodb --start-and-exit
Load the system with the attached dump file (systest1.dump.tar.gz) using
   mysql --user=root --port=9306 --protocol=tcp < systest1.dump
This will create the systest1 database as described in (init.test above)
Run a backup command on the systest1 database
   mysql --user=root --port=9306 --protocol=tcp \
         -e"backup database systest1 to '/some_path_to/file.bck';"
Observe crash:
ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query
   

Suggested fix:
Server should not crash
[10 Sep 2008 17:56] Omer Barnir
Dump of the systest1 database crashing online backup

Attachment: systest1.dump.tar.gz (application/x-gzip, text), 166.30 KiB.

[10 Sep 2008 17:57] Omer Barnir
test file used to generate the schema used in creating systest1

Attachment: init.test (application/octet-stream, text), 15.67 KiB.

[26 Sep 2008 14:33] Omer Barnir
The above init.test file references an include file setting some default values.
Replace the include call line with the following:

--disable_query_log
eval SET @NUM_VAL = IF( '$NUM_VAL' = '', 15, '$NUM_VAL');
eval SET @LOAD_LINES = IF( '$LOAD_LINES' = '', 500, '$LOAD_LINES');
eval SET @LOG_UPPER = IF( '$LOG_UPPER' = '', 5000, '$LOG_UPPER');
eval SET @LOG_LOWER = IF( '$LOG_LOWER' = '', 4000, '$LOG_LOWER');
eval SET @ENG1 = IF( '$ENG1' = '', 'myisam', '$ENG1');
eval SET @ENG1_ALT = IF( '$ENG1_ALT' = '', 'innodb', '$ENG1_ALT');
eval SET @ENG2 = IF( '$ENG2' = '', 'innodb', '$ENG2');
eval SET @ENG_LOG = IF( '$ENG_LOG' = '', 'innodb', '$ENG_LOG');
eval SET @CLIENT_HOST = IF( '$CLIENT_HOST' = '', 'localhost', '$CLIENT_HOST');
eval SET @IUDS_UNIT = IF( '$IUDS_UNIT' = '', 10, '$IUDS_UNIT');
eval SET @TB1_ENG1_UPPER = IF( '$TB1_ENG1_UPPER' = '', @LOAD_LINES, '$TB1_ENG1_UPPER');
eval SET @WITH_TRIGGERS = IF( '$WITH_TRIGGERS' = '', 0, '$WITH_TRIGGERS');
eval SET @CYCLE = IF( '@CYCLE' = '', 60, '$CYCLE');
eval SET @ddl_sleep = IF( '$ddl_sleep' = '', 60, '$ddl_sleep');
--enable_query_log

Sorry of missing it with the original upload
[26 Sep 2008 16:57] Rafal Somla
Here is a gdb backtrace from the crash I managed to get:

#6  0x401e305f in __assert_fail () from /lib/tls/libc.so.6
#7  0x0826d767 in Item_func_in::val_int (this=0x9724eb0) at item_cmpfunc.cc:3820
#8  0x0846ce0f in get_all_tables (thd=0x9650e08, tables=0x4a4150b4, cond=0x9724eb0) at sql_show.cc:3327
#9  0x084e429b in (anonymous namespace)::open_schema_table (thd=0x9650e08, st=0x8ba1b08, db_list=0x4a415358) at si_objects.cc:323
#10 0x084e43b7 in obs::InformationSchemaIterator::prepare_is_table (thd=0x9650e08, is_table=0x4a415354, ha=0x4a415350, 
    orig_columns=0x4a41534c, is_table_idx=SCH_TABLES, db_list=@0x4a415358) at si_objects.cc:1061
#11 0x084e7441 in obs::create_is_iterator<obs::DbViewsIterator> (thd=0x9650e08, is_table_idx=SCH_TABLES, db_name=0x96d3110)
    at si_objects.cc:1471
#12 0x084e4526 in obs::get_db_views (thd=0x9650e08, db_name=0x96d3110) at si_objects.cc:1512
#13 0x089bc546 in Backup_info::add_db_items (this=0x96e6710, db=@0x96d3108) at backup_info.cc:754
#14 0x089bcaaa in Backup_info::add_dbs (this=0x96e6710, dbs=@0x965263c) at backup_info.cc:554
#15 0x089a5efa in execute_backup_command (thd=0x9650e08, lex=0x9652038, backupdir=0x4a415c9c) at kernel.cc:186

Looks like the COND object passed from open_schema_table() to get_all_tables() is not completely valid. This COND is created by obs::create_db_select_condition() at #9.
[22 Dec 2008 13:19] Rafal Somla
I'm not able to reproduce crash with the current tree. Please consider changing priority of this bug accordingly.
[22 Dec 2008 13:21] Rafal Somla
Smallest test case with which I could reproduce problem.

Attachment: bug.test (application/octet-stream, text), 5.18 KiB.

[22 Dec 2008 13:23] Rafal Somla
With the attached test case I do not observe crashes any more. However, the produced backup image is corrupted (inside meta-data storing section). RESTORE detects and reports error.

Need to investigate cause of the corruption and remove it.
[23 Dec 2008 20:11] Omer Barnir
triage: value updated based on description of not crashing anymore
[5 Jan 2009 13:15] Rafal Somla
DETAILED PROBLEM DESCRIPTION

BACKUP command produces corrupted backup file in certain cases. This is due to a bug in the low level backup stream writing code (bstream library). The function bstream_write_part() in sql/backup/stream_v1_transport.c contains this code:

  /*
   To avoid copying bytes to the internal output buffer we try to cut a prefix
   of the data to be written which forms a valid fragment and write this
   fragment to output stream.

   Note: after call to biggest_fragment_prefix() blob fragment contains the
   bytes which didn't fit into the prefix.
  */
  *(s->buf.header)= biggest_fragment_prefix(&fragment);

  /*
    We use this method only if it will actually write enough of the bytes
    to be written - if it is only few bytes we save them into the output
    buffer anyway.
   */
  if (fragment.end > (s->buf.pos + MIN_WRITE_SIZE))
  {
    ...

The bug is in the condition of the if statement. We want to check if the prefix determined by biggest_fragment_prefix() is bigger than MIN_WRITE_SIZE. However, at this moment blob fragment does not describe the prefix but the remainder of the data, as in this picture:

    the prefix            remainder
  |------------|===========================|
  ^            ^                           ^
  buf.pos      fragment.begin              fragment.end

Thus the correct condition should be:

  if (fragment.begin > (s->buf.pos + MIN_WRITE_SIZE))
  {
    ...

This can be fixed trivially, however more work is needed to create good test for this problem.
[7 Jan 2009 14:44] 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/commits/62610

2744 Rafal Somla	2009-01-07
      Bug #39375 - Online backup crashes with simple combination of tables/triggers and SP
      
      This patch fixes the internal buffering logic inside bstream_write_part() function 
      (stream_v1_transport.c). Error in the logic could lead to corrupted backup image
      being written by BACKUP command. Attached test case tries to create such situation.
[8 Jan 2009 11:36] 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/commits/62675

2744 Rafal Somla	2009-01-08
      Bug #39375 - Online backup crashes with simple combination of 
                   tables/triggers and SP
      
      This patch fixes the internal buffering logic inside bstream_write_part()
      function (stream_v1_transport.c). Error in the logic could lead to 
      corrupted backup image being written by BACKUP command. Attached test 
      case tries to create such situation.
[20 Jan 2009 11:37] 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/commits/63603

2752 Rafal Somla	2009-01-20
      Bug #39375 - Online backup crashes with simple combination of 
                   tables/triggers and SP
      
      This patch fixes the internal buffering logic inside bstream_write_part()
      function (stream_v1_transport.c). Error in the logic could lead to 
      corrupted backup image being written by BACKUP command. Attached test 
      case tries to create such situation.
[20 Jan 2009 11:41] Rafal Somla
Pushed into mysql-6.0-backup tree.
[2 Feb 2009 16:07] Bugs System
Pushed into 6.0.10-alpha (revid:sergefp@mysql.com-20090202090240-dlkxhmc1asrar5rl) (version source revid:sergefp@mysql.com-20090129100938-qvke7a9krg24l8pl) (merge vers: 6.0.10-alpha) (pib:6)
[11 Feb 2009 3:26] Paul DuBois
Noted in 6.0.10 changelog.

The internal buffering logic for BACKUP DATABASE had a problem that
could lead to corrupt backup images.