ASan errors on main.audit_log_filter_commands

[Laurynas Biveinis]

Regressed on 5.6 trunk between 7316264c7e821a8590a8ff8204e88ee73f85fa73 and 854b475e1ae93518dd897c2c9fd55ce0dfcbfe74:

main.audit_log_filter_users w1 [ fail ]
        Test ended at 2017-02-07 12:44:14

CURRENT_TEST: main.audit_log_filter_commands
mysqltest: In included file "/mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/mysql-test/t/audit_log_filter_commands_events.inc":
included from /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/mysql-test/t/audit_log_filter_commands_events.inc at line 3:
At line 3: query 'CREATE DATABASE db1 DEFAULT CHARACTER SET latin1' failed: 2013: Lost connection to MySQL server during query
...
=================================================================
==1790==ERROR: AddressSanitizer: global-buffer-overflow on address 0x00000171d166 at pc 0x7f68a3ef3720 bp 0x7f6882987040 sp 0x7f68829867e8
READ of size 18 at 0x00000171d166 thread T20
    #0 0x7f68a3ef371f in memcmp (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x7771f)
    #1 0x16a3d1b in my_strnncoll_binary (/mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/build/sql/mysqld+0x16a3d1b)
    #2 0xf72533 in hashcmp /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/mysys/hash.c:379
    #3 0xf72533 in my_hash_first_from_hash_value /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/mysys/hash.c:294
    #4 0xf72ae7 in my_hash_search /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/mysys/hash.c:235
    #5 0x7f6882253de3 in audit_log_check_command_included /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/plugin/audit_log/filter.c:366
    #6 0x7f688224b655 in audit_log_update_thd_local /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/plugin/audit_log/audit_log.c:994
    #7 0x7f688224b655 in audit_log_notify /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/plugin/audit_log/audit_log.c:1070
    #8 0x8ea765 in plugins_dispatch /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_audit.cc:455
    #9 0x8ea765 in event_class_dispatch /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_audit.cc:491
    #10 0x8ea765 in general_class_handler /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_audit.cc:90
    #11 0x8eace8 in mysql_audit_notify(THD*, unsigned int, unsigned int, ...) /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_audit.cc:217
    #12 0xa020ad in mysql_audit_general /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_audit.h:196
    #13 0xa020ad in dispatch_command(enum_server_command, THD*, char*, unsigned int) /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_parse.cc:1919
    #14 0x95bef9 in do_handle_one_connection(THD*) /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_connect.cc:1550
    #15 0x95c180 in handle_one_connection /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/sql_connect.cc:1454
    #16 0x105b2e9 in pfs_spawn_thread /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/perfschema/pfs.cc:1860
    #17 0x7f68a294e6b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
    #18 0x7f68a1ddc82c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10682c)

0x00000171d166 is located 0 bytes to the right of global variable '*.LC200' defined in '/mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc' (0x171d160) of size 6
  '*.LC200' is ascii string 'error'
0x00000171d166 is located 58 bytes to the left of global variable '*.LC205' defined in '/mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc' (0x171d1a0) of size 44
  '*.LC205' is ascii string 'Failed to create file(file: '%s', errno %d)'
SUMMARY: AddressSanitizer: global-buffer-overflow ??:0 memcmp
Shadow bytes around the buggy address:
  0x0000802db9d0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0000802db9e0: 00 00 04 f9 f9 f9 f9 f9 00 00 00 00 00 02 f9 f9
  0x0000802db9f0: f9 f9 f9 f9 00 00 00 00 00 07 f9 f9 f9 f9 f9 f9
  0x0000802dba00: 00 00 00 00 00 00 00 00 00 00 04 f9 f9 f9 f9 f9
  0x0000802dba10: 00 00 06 f9 f9 f9 f9 f9 00 00 00 00 00 00 00 00
=>0x0000802dba20: 00 00 00 00 00 00 00 f9 f9 f9 f9 f9[06]f9 f9 f9
  0x0000802dba30: f9 f9 f9 f9 00 00 00 00 00 04 f9 f9 f9 f9 f9 f9
  0x0000802dba40: 00 00 00 00 00 00 02 f9 f9 f9 f9 f9 07 f9 f9 f9
  0x0000802dba50: f9 f9 f9 f9 04 f9 f9 f9 f9 f9 f9 f9 00 00 f9 f9
  0x0000802dba60: f9 f9 f9 f9 00 00 f9 f9 f9 f9 f9 f9 03 f9 f9 f9
  0x0000802dba70: f9 f9 f9 f9 00 00 00 00 01 f9 f9 f9 f9 f9 f9 f9
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 T20 created by T0 here:
    #0 0x7f68a3eb2253 in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x36253)
    #1 0x1064d71 in spawn_thread_v1 /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/storage/perfschema/pfs.cc:1910
    #2 0x5e8c05 in inline_mysql_thread_create /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/include/mysql/psi/mysql_thread.h:1252
    #3 0x5e8c05 in create_thread_to_handle_connection(THD*) /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:6502
    #4 0x5e40e1 in create_new_thread /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:6610
    #5 0x5e40e1 in handle_connections_sockets() /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:6900
    #6 0x5f5497 in mysqld_main(int, char**) /mnt/workspace/percona-server-5.6-asan-param/BUILD_TYPE/release-asan/Host/ubuntu-xenial-64bit/sql/mysqld.cc:6112
    #7 0x7f68a1cf682f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)

==1790==ABORTING

[Laurynas Biveinis (laurynas-biveinis)]

Likely a regression from bug 1650321 fix

[Sergei Glushchenko (sergei.glushchenko)]

fix for bug 1650321 does not affect audit_log_filter_users

[Sergei Glushchenko (sergei.glushchenko)]

Looking at the stack trace I see

audit_log_check_command_included(name="error", length=0)

and

p event_general->general_sql_command
(MYSQL_LEX_STRING) $0 = (str = "error", length = 0)

so, it is likely core server to blame.

1. my_hash_search doesn't handle 0 length correctly
2. MYSQL_LEX_STRING contains invalid value when passed to plugin

[Laurynas Biveinis (laurynas-biveinis)]

Right, removing audit_log_filter_users mention - its error was only seen once, and was non-specific.

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/1443
https://github.com/percona/percona-server/pull/1444

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1059