Bug #39224 Mysql server crash, if backup to specific location by giving full pathname.
Submitted: 3 Sep 2008 20:24 Modified: 20 Oct 2008 8:35
Reporter: Hema Sridharan Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Backup Severity:S2 (Serious)
Version:mysql-6.0-backup OS:Linux
Assigned to: Jørgen Løland CPU Architecture:Any
Tags: regression

[3 Sep 2008 20:24] Hema Sridharan
Description:
1)Create database and tables.
2)Backup database to backupdir or datadir(eg: backup database time to 'time.bak'), the operation is successful.
3)Backup database to specific location by giving full path name (say '/tmp/time.bak') results in mysql server crash. 

Note: Even if we give full path name for backupdir, results in server crash.
eg: backup database time to '/data0/mysqlp/mysql-test/var/master-data/time1.bak';

create database time;
use time;
create table t1 (ts timestamp);
insert into t1 values ('2003-10-25 22:00:00'),('2003-10-25 23:00:00');
backup database time to 'time.bak';
backup database time to '/tmp/time.bak';

How to repeat:
mysql> create database time;
Query OK, 1 row affected (0.00 sec)

mysql> 
Database changed
mysql> create table t1 (ts timestamp);
Query OK, 0 rows affected (0.00 sec)

mysql>  insert into t1 values ('2003-10-25 22:00:00'),('2003-10-25 23:00:00');
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> backup database time to 'time.bak';
+-----------+
| backup_id |
+-----------+
| 252       |
+-----------+
1 row in set (0.57 sec)

mysql> backup database time to '/tmp/time.bak';
ERROR 2013 (HY000): Lost connection to MySQL server during query

STACK TRACE
===========

080903 22:44:04 [Note] Backup: Starting backup process
Error: Memory allocated at sql_string.cc:52 was overrun, discovered at 'my_alloc.c:201'
/data0/mysqlp/libexec/mysqld(my_print_stacktrace+0x2f)[0xcfa39b]
/data0/mysqlp/libexec/mysqld(handle_segfault+0x26f)[0x6f6c3d]
/lib64/tls/libpthread.so.0[0x3d6a30c430]
/lib64/tls/libc.so.6(strlen+0x10)[0x3d69a70540]
/lib64/tls/libc.so.6(_IO_vfprintf+0x350b)[0x3d69a42a0b]
/lib64/tls/libc.so.6(fprintf+0x86)[0x3d69a480b6]
/data0/mysqlp/libexec/mysqld[0xcde7a1]
/data0/mysqlp/libexec/mysqld(_sanity+0x6d)[0xcde95b]
/data0/mysqlp/libexec/mysqld(_mymalloc+0x69)[0xcddb85]
/data0/mysqlp/libexec/mysqld(alloc_root+0x1bd)[0xcdd255]
/data0/mysqlp/libexec/mysqld(strmake_root+0x24)[0xcddaa5]
/data0/mysqlp/libexec/mysqld(strdup_root+0x29)[0xcdda7f]
/data0/mysqlp/libexec/mysqld(_ZN11MYSQL_ERROR7set_msgEP3THDPKc+0x2d)[0x7ada09]
/data0/mysqlp/libexec/mysqld(_ZN11MYSQL_ERRORC1EP3THDjNS_18enum_warning_levelEPKc+0x4e)[0x7ae2a2]
/data0/mysqlp/libexec/mysqld(_ZN6backup6Logger13write_messageENS_9log_level5valueEiPKc+0x145)[0xd9a6b5]
/data0/mysqlp/libexec/mysqld(_ZN6backup6Logger15v_write_messageENS_9log_level5valueEiPKcP13__va_list_tag+0x4c)[0xd9a93a]
/data0/mysqlp/libexec/mysqld(_ZN6backup6Logger14v_report_errorENS_9log_level5valueEiP13__va_list_tag+0x7c)[0xd9a8ec]
/data0/mysqlp/libexec/mysqld(_ZN18Backup_restore_ctx11fatal_errorEiz+0x114)[0xd8b120]
/data0/mysqlp/libexec/mysqld(_ZN18Backup_restore_ctx26report_stream_open_failureEiPK19st_mysql_lex_string+0x81)[0xd894bb]
/data0/mysqlp/libexec/mysqld(_ZN18Backup_restore_ctx18prepare_for_backupEP6String19st_mysql_lex_stringPKcb+0x16d)[0xd8830b]
/data0/mysqlp/libexec/mysqld(_Z22execute_backup_commandP3THDP6st_lexP6String+0x207)[0xd875bb]
/data0/mysqlp/libexec/mysqld(_Z21mysql_execute_commandP3THD+0x960)[0x708018]
/data0/mysqlp/libexec/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x1b7)[0x710c0f]
/data0/mysqlp/libexec/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x8cb)[0x705dfd]
/data0/mysqlp/libexec/mysqld(_Z10do_commandP3THD+0x206)[0x705340]
/data0/mysqlp/libexec/mysqld(handle_one_connection+0x128)[0x702cec]
/lib64/tls/libpthread.so.0[0x3d6a30610a]
/lib64/tls/libc.so.6(__clone+0x73)[0x3d69ac68b3]
Error: Memory allocated at 080903 22:44:04 - 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=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 = 60646 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x25a7788
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 = 0x4be941b8 thread_stack 0x40000
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x2614650 = backup database time to '/tmp/time.bak'
thd->thread_id=1
thd->killed=NOT_KILLED
[3 Sep 2008 21:09] MySQL Verification Team
Thank you for the bug report. I wasn't able to repeat with server 1 week older only with latest pull source.

