MySQL Bugs: #103603: heap use after free

Bug #103603	heap use after free
Submitted:	6 May 2021 8:25	Modified:	21 May 2021 12:34
Reporter:	lieyia --	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	5.7.x;8.0.x	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	blackhole, core

Description:
    When I execute an insert... on duplicate statement, I ran into a situation where dangling pointers were used, which led to the core.
 
The stack is as follows:

/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xedd3cb]
/usr/sbin/mysqld(handle_fatal_signal+0x463)[0x7b5133]
/lib64/libpthread.so.0(+0xf5f0)[0x7f04336d85f0]
/lib64/libc.so.6(+0x154a35)[0x7f04318f4a35]
/usr/sbin/mysqld(_ZN10Field_blob4packEPhPKhjb+0xa4)[0x7f6024]
/usr/sbin/mysqld(_Z8pack_rowP5TABLEPK9st_bitmapPhPKh+0x124)[0xe817e4]
/usr/sbin/mysqld(_ZN3THD17binlog_update_rowEP5TABLEbPKhS3_S3_+0x9b) [0xe7289b]
/usr/sbin/mysqld(_ZN21Update_rows_log_event27binlog_row_logging_functionEP3THDP5TABLEbPKhS5_+0xf)[0x82276f]
/usr/sbin/mysqld(_Z14binlog_log_rowP5TABLEPKhS2_PFbP3THDS0_bS2_S2_E+0x29c)[0x81f69c]
/usr/sbin/mysqld(_ZN7handler13ha_update_rowEPKhPh+0x15a)[0x81fd9a]
/usr/sbin/mysqld(_ZN21Update_rows_log_event11do_exec_rowEPK14Relay_log_info+0xbe)[0xe48cee]
/usr/sbin/mysqld(_ZN14Rows_log_event12do_apply_rowEPK14Relay_log_info+0x26)[0xe43ce6]
/usr/sbin/mysqld(_ZN14Rows_log_event24do_index_scan_and_updateEPK14Relay_log_info+0x24c)[0xe5492c]
/usr/sbin/mysqld(_ZN14Rows_log_event14do_apply_eventEPK14Relay_log_info+0x99e)[0xe53f5e]
/usr/sbin/mysqld(_Z27slave_worker_exec_job_groupP12Slave_workerP14Relay_log_info+0x2aa)[0xeb55aa]
/usr/sbin/mysqld(handle_slave_worker+0x33b)[0xe96afb]
/usr/sbin/mysqld(pfs_spawn_thread+0x157)[0xefa177]
/lib64/libpthread.so.0(+0x7e65)[0x7f04336d0e65]
/lib64/libc.so.6(clone+0x6d)[0x7f043189e88d]

How to repeat:

The problem occurred online, we cannot reproduce it offline. And we analyzed the relevant code and used the AddressSanitizer tool to confirm that the memory which has been released been used again.

=================================================================
==323531==ERROR: AddressSanitizer: heap-use-after-free on address 0x7f8522124820 at pc 0x7f85f37ef827 bp 0x7f8528c5c3a0 sp 0x7f8528c5bb48
READ of size 6320181 at 0x7f8522124820 thread T51
    #0 0x7f85f37ef826  (/lib64/libasan.so.5+0x3f826)
    #1 0x97f219 in memcpy /usr/include/bits/string3.h:52
    #2 0x97f219 in Field_blob::pack(unsigned char*, unsigned char const*, unsigned int, bool) /home/liyawei09/dev/git/mysql/sql/field.cc:8584
    #3 0x23e8d19 in pack_row(TABLE*, st_bitmap const*, unsigned char*, unsigned char const*) /home/liyawei09/dev/git/mysql/sql/rpl_record.cc:115
    #4 0x23b974d in THD::binlog_update_row(TABLE*, bool, unsigned char const*, unsigned char const*, unsigned char const*) /home/liyawei09/dev/git/mysql/sql/binlog.cc:11637
    #5 0xa175fe in Update_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*) /home/liyawei09/dev/git/mysql/sql/log_event.h:3529
    #6 0xa0d425 in binlog_log_row(TABLE*, unsigned char const*, unsigned char const*, bool (*)(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)) /home/liyawei09/dev/git/mysql/sql/handler.cc:7937
    #7 0xa0ed30 in handler::ha_update_row(unsigned char const*, unsigned char*) /home/liyawei09/dev/git/mysql/sql/handler.cc:8109
    #8 0x23346a5 in Update_rows_log_event::do_exec_row(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:13033
    #9 0x23346a5 in Update_rows_log_event::do_exec_row(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:13001
    #10 0x2326bfd in Rows_log_event::do_apply_row(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:10112
    #11 0x23610b0 in Rows_log_event::do_index_scan_and_update(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:10501
    #12 0x235ed13 in Rows_log_event::do_apply_event(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:11280
    #13 0x248b558 in slave_worker_exec_job_group(Slave_worker*, Relay_log_info*) /home/liyawei09/dev/git/mysql/sql/rpl_rli_pdb.cc:2666
    #14 0x242d33a in handle_slave_worker /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:6207
    #15 0x254f208 in pfs_spawn_thread /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2190
    #16 0x7f85f359be64 in start_thread (/lib64/libpthread.so.0+0x7e64)
    #17 0x7f85f1e3e88c in clone (/lib64/libc.so.6+0xfe88c)

