Bug #83073 GCC 5 and 6 miscompile mach_parse_compressed
Submitted: 21 Sep 2016 8:57 Modified: 26 Jan 2018 4:37
Reporter: Laurynas Biveinis (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.5,5.6,5.7,8.0 OS:Any
Assigned to: Vasil Dimov CPU Architecture:Any
Tags: Contribution

[21 Sep 2016 8:57] Laurynas Biveinis 
Description:
mach_parse_compressed should load 1 to 5 bytes depending on the value of the first byte. GCC 5 and 6 emit code to load four bytes at first, before the 1st byte value is checked. Even though those bytes are not used for computation, loading them causes an out of bounds read if we are reading a short integer close to the end of buffer.

The GCC bug is https://gcc.gnu.org/bugzilla/show_bug.cgi?id=77673, you can also see a discussion leading to the bug report at http://stackoverflow.com/questions/38821284/why-is-compiler-generating-4-byte-load-instead....

How to repeat:
This presented as

innodb.innodb_bug59641                   w3 [ fail ]
        Test ended at 2016-08-03 14:46:26

CURRENT_TEST: innodb.innodb_bug59641
safe_process[13442]: Child process: 13444, killed by signal: 9

Server [mysqld.1 - pid: 13470, winpid: 13470, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
safe_process[10399]: Child process: 10401, killed by signal: 9
160803 21:46:25 [Note] /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld (mysqld 5.5.51-38.2-log) starting as process 13471 ...
160803 21:46:25 [Warning] setrlimit could not change the size of core files to 'infinity';  We may not be able to generate a core file on signals
160803 21:46:25 [Note] Plugin 'FEDERATED' is disabled.
160803 21:46:25 InnoDB: The InnoDB memory heap is disabled
160803 21:46:25 InnoDB: Mutexes and rw_locks use GCC atomic builtins
160803 21:46:25 InnoDB: Compressed tables use zlib 1.2.8
160803 21:46:25 InnoDB: Using Linux native AIO
160803 21:46:25 InnoDB: Initializing buffer pool, size = 32.0M
160803 21:46:25 InnoDB: Completed initialization of buffer pool
160803 21:46:25 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 31407366
160803 21:46:25  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 33806487
InnoDB: Transaction DFC was in the XA prepared state.
InnoDB: Transaction DFD was in the XA prepared state.
InnoDB: Transaction DFE was in the XA prepared state.
InnoDB: 3 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is F00
160803 21:46:26  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 =================================================================
==13471==ERROR: AddressSanitizer: unknown-crash on address 0x61e00000d745 at pc 0x0000011a5269 bp 0x7fc80c25da60 sp 0x7fc80c25da50
READ of size 4 at 0x61e00000d745 thread T4
    #0 0x11a5268 in mach_parse_compressed /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/mach/mach0data.c:64
    #1 0x11d45e8 in page_cur_parse_insert_rec /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/page/page0cur.c:808
    #2 0x11d5b88 in page_parse_copy_rec_list_to_created_page /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/page/page0cur.c:1583
    #3 0x118aa6c in recv_parse_or_apply_log_rec_body /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:1217
    #4 0x118f63c in recv_recover_page_func /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:1708
    #5 0x103c243 in buf_page_io_complete /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/buf/buf0buf.c:4022
    #6 0x10efc0b in fil_aio_wait /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/fil/fil0fil.c:5719
    #7 0xf4b53f in io_handler_thread /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/srv/srv0start.c:496
    #8 0x7fc8179fa6f9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76f9)
    #9 0x7fc8165a5b5c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x106b5c)

0x61e00000d748 is located 0 bytes to the right of 2760-byte region [0x61e00000cc80,0x61e00000d748)
allocated by thread T0 here:
    #0 0x7fc8180c4602 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x98602)
    #1 0x11a897c in mem_area_alloc /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/mem/mem0pool.c:381
    #2 0x11a6a86 in mem_heap_create_block /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/mem/mem0mem.c:333
    #3 0x11a6a86 in mem_heap_add_block /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/mem/mem0mem.c:452
    #4 0x118bfda in mem_heap_alloc /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/include/mem0mem.ic:186
    #5 0x118bfda in recv_add_to_hash_table /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:1477
    #6 0x118cf89 in recv_add_to_hash_table /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:1421
    #7 0x118cf89 in recv_parse_log_recs /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:2562
    #8 0x11980aa in recv_scan_log_recs /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:2874
    #9 0x11980aa in recv_group_scan_log_recs /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:2929
    #10 0x11980aa in recv_recovery_from_checkpoint_start_func /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/log/log0recv.c:3200
    #11 0xf503a6 in innobase_start_or_create_for_mysql /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/srv/srv0start.c:1933
    #12 0xe9016b in innobase_init /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/handler/ha_innodb.cc:3273
    #13 0x9a8a5b in ha_initialize_handlerton(st_plugin_int*) /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/handler.cc:577
    #14 0x6cdd76 in plugin_initialize /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_plugin.cc:1111
    #15 0x6dff5e in plugin_init(int*, char**, int) /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_plugin.cc:1400
    #16 0x5428d3 in init_server_components /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:4037
    #17 0x54d755 in mysqld_main(int, char**) /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:4772
    #18 0x7fc8164bf82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

Thread T4 created by T0 here:
    #0 0x7fc818062253 in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x36253)
    #1 0x11c8e4a in os_thread_create /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/os/os0thread.c:173
    #2 0xf4e1d3 in innobase_start_or_create_for_mysql /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/srv/srv0start.c:1630
    #3 0xe9016b in innobase_init /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/handler/ha_innodb.cc:3273
    #4 0x9a8a5b in ha_initialize_handlerton(st_plugin_int*) /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/handler.cc:577
    #5 0x6cdd76 in plugin_initialize /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_plugin.cc:1111
    #6 0x6dff5e in plugin_init(int*, char**, int) /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_plugin.cc:1400
    #7 0x5428d3 in init_server_components /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:4037
    #8 0x54d755 in mysqld_main(int, char**) /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:4772
    #9 0x7fc8164bf82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

SUMMARY: AddressSanitizer: unknown-crash /mnt/workspace/percona-server-5.5-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/innobase/mach/mach0data.c:64 mach_parse_compressed
Shadow bytes around the buggy address:
  0x0c3c7fff9a90: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c3c7fff9aa0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c3c7fff9ab0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c3c7fff9ac0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c3c7fff9ad0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
=>0x0c3c7fff9ae0: 00 00 00 00 00 00 00 00[00]fa fa fa fa fa fa fa
  0x0c3c7fff9af0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c3c7fff9b00: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c3c7fff9b10: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c3c7fff9b20: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c3c7fff9b30: 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
==13471==ABORTING
safe_process[13470]: Child process: 13471, exit: 1
----------SERVER LOG END-------------

Suggested fix:
Separating 1st byte < 0x80 case from the rest by "asm volatile("": : :"memory");" appears to be a viable workaround for the affected compilers.
[21 Sep 2016 13:53] MySQL Verification Team 
Hello Laurynas,

Thank you for the report.
I tried to reproduce this issue at my end using gcc 6.1.0 with no luck so far. Anything else required to trigger this issue other than my below steps? Please let us know.

cmake . -DBUILD_CONFIG=mysql_release -DWITH_DEBUG=ON -DWITH_ASAN=ON -DDOWNLOAD_BOOST=1 -DWITH_BOOST=./boost
make -j32
./mtr innodb.innodb_bug59641
Logging: ./mtr  innodb.innodb_bug59641
MySQL Version 8.0.0
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/export/umesh/server/source/bugs/83073/mysql-8.0.0-dmr/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
innodb.innodb_bug59641                   [ pass ]   7591
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 7.591 of 33 seconds executing testcases

Completed: All 1 tests were successful.

-- env

bin/gcc --version
gcc (GCC) 6.1.0
bin/g++ --version
g++ (GCC) 6.1.0

bin/cmake --version
cmake version 3.6.1

cat /etc/*release
Oracle Linux Server release 7.1
NAME="Oracle Linux Server"
VERSION="7.1"

Thanks,
Umesh
[21 Sep 2016 14:32] Laurynas Biveinis 
Umesh -

I saw it maybe twice at most over all our recent Jenkins and my local builds. It is a very rare occurrence. I'd suggest to verify this by disassembly analysis
[22 Sep 2016 5:58] Laurynas Biveinis 
If that helps, the linked GCC bug report has a complete standalone C program to show a crash or Valgrind/ASan error in three different ways (mmap, heap, stack). It contains a reduced version of mach_parse_compressed but it would work the same with the complete mach_parse_compressed and its dependencies pulled in.
[22 Sep 2016 7:17] Laurynas Biveinis 
Bug 83073 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: bug83073-5.5.patch (application/octet-stream, text), 1.11 KiB.
[22 Sep 2016 7:17] Laurynas Biveinis 
Bug 83073 fix for 5.6

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

Contribution: bug83073-5.6.patch (application/octet-stream, text), 950 bytes.
[22 Sep 2016 7:17] Laurynas Biveinis 
Bug 83073 fix for 5.7

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

Contribution: bug83073-5.7.patch (application/octet-stream, text), 1.02 KiB.
[22 Sep 2016 7:18] Laurynas Biveinis 
Bug 83073 fix for 8.0

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

Contribution: bug83073-8.0.patch (application/octet-stream, text), 1.02 KiB.
[22 Sep 2016 7:39] MySQL Verification Team 
Thank you Laurynas for the contribution.

Thanks,
Umesh
[27 Sep 2016 11:45] Vasil Dimov 
Hi Laurynas,

The patch is pending review and will be pushed soon.

I changed the assembly to __atomic_thread_fence(__ATOMIC_ACQUIRE); and confirm that the offending load, +45 below:

Dump of assembler code for function mach_parse_compressed:
   ...
   0x000000000000172a <+42>:	movzbl (%rdi),%ecx
   0x000000000000172d <+45>:	mov    (%rdi),%eax
   0x000000000000172f <+47>:	bswap  %eax
   0x0000000000001731 <+49>:	cmp    $0x7f,%rcx
   ...

is moved further down when the patch is applied.

Thanks!
[3 Oct 2016 19:43] Daniel Price 
Posted by developer:
 
Fixed as of the upcoming 5.5.54, 5.6.35, 5.7.17, 8.0.1 release, and here's the changelog entry:

The GCC mach_parse_compressed function should load 1 to 5 bytes depending
on the value of the first byte. Due to a GCC bug, GCC 5 and 6 emit code to
load four bytes, before the first byte value is checked (GCC Bug #77673).
A workaround prevents this behavior. 

Thanks to Laurynas Biveinis for the patch.
[26 Jan 2018 4:37] Laurynas Biveinis 
The latest point releases in all the affected GCC release series have been fixed, see bug 89427 to take this into account