mysql> insert into t1 values ('2003-10-25 22:00:00'),('2003-10-25 23:00:00');
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> backup database time to 'time.bak';
+-----------+
| backup_id |
+-----------+
| 252       | 
+-----------+
1 row in set (0.09 sec)

mysql> backup database time to '/tmp/time.bak';
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>
[4 Sep 2008 9:39] Jørgen Løland
May be duplicate of bug#39189
[4 Sep 2008 18:18] Rafal Somla
A backtrace from the crash:

> #3  <signal handler called>
> #4  0x0000003d69a70540 in strlen () from /lib64/tls/libc.so.6
> #5  0x0000003d69a42a0b in vfprintf () from /lib64/tls/libc.so.6
> #6  0x0000003d69a480b6 in fprintf () from /lib64/tls/libc.so.6
> #7  0x0000000000cde7a1 in _checkchunk (irem=0x1deb030, filename=0xf626f0 "my_alloc.c", lineno=201) at safemalloc.c:471
> #8  0x0000000000cde95b in _sanity (filename=0xf626f0 "my_alloc.c", lineno=201) at safemalloc.c:516
> #9  0x0000000000cddb85 in _mymalloc (size=1980, filename=0xf626f0 "my_alloc.c", lineno=201, MyFlags=1040) at safemalloc.c:130
> #10 0x0000000000cdd255 in alloc_root (mem_root=0x2a97427338, length=104) at my_alloc.c:201
> #11 0x0000000000cddaa5 in strmake_root (root=0x2a97427338, 
>     str=0x4788b270 "The MySQL server is running with the --secure-file-priv option so it cannot execute this statement", len=98)
>     at my_alloc.c:405
> #12 0x0000000000cdda7f in strdup_root (root=0x2a97427338, 
>     str=0x4788b270 "The MySQL server is running with the --secure-file-priv option so it cannot execute this statement")
>     at my_alloc.c:398
> #13 0x00000000007ada09 in MYSQL_ERROR::set_msg (this=0x1ddeeb8, thd=0x2a97426f78, 
>     msg_arg=0x4788b270 "The MySQL server is running with the --secure-file-priv option so it cannot execute this statement")
>     at sql_error.cc:56
> #14 0x00000000007ae2a2 in MYSQL_ERROR (this=0x1ddeeb8, thd=0x2a97426f78, code_arg=1290, 
>     level_arg=MYSQL_ERROR::WARN_LEVEL_ERROR, 
>     msg_arg=0x4788b270 "The MySQL server is running with the --secure-file-priv option so it cannot execute this statement")
>     at ../sql_error.h:31
> #15 0x0000000000d9a6b5 in backup::Logger::write_message (this=0x1dfdcf0, level=backup::log_level::ERROR, error_code=1290, 
>     msg=0x4788b270 "The MySQL server is running with the --secure-file-priv option so it cannot execute this statement")
>     at logger.cc:49
> #16 0x0000000000d9a93a in backup::Logger::v_write_message (this=0x1dfdcf0, level=backup::log_level::ERROR, error_code=1290, 
>     format=0x1dbf3fb "The MySQL server is running with the %s option so it cannot execute this statement", args=0x4788b410)
>     at logger.cc:111
> #17 0x0000000000d9a8ec in backup::Logger::v_report_error (this=0x1dfdcf0, level=backup::log_level::ERROR, error_code=1290, 
>     args=0x4788b410) at logger.cc:95
> #18 0x0000000000d8bbfe in backup::Logger::report_error (this=0x1dfdcf0, error_code=1290) at ../../sql/backup/logger.h:121
> #19 0x0000000000d9938a in backup::Stream::test_secure_file_priv_access (this=0x1dfdbb0, path=0x1deaf28 "/tmp/test.bak/")
>     at stream.cc:401
> #20 0x0000000000d993c9 in backup::Stream::open (this=0x1dfdbb0) at stream.cc:417
> #21 0x0000000000d997f4 in backup::Output_stream::open (this=0x1dfdbb0) at stream.cc:538
> #22 0x0000000000d882f2 in Backup_restore_ctx::prepare_for_backup (this=0x4788b700, backupdir=0x4788bd80, orig_loc=

