Bug #81657 DBUG_PRINT in THD::decide_logging_format prints incorrectly, access out-of-bound
Submitted: 31 May 2016 11:46 Modified: 23 Sep 2016 9:24
Reporter: Laurynas Biveinis Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.5+ OS:Any
Assigned to: CPU Architecture:Any
Tags: asan, debug

[31 May 2016 11:46] Laurynas Biveinis
Description:
THD::decide_logging_format does

#ifndef DBUG_OFF
    {
      static const char *prelocked_mode_name[] = {
        "NON_PRELOCKED",
        "PRELOCKED",
        "PRELOCKED_UNDER_LOCK_TABLES",
      };
      DBUG_PRINT("debug", ("prelocked_mode: %s",
                           prelocked_mode_name[locked_tables_mode]));
    }
#endif

but the type of locked_tables_mode is

enum enum_locked_tables_mode
{
  LTM_NONE= 0,
  LTM_LOCK_TABLES,
  LTM_PRELOCKED,
  LTM_PRELOCKED_UNDER_LOCK_TABLES
};

resulting in incorrect printout and out-of-bound read if it is LTM_PRELOCKED_UNDER_LOCK_TABLES.

How to repeat:
This shows up as an ASan error on 5.5:
cmake ... -DWITH_DEBUG=ON -DWITH_ASAN=ON
...
./mtr --debug-server rpl_unsafe_statements
...
rpl.rpl_unsafe_statements 'mix'          [ fail ]
...
mysqltest: At line 54: query 'INSERT INTO t1(i) VALUES(3)' failed: 2013: Lost connection to MySQL server during query
...
=================================================================
==32732==ERROR: AddressSanitizer: global-buffer-overflow on address 0x000001a7fff8 at pc 0x0000005fc568 bp 0x7f11fccf6250 sp 0x7f11fccf6240
READ of size 8 at 0x000001a7fff8 thread T19
    #0 0x5fc567 in THD::decide_logging_format(TABLE_LIST*) /home/laurynas/mysql-server/sql/sql_class.cc:4406
    #1 0x5a5b94 in lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int) /home/laurynas/mysql-server/sql/sql_base.cc:5845
    #2 0x5bee36 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /home/laurynas/mysql-server/sql/sql_base.cc:5571
    #3 0x6324a5 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /home/laurynas/mysql-server/sql/sql_base.h:500
    #4 0x6324a5 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool) /home/laurynas/mysql-server/sql/sql_insert.cc:714
    #5 0x67025f in mysql_execute_command(THD*) /home/laurynas/mysql-server/sql/sql_parse.cc:2938
    #6 0x67be42 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/laurynas/mysql-server/sql/sql_parse.cc:5780
    #7 0x67f74a in dispatch_command(enum_server_command, THD*, char*, unsigned int) /home/laurynas/mysql-server/sql/sql_parse.cc:1038
    #8 0x683df9 in do_command(THD*) /home/laurynas/mysql-server/sql/sql_parse.cc:773
    #9 0x86c6b6 in do_handle_one_connection(THD*) /home/laurynas/mysql-server/sql/sql_connect.cc:862
    #10 0x86c8db in handle_one_connection /home/laurynas/mysql-server/sql/sql_connect.cc:781
    #11 0xd53f20 in pfs_spawn_thread /home/laurynas/mysql-server/storage/perfschema/pfs.cc:1015
    #12 0x7f12092b06f9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76f9)
    #13 0x7f120895bb5c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x106b5c)

0x000001a7fff8 is located 40 bytes to the left of global variable 'DEFAULT_WHERE' defined in '/home/laurynas/mysql-server/sql/sql_class.cc:71:20' (0x1a80020) of size 8
0x000001a7fff8 is located 0 bytes to the right of global variable 'prelocked_mode_name' defined in '/home/laurynas/mysql-server/sql/sql_class.cc:4401:26' (0x1a7ffe0) of size 24
SUMMARY: AddressSanitizer: global-buffer-overflow /home/laurynas/mysql-server/sql/sql_class.cc:4406 THD::decide_logging_format(TABLE_LIST*)
Shadow bytes around the buggy address:
  0x000080347fa0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x000080347fb0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x000080347fc0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x000080347fd0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x000080347fe0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
=>0x000080347ff0: 00 00 00 00 00 00 00 00 f9 f9 f9 f9 00 00 00[f9]
  0x000080348000: f9 f9 f9 f9 00 f9 f9 f9 f9 f9 f9 f9 00 00 00 00
  0x000080348010: 00 00 00 00 f9 f9 f9 f9 00 00 f9 f9 f9 f9 f9 f9
  0x000080348020: 00 00 f9 f9 f9 f9 f9 f9 00 00 00 00 00 00 00 00
  0x000080348030: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x000080348040: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Heap right redzone:      fb
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack partial redzone:   f4
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
Thread T19 created by T0 here:
    #0 0x7f1209b3a253 in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x36253)
    #1 0xd574dd in spawn_thread_v1 /home/laurynas/mysql-server/storage/perfschema/pfs.cc:1038
    #2 0x511e52 in inline_mysql_thread_create /home/laurynas/mysql-server/include/mysql/psi/mysql_thread.h:1049
    #3 0x511e52 in create_thread_to_handle_connection(THD*) /home/laurynas/mysql-server/sql/mysqld.cc:5070
    #4 0x51331c in create_new_thread /home/laurynas/mysql-server/sql/mysqld.cc:5162
    #5 0x51331c in handle_connections_sockets() /home/laurynas/mysql-server/sql/mysqld.cc:5424
    #6 0x51686c in mysqld_main(int, char**) /home/laurynas/mysql-server/sql/mysqld.cc:4686
    #7 0x4ff8ae in main /home/laurynas/mysql-server/sql/main.cc:25
    #8 0x7f120887582f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

==32732==ABORTING

Suggested fix:
Sync THD::decide_logging_format DBUG_PRINT with the enum
[31 May 2016 12:18] Laurynas Biveinis
Bug 81657 fix for 5.5

(*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug81657-5.5.patch (application/octet-stream, text), 613 bytes.

[1 Jun 2016 7:37] MySQL Verification Team
Hello Laurynas,

Thank you for the report and contribution.

Thanks,
Umesh
[12 Sep 2016 11:47] David Moss
Posted by developer:
 
Seems to be related to internals only, so closing without change log entry.
[13 Sep 2016 10:11] Roel Van de Paar
David, user visible consequences could have been possible.
[13 Sep 2016 10:12] Roel Van de Paar
On second thought, that may have been in debug only. Ignore me :)
[23 Sep 2016 9:24] Laurynas Biveinis
The fix is broken in 5.6, see bug 83124