Bug #20929 BINLOG command causes invalid free
Submitted: 9 Jul 2006 14:17 Modified: 26 Feb 2007 9:58
Reporter: Guilhem Bichot Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1-bk OS:Linux (linux)
Assigned to: Rafal Somla CPU Architecture:Any

[9 Jul 2006 14:17] Guilhem Bichot
Description:
NOTE that I originally had to use "mysqlbinlog --base64-output" to workaround BUG#11312 "DELIMITER is not written to the binary log that causes
syntax error", so don't you say that --base64-output is something marginal, because it's currently the only way in 5.1 to be able to restore a stored routine (if it didn't break like below).

The code tests thd->slave_thread in several places, mostly for this:
for a normal client connection it's ok to free() the thd->db; for a slave thread it is NOT because this thd->db is part of a bigger buffer allocated by Query_log_event::exec_event().
Now in 5.1, a the client connection can issue the BINLOG command which will create a binlog event in memory and pass it to Query_log_event::exec_event().
So if the binlog contains a DROP DATABASE, and we execute mysqlbinlog
with the --base64-output option, and pipe it into a "mysql" client, we get in the server:
==15085== Invalid free() / delete / delete[]
==15085==    at 0x4905785: free (vg_replace_malloc.c:233)
==15085==    by 0xB1919F: my_no_flags_free (my_malloc.c:60)
==15085==    by 0x7BBEBE: mysql_rm_db(THD*, char*, bool, bool) (sql_db.cc:932)
==15085==    by 0x66A8F9: mysql_execute_command(THD*) (sql_parse.cc:3723)
==15085==    by 0x66FBFE: mysql_parse(THD*, char*, unsigned) (sql_parse.cc:6045)
==15085==    by 0x707076: Query_log_event::exec_event(st_relay_log_info*, char const*, unsigned) (log_event.cc:1805)
==15085==    by 0x707505: Query_log_event::exec_event(st_relay_log_info*) (log_event.cc:1686)
==15085==    by 0x85895D: mysql_client_binlog_statement(THD*) (sql_binlog.cc:109)
==15085==    by 0x66F896: mysql_execute_command(THD*) (sql_parse.cc:5135)
==15085==    by 0x66FBFE: mysql_parse(THD*, char*, unsigned) (sql_parse.cc:6045)
==15085==    by 0x6707A2: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1796)
==15085==    by 0x671F1A: do_command(THD*) (sql_parse.cc:1582)
==15085==    by 0x672335: handle_one_connection (sql_parse.cc:1222)
==15085==    by 0x320070697B: start_thread (in /lib64/libpthread-2.3.5.so)
==15085==    by 0x31FFAC9C2D: clone (in /lib64/libc-2.3.5.so)
==15085==  Address 0x58A09FC is 4 bytes inside a block of size 126 alloc'd
==15085==    at 0x4904B05: malloc (vg_replace_malloc.c:149)
==15085==    by 0xB1905C: my_malloc (my_malloc.c:35)
==15085==    by 0x705F86: Query_log_event::Query_log_event(char const*, unsigned, Format_description_log_event const*, Log_e
vent_type) (log_event.cc:1492)
==15085==    by 0x713058: Log_event::read_log_event(char const*, unsigned, char const**, Format_description_log_event const*
) (log_event.cc:852)
==15085==    by 0x858892: mysql_client_binlog_statement(THD*) (sql_binlog.cc:92)
==15085==    by 0x66F896: mysql_execute_command(THD*) (sql_parse.cc:5135)
==15085==    by 0x66FBFE: mysql_parse(THD*, char*, unsigned) (sql_parse.cc:6045)