The crash happens when backup code is reporting an error, because it can not open location which is outside area given wih --secure-file-priv option. It happens inside _mymalloc() function when it is performing sanity checks on safe allocator structures.

In _sanity() the following code is executed:

>   count=sf_malloc_count;
>   for (irem= sf_malloc_root; irem != NULL && count-- ; irem= irem->next)
>     flag+= _checkchunk (irem, filename, lineno);

where sf_malloc_count=404 and count=329. So irem is pointing at 329-th item in the linked list starting at sf_malloc_root. The problem is that contents of irem is invalid:

> (gdb) p *irem
> $30 = {next = 0x5a5a5a5a5a5a5a5a, prev = 0x5a5a5a5a5a5a5a5a, 
>   filename = 0x5a5a5a5a5a5a5a5a <Address 0x5a5a5a5a5a5a5a5a out of bounds>, datasize = 6510615555426900570, 
>   linenum = 1515870810, SpecialValue = 1515870810}

This leads to crash later in fprintf(). Looks like the chain of st_irem records starting from sf_malloc_root is corrupted at some point. But why this is so I have no idea right now.
[5 Sep 2008 6:15] Rafal Somla
A possible cause of the problem is a memory overrun which is detected by _mymalloc(). Since invalid memory was overwritten, data structures can be corrupted leading to the crash. If this is the case the problem should be fixed by eliminating the overrun, which could happen before the point of crash.

Some suggestions from Monty how to approach this:

> monty: Run program with sf_malloc_prehunc as a bigger number, like 512. This is he number of protection bytes
> rafal|around: monty: how do I change this number? In the code?
> monty: you can set this variable in the debugger when you start testing
> monty: other options are:
> monty: - Compile with one of the valgrind builds and run the program under valgrind.  In this case the _mmalloc code is not used
> monty: - run the program wih --debug=d:t:S:o/tmp/trace
> monty: the 'S' option will cause safemalloc to check all memory at every enter/exit function call
> monty: when it crashes, the log will show you in which function the bug is
> monty: eof
[20 Oct 2008 8:35] Jørgen Løland
Can't repeat in the current backup tree. 

This part of the code has recently been modified by multiple patches, e.g., bug#34171, bug#39189. Not sure which patch removed this bug.

Fixed in 6.0.8.