0x7f8522124820 is located 32 bytes inside of 25280760-byte region [0x7f8522124800,0x7f85239408f8)
freed by thread T51 here:
    #0 0x7f85f389db30 in __interceptor_free (/lib64/libasan.so.5+0xedb30)
    #1 0x205646a in String::mem_free() /home/liyawei09/dev/git/mysql/include/sql_string.h:337
    #2 0x205646a in String::real_alloc(unsigned long) /home/liyawei09/dev/git/mysql/sql-common/sql_string.cc:49
    #3 0x99313e in String::alloc(unsigned long) /home/liyawei09/dev/git/mysql/include/sql_string.h:347
    #4 0x99313e in Field_blob::store_internal(char const*, unsigned long, charset_info_st const*) /home/liyawei09/dev/git/mysql/sql/field.cc:8220
    #5 0x97fee5 in Field_blob::unpack(unsigned char*, unsigned char const*, unsigned int, bool) /home/liyawei09/dev/git/mysql/sql/field.cc:8622
    #6 0x23e9a8b in unpack_row(Relay_log_info const*, TABLE*, unsigned int, unsigned char const*, st_bitmap const*, unsigned char const**, unsigned long*, unsigned char const*) /home/liyawei09/dev/git/mysql/sql/rpl_record.cc:366
    #7 0x233460f in Rows_log_event::unpack_current_row(Relay_log_info const*, st_bitmap const*) /home/liyawei09/dev/git/mysql/sql/log_event.h:3149
    #8 0x233460f in Update_rows_log_event::do_exec_row(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:13033
    #9 0x2326bfd in Rows_log_event::do_apply_row(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:10112
    #10 0x23610b0 in Rows_log_event::do_index_scan_and_update(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:10501
    #11 0x235ed13 in Rows_log_event::do_apply_event(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:11280
    #12 0x248b558 in slave_worker_exec_job_group(Slave_worker*, Relay_log_info*) /home/liyawei09/dev/git/mysql/sql/rpl_rli_pdb.cc:2666
    #13 0x242d33a in handle_slave_worker /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:6207
    #14 0x254f208 in pfs_spawn_thread /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2190
    #15 0x7f85f359be64 in start_thread (/lib64/libpthread.so.0+0x7e64)

previously allocated by thread T51 here:
    #0 0x7f85f389def0 in malloc (/lib64/libasan.so.5+0xedef0)
    #1 0x24e7c4f in my_malloc /home/liyawei09/dev/git/mysql/mysys/my_malloc.c:191
    #2 0x20563b3 in String::real_alloc(unsigned long) /home/liyawei09/dev/git/mysql/sql-common/sql_string.cc:49
    #3 0x99313e in String::alloc(unsigned long) /home/liyawei09/dev/git/mysql/include/sql_string.h:347
    #4 0x99313e in Field_blob::store_internal(char const*, unsigned long, charset_info_st const*) /home/liyawei09/dev/git/mysql/sql/field.cc:8220
    #5 0x97fee5 in Field_blob::unpack(unsigned char*, unsigned char const*, unsigned int, bool) /home/liyawei09/dev/git/mysql/sql/field.cc:8622
    #6 0x23e9a8b in unpack_row(Relay_log_info const*, TABLE*, unsigned int, unsigned char const*, st_bitmap const*, unsigned char const**, unsigned long*, unsigned char const*) /home/liyawei09/dev/git/mysql/sql/rpl_record.cc:366
    #7 0x2360d9f in Rows_log_event::unpack_current_row(Relay_log_info const*, st_bitmap const*) /home/liyawei09/dev/git/mysql/sql/log_event.h:3149
    #8 0x2360d9f in Rows_log_event::do_index_scan_and_update(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:10334
    #9 0x235ed13 in Rows_log_event::do_apply_event(Relay_log_info const*) /home/liyawei09/dev/git/mysql/sql/log_event.cc:11280
    #10 0x248b558 in slave_worker_exec_job_group(Slave_worker*, Relay_log_info*) /home/liyawei09/dev/git/mysql/sql/rpl_rli_pdb.cc:2666
    #11 0x242d33a in handle_slave_worker /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:6207
    #12 0x254f208 in pfs_spawn_thread /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2190
    #13 0x7f85f359be64 in start_thread (/lib64/libpthread.so.0+0x7e64)

