[MDEV-22806] MSAN reports use-of-uninitialized-value for rpl_parallel_conflicts.test Created: 2020-06-05  Updated: 2020-06-30  Resolved: 2020-06-26

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.1.46, 10.2.33, 10.3.24, 10.4.14, 10.5.5

Type: Bug Priority: Major
Reporter: Sujatha Sivakumar (Inactive) Assignee: Sujatha Sivakumar (Inactive)
Resolution: Fixed Votes: 0
Labels: None


 Description   

To repeat:
=========
LD_LIBRARY_PATH=/bug_repo/llvm-toolchain-9-9/libc++msan/lib/ ./mtr rpl_parallel_conflicts --repeat 3

Logging: bug_repo/test-10.5-msan/mysql-test/mysql-test-run.pl  rpl_parallel_conflicts --repeat 3
vardir: /bug_repo/test-10.5-msan/bld/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/bug_repo/test-10.5-msan/bld/mysql-test/var'...
Checking supported features...
MariaDB Version 10.5.4-MariaDB-debug
 - SSL connections supported
 - binaries are debug compiled
 - binaries built with wsrep patch
Collecting tests...
Installing system database...
 
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
rpl.rpl_parallel_conflicts 'innodb,mix'  [ pass ]   4165
rpl.rpl_parallel_conflicts 'innodb,mix'  [ 2 pass ]   4391
rpl.rpl_parallel_conflicts 'innodb,mix'  [ 3 pass ]   4616
rpl.rpl_parallel_conflicts 'innodb,row'  [ fail ]
        Test ended at 2020-06-05 11:14:48
 
CURRENT_TEST: rpl.rpl_parallel_conflicts
mysqltest: In included file "./include/sync_with_master_gtid.inc": 
included from /home/sujatha/bug_repo/test-10.5-msan/mysql-test/suite/rpl/t/rpl_parallel_conflicts.test at line 203:
At line 43: query 'let $_result= `SELECT master_gtid_wait('$master_pos', $_slave_timeout)`' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
81	81
83	83
85	85
87	87
88	88
89	89
90	90
91	91
92	92
93	93
94	94
95	95
96	96
97	97
98	98
99	99
include/save_master_gtid.inc
connection server_2;
include/start_slave.inc
include/sync_with_master_gtid.inc