For queries which manipulate times (like NOW()) we can see:
mysqld: tztime.cc:2294: Time_zone* my_tz_find_with_opening_tz_tables(THD*, const String*): Assertion `thd->slave_thread' fai
led.

How to repeat:
Run mysqld in Valgrind;
RESET MASTER;
CREATE DATABASE mydb;
USE mydb;
CREATE TABLE t (a DATETIME);
INSERT INTO t VALUES(NOW()); # will later cause assert
DROP DATABASE mydb; # will later cause invalid free
mysqlbinlog --base64-output the_binlog | mysql
[6 Nov 2006 13:57] Lars Thalmann
We think this is fixed by the patch for BUG#19459, so good
if this bug is re-verified.  I've set it to "open".
[30 Dec 2006 13:35] Valeriy Kravchuk
Sorry, but I was not able to repeat the behaviour described with 5.1.15-Bk built --with-valgrind. I've got the following:

openxs@suse:~/dbs/5.1> bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 6
Server version: 5.1.15-beta-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> reset master;
Query OK, 0 rows affected (0.02 sec)

mysql> CREATE DATABASE mydb;
Query OK, 1 row affected (0.00 sec)

mysql> USE mydb;
Database changed
mysql> CREATE TABLE t (a DATETIME);
Query OK, 0 rows affected (0.01 sec)

mysql> INSERT INTO t VALUES(NOW());
Query OK, 1 row affected (0.00 sec)

mysql> DROP DATABASE mydb;
Query OK, 1 row affected (0.01 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.1> bin/mysqlbinlog --base64-output var/suse-bin.000001 | bi
n/mysql -uroot
ERROR 1064 (42000) at line 9: You have an error in your SQL syntax; check the ma
nual that corresponds to your MySQL server version for the right syntax to use n
ear 'AG15ZGIAQ1JFQVRFIERBVEFCQVNFIG15ZGI=
';
# at 185
#61230 13:8:30 server id 1  end' at line 1

Looks like I missed something. Please, explain steps to repeat in more details.
[5 Jan 2007 10:10] Guilhem Bichot
Now I get the same as Valeriy (syntax error).
So, I guess the syntax error must be fixed, and then we can search for the valgrind errors again.

[DEL 12:04 ~ $] /m/mysql-5.1-clean/client/mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.15-beta-valgrind-max-debug-log Source distribution

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> RESET MASTER;
Query OK, 0 rows affected (0.06 sec)

mysql> CREATE DATABASE mydb;
Query OK, 1 row affected (0.10 sec)

mysql> USE mydb;
Database changed
mysql> CREATE TABLE t (a DATETIME);
Query OK, 0 rows affected (0.41 sec)

mysql> INSERT INTO t VALUES(NOW()); # will later cause assert
Query OK, 1 row affected (0.19 sec)

mysql> DROP DATABASE mydb; # will later cause invalid free
Query OK, 1 row affected (0.33 sec)

mysql> show master status;
+---------------------+----------+--------------+------------------+
| File                | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+---------------------+----------+--------------+------------------+
| gbichot3-bin.000001 |      454 |              |                  |
+---------------------+----------+--------------+------------------+
1 row in set (0.04 sec)

mysql> Bye
[DEL 12:05 ~ $] /m/mysql-5.1/client/mysqlbinlog --base64-output /m/data/5/1/gbichot3-bin.000001| mysql
-bash: mysql: command not found
-bash: /m/mysql-5.1/client/mysqlbinlog: No such file or directory
[DEL 12:07 ~ $] /m/mysql-5.1-clean/client/mysqlbinlog --base64-output /m/data/5/1/gbichot3-bin.000001| /m/mysql-5.1-clean/client/mysql
ERROR 1064 (42000) at line 9: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'AG15ZGIAQ1JFQVRFIERBVEFCQVNFIG15ZGI=
';
# at 185
#715 12:4:38 server id 1  end_l' at line 1
[DEL 12:07 ~ $]
[24 Jan 2007 20:14] Guilhem Bichot
The syntax error is due to the fact that the BINLOG keyword is not printed anymore in the mysqlbinlog dump; we get only base64 codes. No wonder it's a syntax error.
It's not seen in the testsuite because the "mysqlbinlog_base64" test only tests the --hexdump option, not the --base64-output option, in spite of its name.
The reason why BINLOG disappeared is that, for example for Query_log_event, this is called:
static int
write_event_header_and_base64(Log_event *ev, FILE *result_file,
                              PRINT_EVENT_INFO *print_event_info)
which calls ev->print_header() and ev->print_base64() with the same IO_CACHE in argument. First print_header() runs and prints comments (#...) into the IO_CACHE. So when ev->print_base64() executes, the IO_CACHE is not empty, so this code:
  if (my_b_tell(file) == 0)
    my_b_printf(file, "\nBINLOG '\n");
has the effect that "BINLOG" is not printed.
A (quick?) fix is using the two available separate IO_CACHEs:
--- 1.141/client/mysqlbinlog.cc 2007-01-24 22:10:33 +01:00
+++ edited/../client/mysqlbinlog.cc     2007-01-24 21:53:57 +01:00
@@ -485,21 +485,20 @@ static int
 write_event_header_and_base64(Log_event *ev, FILE *result_file,
                               PRINT_EVENT_INFO *print_event_info)
 {
+  IO_CACHE *head= &print_event_info->head_cache;
+  IO_CACHE *body= &print_event_info->body_cache;
   DBUG_ENTER("write_event_header_and_base64");
   /* Write header and base64 output to cache */
-  IO_CACHE result_cache;
-  if (init_io_cache(&result_cache, -1, 0, WRITE_CACHE, 0L, FALSE,
-                    MYF(MY_WME | MY_NABP)))
-  {
-    return 1;
-  }

-  ev->print_header(&result_cache, print_event_info, FALSE);
-  ev->print_base64(&result_cache, print_event_info, FALSE);
+  ev->print_header(head, print_event_info, FALSE);
+  ev->print_base64(body, print_event_info, FALSE);

   /* Read data from cache and write to result file */
-  my_b_copy_to_file(&result_cache, result_file);
-  end_io_cache(&result_cache);
+  my_b_copy_to_file(head, result_file);
+  my_b_copy_to_file(body, result_file);
+  reinit_io_cache(head, WRITE_CACHE, 0, FALSE, TRUE);
+  reinit_io_cache(body, WRITE_CACHE, 0, FALSE, TRUE);
+
   DBUG_RETURN(0);
 }                    

And after that, the BINLOG word is printed again, no syntax error.
Then I observe again the problems originally the subject of this bug report: Valgrind errors and assertion failure.
[8 Feb 2007 19:15] Rafal Somla
I'm using mysqlbinlog ver. 3.1 and the --base64-output option works fine.
[8 Feb 2007 19:28] Rafal Somla
The part concerning failed assertion is probably a separate problem and is now reported as BUG#26193. From now on this bug is only about invalid free of thd->db.
[14 Feb 2007 10:11] Rafal Somla
I couldn't reproduce this problem in our 5.1-new-rpl tree (5.1.15). Instead, I got a different valgrind complaint reported as BUG#26361.
[26 Feb 2007 9:50] Rafal Somla
Apparently, the issue of this bug is already fixed in the current tree. I have checked how the tree looked in July 2006 when the bug was reported. This is the suspected fragment in Query_log_event::exec_event():

  thd->db_length= db_len;
  thd->db= (char *) rpl_filter->get_rewrite_db(db, &thd->db_length);

In the current tree the same fragment looks like this:

  new_db.length= db_len;
  new_db.str= (char *) rpl_filter->get_rewrite_db(db, &new_db.length);
  thd->set_db(new_db.str, new_db.length);       /* allocates a copy of 'db' */

which should be ok with respect to memory allocation/deallocation.
[26 Feb 2007 9:58] Lars Thalmann
Rafal says he can't repeat it.