Thread T51 created by T50 here:
    #0 0x7f85f38019af in pthread_create (/lib64/libasan.so.5+0x519af)
    #1 0x254f475 in pfs_spawn_thread_v1 /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2241
    #2 0x2430dc3 in inline_mysql_thread_create /home/liyawei09/dev/git/mysql/include/mysql/psi/mysql_thread.h:1297
    #3 0x2430dc3 in slave_start_single_worker(Relay_log_info*, unsigned long) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:6994
    #4 0x2432954 in slave_start_workers(Relay_log_info*, unsigned long, bool*) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:7103
    #5 0x244b79c in handle_slave_sql /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:7407
    #6 0x254f208 in pfs_spawn_thread /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2190
    #7 0x7f85f359be64 in start_thread (/lib64/libpthread.so.0+0x7e64)

Thread T50 created by T47 here:
    #0 0x7f85f38019af in pthread_create (/lib64/libasan.so.5+0x519af)
    #1 0x254f475 in pfs_spawn_thread_v1 /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2241
    #2 0x241d987 in inline_mysql_thread_create /home/liyawei09/dev/git/mysql/include/mysql/psi/mysql_thread.h:1297
    #3 0x241d987 in start_slave_thread(unsigned int, void* (*)(void*), st_mysql_mutex*, st_mysql_mutex*, st_mysql_cond*, unsigned int volatile*, unsigned long volatile*, Master_info*) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:1918
    #4 0x2455062 in start_slave_threads(bool, bool, Master_info*, int) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:2042
    #5 0x2455773 in start_slave(THD*, struct_slave_connection*, st_lex_master_info*, int, Master_info*, bool) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:10159
    #6 0x2457962 in start_slave(THD*) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:537
    #7 0x245835b in start_slave_cmd(THD*) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:688
    #8 0x1da2961 in mysql_execute_command(THD*, bool) /home/liyawei09/dev/git/mysql/sql/sql_parse.cc:3442
    #9 0x1db7e0c in mysql_parse(THD*, Parser_state*, bool) /home/liyawei09/dev/git/mysql/sql/sql_parse.cc:5570
    #10 0x1dba128 in dispatch_command(THD*, COM_DATA const*, enum_server_command) /home/liyawei09/dev/git/mysql/sql/sql_parse.cc:1484
    #11 0x1dbf4a1 in do_command(THD*) /home/liyawei09/dev/git/mysql/sql/sql_parse.cc:1025
    #12 0x205c9df in handle_connection /home/liyawei09/dev/git/mysql/sql/conn_handler/connection_handler_per_thread.cc:306
    #13 0x254f208 in pfs_spawn_thread /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2190
    #14 0x7f85f359be64 in start_thread (/lib64/libpthread.so.0+0x7e64)

Thread T47 created by T0 here:
    #0 0x7f85f38019af in pthread_create (/lib64/libasan.so.5+0x519af)
    #1 0x254f475 in pfs_spawn_thread_v1 /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2241
    #2 0x205db4b in inline_mysql_thread_create /home/liyawei09/dev/git/mysql/include/mysql/psi/mysql_thread.h:1297
    #3 0x205db4b in Per_thread_connection_handler::add_connection(Channel_info*) /home/liyawei09/dev/git/mysql/sql/conn_handler/connection_handler_per_thread.cc:410
    #4 0x952589 in Connection_handler_manager::process_new_connection(Channel_info*) /home/liyawei09/dev/git/mysql/sql/conn_handler/connection_handler_manager.cc:268
    #5 0x8ab79e in Connection_acceptor<Mysqld_socket_listener>::connection_event_loop() /home/liyawei09/dev/git/mysql/sql/conn_handler/connection_acceptor.h:68
    #6 0x8ab79e in mysqld_main(int, char**) /home/liyawei09/dev/git/mysql/sql/mysqld.cc:5149
    #7 0x7f85f1d62504 in __libc_start_main (/lib64/libc.so.6+0x22504)

SUMMARY: AddressSanitizer: heap-use-after-free (/lib64/libasan.so.5+0x3f826)
Shadow bytes around the buggy address:
  0x0ff12441c8b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0ff12441c8c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0ff12441c8d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0ff12441c8e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0ff12441c8f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
=>0x0ff12441c900: fd fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd
  0x0ff12441c910: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0ff12441c920: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0ff12441c930: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0ff12441c940: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0ff12441c950: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
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
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  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
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==323531==ABORTING