2020-06-05 11:14:47 5 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16000', master_log_file='master-bin.000001', master_log_pos='4'.
2020-06-05 11:14:47 7 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:16000' in log 'master-bin.000001' at position 4
2020-06-05 11:14:47 8 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
2020-06-05 11:14:47 7 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication started in log 'master-bin.000001' at position 4
2020-06-05 11:14:48 8 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 814
2020-06-05 11:14:48 7 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 814
2020-06-05 11:14:48 11 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:16000' in log 'master-bin.000001' at position 814
2020-06-05 11:14:48 11 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication started in log 'master-bin.000001' at position 814
2020-06-05 11:14:48 12 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 814, relay log './slave-relay-bin.000002' position: 1114
Uninitialized bytes in __interceptor_write at offset 57 inside [0x725000041018, 114)
Uninitialized bytes in __interceptor_write at offset 57 inside [0x725000041018, 114)
==17820==WARNING: MemorySanitizer: use-of-uninitialized-value
    #0 0x5586cf8317ec in my_write /home/sujatha/bug_repo/test-10.5-msan/mysys/my_write.c:49:19
    #1 0x5586cf75c126 in inline_mysql_file_write /home/sujatha/bug_repo/test-10.5-msan/include/mysql/psi/mysql_file.h:1166:13
    #2 0x5586cf75c126 in _my_b_cache_write /home/sujatha/bug_repo/test-10.5-msan/mysys/mf_iocache.c:1768:7
    #3 0x5586cf74fa78 in my_b_flush_io_cache /home/sujatha/bug_repo/test-10.5-msan/mysys/mf_iocache.c:1967:18
    #4 0x5586ccc37e07 in Relay_log_info::flush() /home/sujatha/bug_repo/test-10.5-msan/sql/rpl_rli.cc:2595:7
    #5 0x5586ccc40cdf in Relay_log_info::stmt_done(unsigned long long, THD*, rpl_group_info*) /home/sujatha/bug_repo/test-10.5-msan/sql/rpl_rli.cc:1476:11
    #6 0x5586cd8cd65b in Log_event::do_update_pos(rpl_group_info*) /home/sujatha/bug_repo/test-10.5-msan/sql/log_event_server.cc:628:12
    #7 0x5586cc25e1b7 in Log_event::update_pos(rpl_group_info*) /home/sujatha/bug_repo/test-10.5-msan/sql/log_event.h:1512:12
    #8 0x5586cc25e1b7 in apply_event_and_update_pos_apply(Log_event*, THD*, rpl_group_info*, int) /home/sujatha/bug_repo/test-10.5-msan/sql/slave.cc:4055:20
    #9 0x5586cce63536 in rpt_handle_event(rpl_parallel_thread::queued_event*, rpl_parallel_thread*) /home/sujatha/bug_repo/test-10.5-msan/sql/rpl_parallel.cc:61:8
    #10 0x5586cce554e8 in handle_rpl_parallel_thread /home/sujatha/bug_repo/test-10.5-msan/sql/rpl_parallel.cc:1342:18
    #11 0x5586ce145b29 in pfs_spawn_thread /home/sujatha/bug_repo/test-10.5-msan/storage/perfschema/pfs.cc:2201:3
    #12 0x7f48d68796da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
    #13 0x7f48d53c588e in clone /build/glibc-OTsEL5/glibc-2.27/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
  Memory was marked as uninitialized
    #0 0x5586cc0ffa4e in __msan_allocated_memory (/home/sujatha/bug_repo/test-10.5-msan/bld/sql/mariadbd+0x6dfa4e)
    #1 0x5586cf81e2b6 in my_malloc /home/sujatha/bug_repo/test-10.5-msan/mysys/my_malloc.c:111:7
 
SUMMARY: MemorySanitizer: use-of-uninitialized-value /home/sujatha/bug_repo/test-10.5-msan/mysys/my_write.c:49:19 in my_write
Exiting
==17820==WARNING: MemorySanitizer: use-of-uninitialized-value
----------SERVER LOG END-------------



 Comments   
Comment by Andrei Elkin [ 2020-06-12 ]

The bug is in that flush() (of 10.5) or flush_relay_log_info() (of 10.1) are invoked by Workers
concurrently.
Unlike the slave execution status which may be updated by Workers in Relay_log_info::stmt_done() after they
acquire mutex on rgi->rli->data_lock. That suggests how to fix.

Comment by Sujatha Sivakumar (Inactive) [ 2020-06-17 ]

Hello Andrei,

Thank you for the suggestion.
Please review the 10.1 changes.

Patch: https://github.com/MariaDB/server/commit/ad14a2821883b11228885253672ce4967ef4d55d
BuildBot: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.1-sujatha

Comment by Andrei Elkin [ 2020-06-24 ]

Left this on GH:
The patch is good and does not need any changes to 10.1-10.5. Yet in 10.6
I suggest relocate `flush_relay_log_info()` into `inc_group_relay_log_pos()`
to avoid two times mysql_mutex_lock(&data_lock).

The patch approved for 10.1, but in 10.6 we should try to improve it.

Comment by Sujatha Sivakumar (Inactive) [ 2020-06-26 ]

Fix is pushed into 10.1.46.

In 10.2 minor merge conflict will be there, as function name has changed.
Function name in 10.1 "flush_relay_log_info(this)" has been changed to "flush()" in 10.2.

10.2 Patch: https://github.com/MariaDB/server/commit/0e0d8d6dd01c2ff4ce85929f447077dfa85eb821

Patch remains the same for higher versions. All have been tested on buildbot.
10.3: https://github.com/MariaDB/server/commit/64f217e26b1310094dab1fc01b514244aa3f3bbd
10.4: https://github.com/MariaDB/server/commit/d9370e21e00d2af64fb0e2fd2a848dd2bfde3c10
10.5: https://github.com/MariaDB/server/commit/697b6c5a6280da10ccde095f5ccb936588f54e9a

Generated at Thu Feb 08 09:17:37 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.