Thread T51 created by T50 here:
    #0 0x7f85f38019af in pthread_create (/lib64/libasan.so.5+0x519af)
    #1 0x254f475 in pfs_spawn_thread_v1 /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2241
    #2 0x2430dc3 in inline_mysql_thread_create /home/liyawei09/dev/git/mysql/include/mysql/psi/mysql_thread.h:1297
    #3 0x2430dc3 in slave_start_single_worker(Relay_log_info*, unsigned long) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:6868
    #4 0x2432954 in slave_start_workers(Relay_log_info*, unsigned long, bool*) /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:6977
    #5 0x244b79c in handle_slave_sql /home/liyawei09/dev/git/mysql/sql/rpl_slave.cc:7281
    #6 0x254f208 in pfs_spawn_thread /home/liyawei09/dev/git/mysql/storage/perfschema/pfs.cc:2190
    #7 0x7f85f359be64 in start_thread (/lib64/libpthread.so.0+0x7e64)

Hi Mr --,

Thank you for your bug report.

However, we need more feedback from you.

First of all, download our latest release, 8.0.24 and try if you get the same problem with it. Please, do use our binary only, because, if we are not able to repeat the behaviour, we will not be able to verify this report as a bug.

Second, if you do have a problem, send us a repeatable test case. It should include a statement that caused a crash, together with all tables, with their contents. We require all this in order to repeat your problem.

We are waiting on your feedback.

This problem occurs on the blackhole engine, not on innodb.

The second 'insert duplicate update sql' produces a incorrect gtid info in binlog where the old value of content is the same as new value which is 'repeat(testcom.apigw.grocery.default, 11000)', however it should be 'repeat(com.apigw.grocery.default, 10000)'.
 
reproduce:
CREATE TABLE `appkey_document` (
  `id` int(11) NOT NULL AUTO_INCREMENT COMMENT 'auto increase key',
  `app_key` varchar(64) NOT NULL,
  `commit_id` varchar(200) NOT NULL DEFAULT '-1',
  `branch_name` varchar(200) DEFAULT NULL,
  `codeAddress` varchar(500) DEFAULT NULL,
  `content` longtext CHARACTER SET utf8mb4 COLLATE utf8mb4_unicode_ci,
  `launcher_mis` varchar(50) DEFAULT NULL,
  `updateTime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `last_score` double DEFAULT '0',
  PRIMARY KEY (`id`),
  UNIQUE KEY `idx_app_key_commit_id` (`app_key`,`commit_id`),
  KEY `idx_app_key` (`app_key`),
  KEY `idx_commit_id` (`commit_id`),
  KEY `idx_updatetime` (`updateTime`),
  KEY `idx_apk_uptime` (`app_key`,`updateTime`)
) ENGINE=BLACKHOLE DEFAULT CHARSET=utf8

mysql -h 127.0.0.1 -uroot -P3006 test -Bse"delete from test.appkey_document"
mysql -h 127.0.0.1 -uroot -P3006 test -Bse"insert into appkey_document (app_key, commit_id, branch_name, codeAddress, content, launcher_mis) values('com.apigw.grocery.default', '12634e708a76113fdf29169bd08251fca606b103', null, null, repeat('com.apigw.grocery.default', 10000), null) ON DUPLICATE KEY UPDATE branch_name  = VALUES(branch_name),codeAddress  = VALUES(codeAddress),content      = VALUES(content),launcher_mis = VALUES(launcher_mis)"

mysql -h 127.0.0.1 -uroot -P5002 test -Bse"insert into appkey_document (app_key, commit_id, branch_name, codeAddress, content, launcher_mis) values('com.apigw.grocery.default', '12634e708a76113fdf29169bd08251fca606b103', 'lyw', null, repeat('testcom.apigw.grocery.default', 11000), null) ON DUPLICATE KEY UPDATE branch_name  = VALUES(branch_name),codeAddress  = VALUES(codeAddress),content      = VALUES(content),launcher_mis = VALUES(launcher_mis)"

Hi,

Since this is about Blackhole SE, we need two infos from you.

First, please try if it works with our latest 8.0.24 binary.

Second, we need to know the format that you use for the binary log and whether it is in table or in a file.

Now, the most important question for you ...... Since Blackhole SE does not store nor changes or deletes any rows in the table, why does it matter what are the old data, when these data have never ever been stored in the table ,  at all !!!!!!! In short, how can we fetch old data, when they never existed ????

We are waiting on your feedback.

I am so sorry for missing important information.
First, It is a master-salve architecture, and the sql is executed on master, the table on master is innodb SE , on slave is blackhole SE.

Second,binlog-format on master and slave are both ROW.

Third, I found the cause of the problem may be not implement the interface of "ha_blackhole::position" .

Rows_log_event::do_index_scan_and_update(Relay_log_info const *rli)
error= m_table->file->rnd_pos_by_record(m_table->record[0])
position(record)

Hi,

I have tested your test case with our 8.0.24 binary and could not repeat the problem with pointers.

Regarding Blackhole, it works exactly as it should. Our Reference Manual contains all descriptions, including the reason why this SE can be used only on the last slave in the hierarchy.

Can't repeat.