Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.4.5
-
None
-
BUILD/compile-pentium64-valgrind-max
Description
mtr --valgrind main.xa_binlog
==10964== Syscall param pwrite64(buf) points to uninitialised byte(s)
==10964== at 0x4E4CA83: ??? (in /lib64/libpthread-2.26.so)
==10964== by 0x1064216: SyncFileIO::execute(IORequest const&) (os0file.cc:1481)
==10964== by 0x1067E32: os_file_io(IORequest const&, int, void*, unsigned long, u
nsigned long, dberr_t*) (os0file.cc:4726)
==10964== by 0x1068348: os_file_pwrite(IORequest const&, int, unsigned char const*, unsigned long, unsigned long, dberr_t*) (os0file.cc:4811)
==10964== by 0x10684AC: os_file_write_func(IORequest const&, char const*, int, void const*, unsigned long, unsigned long) (os0file.cc:4842)
==10964== by 0x106B477: os_aio_func(IORequest&, unsigned long, char const*, pfs_os_file_t, void*, unsigned long, unsigned long, bool, fil_node_t*, void*) (os0file.cc:6504)
==10964== by 0x12B7E87: pfs_os_aio_func(IORequest&, unsigned long, char const*, pfs_os_file_t, void*, unsigned long, unsigned long, bool, fil_node_t*, void*, char const*, unsigned int) (os0file.ic:254)
==10964== by 0x12C5319: fil_io(IORequest const&, bool, page_id_t, unsigned long, unsigned long, unsigned long, void*, void*, bool) (fil0fil.cc:4299)
==10964== by 0x103CAC5: log_write_buf(unsigned char*, unsigned long, unsigned long, unsigned long, unsigned long) (log0log.cc:759)
==10964== by 0x103D47C: log_write_up_to(unsigned long, bool, bool) (log0log.cc:1009)
==10964== by 0x11B3D91: trx_flush_log_if_needed_low(unsigned long) (trx0trx.cc:1201)
==10964== by 0x11B3DDA: trx_flush_log_if_needed(unsigned long, trx_t*) (trx0trx.cc:1223)
==10964== by 0x11B671D: trx_prepare(trx_t*) (trx0trx.cc:2075)
==10964== by 0x11B677B: trx_prepare_for_mysql(trx_t*) (trx0trx.cc:2087)
==10964== by 0xF9D0BA: innobase_xa_prepare(handlerton*, THD*, bool) (ha_innodb.cc:16789)
=10964== by 0xBA3E11: prepare_or_error(handlerton*, THD*, bool) (handler.cc:1223)
==10964== Address 0x1166e1e4 is in a rw- anonymous segment
- saving '/home/my/maria-10.5/mysql-test/var/log/main.xa_binlog-innodb/' to '/home/my/maria-10.5/mysql-test/var/log/main.xa_binlog-innodb/'
***Warnings generated in error logs during shutdown after running tests: main.xa_binlog
==22104== Thread 10:
==22104== Uninitialised byte(s) found during client check request
==22104== at 0x12422C9: buf_dblwr_add_to_batch(buf_page_t*) (buf0dblwr.cc:1147)
==22104== by 0x124A620: buf_flush_write_block_low(buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1063)
==22104== by 0x124AD08: buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1211)
==22104== by 0x124B6A0: buf_flush_try_neighbors(page_id_t, buf_flush_t, unsigned long, unsigned long) (buf0flu.cc:1437)
==22104== by 0x124BADC: buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) (buf0flu.cc:1511)
==22104== by 0x124C9C9: buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) (buf0flu.cc:1770)
==22104== by 0x124D0E0: buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, flush_counters_t*) (buf0flu.cc:1840)
==22104== by 0x124D798: buf_flush_do_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, flush_counters_t*) (buf0flu.cc:1998)
==22104== by 0x124DA4E: buf_flush_lists(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:2100)
==22104== by 0x12526D6: buf_flush_page_cleaner_coordinator (buf0flu.cc:3256)
==22104== by 0x4E42568: start_thread (in /lib64/libpthread-2.26.so)
==22104== by 0x6ECBA2E: clone (in /lib64/libc-2.26.so)
==22104== Address 0x10ef4249 is 585 bytes inside a frame of size 16,384 client-defined
==22104== at 0x1227997: buf_block_init(buf_pool_t*, buf_block_t*, unsigned char*) (buf0buf.cc:1511)
==22104== by 0x1227E28: buf_chunk_init(buf_pool_t*, buf_chunk_t*, unsigned long) (buf0buf.cc:1657)
==22104== by 0x12288CD: buf_pool_init_instance(buf_pool_t*, unsigned long, unsigned long) (buf0buf.cc:1891)
==22104== by 0x12292E1: buf_pool_init(unsigned long, unsigned long) (buf0buf.cc:2087)
==22104== by 0x116C25A: srv_start(bool) (srv0start.cc:1512)
==22104== by 0xF83BA0: innodb_init(void*) (ha_innodb.cc:4127)
==22104== by 0xBA2FC4: ha_initialize_handlerton(st_plugin_int*) (handler.cc:550)
==22104== by 0x8A3030: plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) (sql_plugin.cc:1437)
==22104== by 0x8A3C2C: plugin_init(int*, char**, int) (sql_plugin.cc:1719)
==22104== by 0x75C827: init_server_components() (mysqld.cc:5037)
==22104== by 0x75D99E: mysqld_main(int, char**) (mysqld.cc:5566)
==22104== by 0x7524A6: main (main.cc:25)
==22104== Syscall param io_submit(PWRITE) points to uninitialised byte(s)
==22104== at 0x5E6A787: io_submit (in /lib64/libaio.so.1.0.1)
==22104== by 0x106529A: AIO::linux_dispatch(Slot*) (os0file.cc:2035)
==22104== by 0x106B5B1: os_aio_func(IORequest&, unsigned long, char const*, pfs_os_file_t, void*, unsigned long, unsigned long, bool, fil_node_t*, void*) (os0file.cc:6548)
==22104== by 0x12B7E87: pfs_os_aio_func(IORequest&, unsigned long, char const*, pfs_os_file_t, void*, unsigned long, unsigned long, bool, fil_node_t*, void*, char const*, unsigned int) (os0file.ic:254)
==22104== by 0x12C5319: fil_io(IORequest const&, bool, page_id_t, unsigned long, unsigned long, unsigned long, void*, void*, bool) (fil0fil.cc:4299)
==22104== by 0x1241937: buf_dblwr_write_block_to_datafile(buf_page_t const*, bool) (buf0dblwr.cc:938)
==22104== by 0x1241F15: buf_dblwr_flush_buffered_writes() (buf0dblwr.cc:1082)
==22104== by 0x124D5E7: buf_flush_end(buf_pool_t*, buf_flush_t) (buf0flu.cc:1931)
==22104== by 0x124D7A9: buf_flush_do_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, flush_counters_t*) (buf0flu.cc:2000)
==22104== by 0x124DA4E: buf_flush_lists(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:2100)
==22104== by 0x12526D6: buf_flush_page_cleaner_coordinator (buf0flu.cc:3256)
==22104== by 0x4E42568: start_thread (in /lib64/libpthread-2.26.so)
==22104== by 0x6ECBA2E: clone (in /lib64/libc-2.26.so)
==22104== Address 0x10ef4249 is 585 bytes inside a frame of size 16,384 client-defined
==22104== at 0x1227997: buf_block_init(buf_pool_t*, buf_block_t*, unsigned char*) (buf0buf.cc:1511)
==22104== by 0x1227E28: buf_chunk_init(buf_pool_t*, buf_chunk_t*, unsigned long) (buf0buf.cc:1657)
==22104== by 0x12288CD: buf_pool_init_instance(buf_pool_t*, unsigned long, unsigned long) (buf0buf.cc:1891)
==22104== by 0x12292E1: buf_pool_init(unsigned long, unsigned long) (buf0buf.cc:2087)
==22104== by 0x116C25A: srv_start(bool) (srv0start.cc:1512)
==22104== by 0xF83BA0: innodb_init(void*) (ha_innodb.cc:4127)
==22104== by 0xBA2FC4: ha_initialize_handlerton(st_plugin_int*) (handler.cc:550)
==22104== by 0x8A3030: plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) (sql_plugin.cc:1437)
==22104== by 0x8A3C2C: plugin_init(int*, char**, int) (sql_plugin.cc:1719)
==22104== by 0x75C827: init_server_components() (mysqld.cc:5037)
==22104== by 0x75D99E: mysqld_main(int, char**) (mysqld.cc:5566)
==22104== by 0x7524A6: main (main.cc:25)
Attachments
Issue Links
- is part of
-
-
- Closed
-
- relates to
-
MDEV-7974 backport fix for mysql bug#12161 (XA and binlog)
-
- Closed
-
-
-
- Closed
-
Activity
I tested the latest 5.5, 10.1, 10.2, 10.3, and I was unable to repeat this problem there. I can repeat on 10.4 and 10.5. I will try further to find where in 10.4 the problem was introduced.
Starting with this refactoring that was part of MDEV-7974, Valgrind became aware that the unused tail of the buffer that is returned by thd_get_xid() is actually uninitialized.
It is possible that the problem exists since MySQL 5.0. InnoDB is allocating 128+4+4 bytes for the XID and the lengths of its components, even when the XID is shorter than 64+64 bytes. In MariaDB 10.3, in the xid_t::set() that is called by sql_yacc.yy, the 128-byte data buffer was uninitialized according to Valgrind, and only the first bytes were initialized. The entire 128-byte data was later ‘blessed’ by something that copied it to thd.transaction.xid_state.xid.data. With additional instrumentation, I can repeat the issue on 5.5:
diff --git a/sql/handler.h b/sql/handler.h
|
index 32a7686f6c9..42ec434c4c3 100644
|
--- a/sql/handler.h
|
+++ b/sql/handler.h
|
@@ -454,12 +454,17 @@ struct xid_t {
|
bool eq(long g, long b, const char *d)
|
{ return g == gtrid_length && b == bqual_length && !memcmp(d, data, g+b); }
|
void set(struct xid_t *xid)
|
- { memcpy(this, xid, xid->length()); }
|
+ { memcpy(this, xid, xid->length());
|
+ TRASH_ALLOC(data + (gtrid_length + bqual_length), (sizeof data)
|
+ - (gtrid_length + bqual_length));
|
+ }
|
void set(long f, const char *g, long gl, const char *b, long bl)
|
{
|
formatID= f;
|
memcpy(data, g, gtrid_length= gl);
|
memcpy(data+gl, b, bqual_length= bl);
|
+ TRASH_ALLOC(data + (gtrid_length + bqual_length), (sizeof data)
|
+ - (gtrid_length + bqual_length));
|
}
|
void set(ulonglong xid)
|
{ |
It is the first hunk that matters. With the second hunk alone, the buffer returned by thd_get_xid() would still be fully initialized.
|
mariadb-5.5.65 with the above patch |
main.xa_binlog 'innodb_plugin' w1 [ fail ] Found warnings/errors in server log file!
|
Test ended at 2019-08-12 13:33:26
|
line
|
==18115== Thread 14:
|
==18115== Syscall param pwrite64(buf) points to uninitialised byte(s)
|
==18115== at 0x4881EDF: __libc_pwrite64 (pwrite64.c:29)
|
==18115== by 0x4881EDF: pwrite (pwrite64.c:27)
|
==18115== by 0x86CEAA1: os_file_pwrite (os0file.c:2398)
|
==18115== by 0x86CED23: os_file_write_func (os0file.c:2896)
|
==18115== by 0x86D094B: os_aio_func (os0file.c:4252)
|
==18115== by 0x866A643: pfs_os_aio_func (os0file.ic:246)
|
==18115== by 0x86750B3: fil_io (fil0fil.c:4740)
|
==18115== by 0x86B85CE: log_group_write_buf (log0log.c:1417)
|
==18115== by 0x86B8AFA: log_write_up_to (log0log.c:1599)
|
==18115== by 0x87AB5EA: trx_prepare_off_kernel (trx0trx.c:2007)
|
==18115== by 0x87AB6CE: trx_prepare_for_mysql (trx0trx.c:2043)
|
==18115== by 0x87122B6: innobase_xa_prepare(handlerton*, THD*, bool) (ha_innodb.cc:10847)
|
==18115== by 0x6AE245: ha_prepare(THD*) (handler.cc:1069)
|
==18115== by 0x6099A6: trans_xa_prepare(THD*) (transaction.cc:673)
|
==18115== by 0x4F6B89: mysql_execute_command(THD*) (sql_parse.cc:4379)
|
==18115== by 0x4FA6DC: mysql_parse(THD*, char*, unsigned int, Parser_state*) (sql_parse.cc:5929)
|
==18115== by 0x4EDFC7: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1067)
|
==18115== Address 0x9d02c18 is 12,504 bytes inside a block of size 1,049,240 alloc'd
|
==18115== at 0x48356AF: malloc (vg_replace_malloc.c:308)
|
==18115== by 0x87B4968: ut_malloc_low (ut0mem.c:115)
|
==18115== by 0x86C5EC1: mem_area_alloc (mem0pool.c:404)
|
==18115== by 0x86C43B4: mem_heap_create_block (mem0mem.c:334)
|
==18115== by 0x86B5C65: mem_heap_create_func (mem0mem.ic:434)
|
==18115== by 0x86B5E31: mem_alloc_func (mem0mem.ic:520)
|
==18115== by 0x86B74F2: log_init (log0log.c:895)
|
==18115== by 0x87834CE: innobase_start_or_create_for_mysql (srv0start.c:1450)
|
==18115== by 0x8703BD1: innobase_init(void*) (ha_innodb.cc:2611)
|
==18115== by 0x6AD7F2: ha_initialize_handlerton(st_plugin_int*) (handler.cc:470)
|
==18115== by 0x503B0B: plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) (sql_plugin.cc:1381)
|
==18115== by 0x504532: plugin_init(int*, char**, int) (sql_plugin.cc:1654)
|
==18115== by 0x442325: init_server_components() (mysqld.cc:4291)
|
==18115== by 0x443372: mysqld_main(int, char**) (mysqld.cc:4890)
|
==18115== by 0x43B3C4: main (main.cc:25)
|
^ Found warnings in /dev/shm/5.5/mysql-test/var/1/log/mysqld.1.err
|
ok
|
|
|
- saving '/dev/shm/5.5/mysql-test/var/1/log/main.xa_binlog-innodb_plugin/' to '/dev/shm/5.5/mysql-test/var/log/main.xa_binlog-innodb_plugin/'
|
***Warnings generated in error logs during shutdown after running tests: main.xa_binlog
|
|
|
==18115== Thread 12:
|
==18115== Uninitialised byte(s) found during client check request
|
==18115== at 0x863084C: buf_flush_post_to_doublewrite_buf (buf0flu.c:991)
|
==18115== by 0x86310C6: buf_flush_write_block_low (buf0flu.c:1186)
|
==18115== by 0x8631768: buf_flush_page (buf0flu.c:1379)
|
==18115== by 0x8631A85: buf_flush_try_neighbors (buf0flu.c:1488)
|
==18115== by 0x8631CE7: buf_flush_page_and_try_neighbors (buf0flu.c:1554)
|
==18115== by 0x86320D8: buf_flush_flush_list_batch (buf0flu.c:1678)
|
==18115== by 0x8632227: buf_flush_batch (buf0flu.c:1758)
|
==18115== by 0x86327F6: buf_flush_list (buf0flu.c:1975)
|
==18115== by 0x877FB02: srv_master_thread (srv0srv.c:3126)
|
==18115== by 0x4877FA2: start_thread (pthread_create.c:486)
|
==18115== by 0x4D624CE: clone (clone.S:95)
|
==18115== Address 0x9988000 is 0 bytes inside a of size 16,384 client-defined
|
==18115== at 0x8622061: buf_block_init (buf0buf.c:900)
|
==18115== by 0x8622353: buf_chunk_init (buf0buf.c:1023)
|
==18115== by 0x8622909: buf_pool_init_instance (buf0buf.c:1201)
|
==18115== by 0x8622DBC: buf_pool_init (buf0buf.c:1309)
|
==18115== by 0x87833F2: innobase_start_or_create_for_mysql (srv0start.c:1420)
|
==18115== by 0x8703BD1: innobase_init(void*) (ha_innodb.cc:2611)
|
==18115== by 0x6AD7F2: ha_initialize_handlerton(st_plugin_int*) (handler.cc:470)
|
==18115== by 0x503B0B: plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) (sql_plugin.cc:1381)
|
==18115== by 0x504532: plugin_init(int*, char**, int) (sql_plugin.cc:1654)
|
==18115== by 0x442325: init_server_components() (mysqld.cc:4291)
|
==18115== by 0x443372: mysqld_main(int, char**) (mysqld.cc:4890)
|
==18115== by 0x43B3C4: main (main.cc:25)
|
==18115== Syscall param io_submit(PWRITE) points to uninitialised byte(s)
|
==18115== at 0x4D5CF59: syscall (syscall.S:38)
|
==18115== by 0x4892310: io_submit (in /usr/lib/x86_64-linux-gnu/libaio.so.1.0.1)
|
==18115== by 0x86D074B: os_aio_linux_dispatch (os0file.c:4139)
|
==18115== by 0x86D0B47: os_aio_func (os0file.c:4318)
|
==18115== by 0x866A643: pfs_os_aio_func (os0file.ic:246)
|
==18115== by 0x86750B3: fil_io (fil0fil.c:4740)
|
==18115== by 0x863051E: buf_flush_buffered_writes (buf0flu.c:934)
|
==18115== by 0x863228F: buf_flush_batch (buf0flu.c:1766)
|
==18115== by 0x86327F6: buf_flush_list (buf0flu.c:1975)
|
==18115== by 0x877FB02: srv_master_thread (srv0srv.c:3126)
|
==18115== by 0x4877FA2: start_thread (pthread_create.c:486)
|
==18115== by 0x4D624CE: clone (clone.S:95)
|
==18115== Address 0x9988000 is 0 bytes inside a of size 16,384 client-defined
|
==18115== at 0x8622061: buf_block_init (buf0buf.c:900)
|
==18115== by 0x8622353: buf_chunk_init (buf0buf.c:1023)
|
==18115== by 0x8622909: buf_pool_init_instance (buf0buf.c:1201)
|
==18115== by 0x8622DBC: buf_pool_init (buf0buf.c:1309)
|
==18115== by 0x87833F2: innobase_start_or_create_for_mysql (srv0start.c:1420)
|
==18115== by 0x8703BD1: innobase_init(void*) (ha_innodb.cc:2611)
|
==18115== by 0x6AD7F2: ha_initialize_handlerton(st_plugin_int*) (handler.cc:470)
|
==18115== by 0x503B0B: plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) (sql_plugin.cc:1381)
|
==18115== by 0x504532: plugin_init(int*, char**, int) (sql_plugin.cc:1654)
|
==18115== by 0x442325: init_server_components() (mysqld.cc:4291)
|
==18115== by 0x443372: mysqld_main(int, char**) (mysqld.cc:4890)
|
==18115== by 0x43B3C4: main (main.cc:25)
|
I believe that it suffices to fix this bug in the 10.4 series onwards. Even though the older versions have been writing garbage, that garbage has been ignored, because only the xid_t::data prefix of gtrid_length + bqual_length is being considered. A fix for earlier versions would be different, because the redo log record type MLOG_MEMSET was only introduced in 10.4.
I can repeat some Valgrind warnings when running main.xa_binlog. First, many Conditional jump or move depends on uninitialised value(s) outside InnoDB, related to SSL initialization. Here is the first one:
10.5 f6e386f00b4e50174758d3707706f0d1288baeb3
Thread 1 received signal SIGTRAP, Trace/breakpoint trap.0x00000000052542e3 in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(gdb) bt#0 0x00000000052542e3 in ?? ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#1 0x00000000052551fb in RAND_DRBG_generate ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#2 0x0000000005256621 in ?? ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#3 0x0000000005254a0a in RAND_DRBG_instantiate ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#4 0x0000000005255938 in ?? ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#5 0x0000000005255cca in RAND_DRBG_get0_public ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#6 0x0000000005255cf0 in ?? ()from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1#7 0x0000000005046be3 in SSL_CTX_new ()from /usr/lib/x86_64-linux-gnu/libssl.so.1.1#8 0x0000000000b4fe52 in new_VioSSLFd (key_file=0x58adfa0 "/mariadb/10.5/mysql-test/std_data/server-key.pem",cert_file=0x58adef1 "/mariadb/10.5/mysql-test/std_data/server-cert.pem",ca_file=0x58ade4f "/mariadb/10.5/mysql-test/std_data/cacert.pem",ca_path=0x0, cipher=<optimized out>, is_client_method=0 '\000',error=<optimized out>, crl_file=<optimized out>,crl_path=<optimized out>, tls_version=<optimized out>)at /mariadb/10.5/vio/viosslfactories.c:251#9 0x0000000000b505f5 in new_VioSSLAcceptorFd (key_file=0xb276860 "",cert_file=0xb90ce30 "", ca_file=0xb276957 "{800-90A DRBG\200",ca_path=0x0, cipher=0x0, error=<optimized out>, crl_file=0x0,crl_path=0x0, tls_version=14) at /mariadb/10.5/vio/viosslfactories.c:413#10 0x000000000063ba04 in init_ssl () at /mariadb/10.5/sql/mysqld.cc:4626#11 mysqld_main (argc=<optimized out>, argv=<optimized out>)at /mariadb/10.5/sql/mysqld.cc:5632#12 0x00000000055a509b in __libc_start_main (main=0x636770 <main(int, char**)>, argc=25, argv=0x1fff000378,init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>,stack_end=0x1fff000368) at ../csu/libc-start.c:308#13 0x00000000006366aa in _start ()Then, a bogus warning, apparently because Valgrind is not compatible with the optimized code generated by my compiler clang-8:
==20837== Conditional jump or move depends on uninitialised value(s)==20837== at 0xD6D00B: mach_write_to_2 (mach0data.ic:58)==20837== by 0xD6D00B: rec_set_bit_field_2 (rem0rec.ic:220)==20837== by 0xD6D00B: rec_set_n_fields_old (rem0rec.ic:431)==20837== by 0xD6D00B: rec_convert_dtuple_to_rec_old (rem0rec.cc:1419)==20837== by 0xD6D00B: rec_convert_dtuple_to_rec(unsigned char*, dict_index_t const*, dtuple_t const*, unsigned long) (rem0rec.cc:1765)==20837== by 0xE86D06: page_cur_tuple_insert(page_cur_t*, dtuple_t const*, dict_index_t*, unsigned long**, mem_block_info_t**, unsigned long, mtr_t*) (page0cur.ic:272)The code is
ut_ad((n & ~0xFFFFUL) == 0);After I removed -O2 from the CMAKE_CXX_FLAGS, this bogus warning went away, and the first InnoDB issue (after the SSL initialization) instead was the reported one:
Syscall param pwrite64(buf) points to uninitialised byte(s)…#0 __libc_pwrite64 (offset=141312, count=512, buf=0xce72000, fd=11)at ../sysdeps/unix/sysv/linux/pwrite64.c:29#1 __libc_pwrite64 (fd=11, buf=0xce72000, count=512, offset=141312)at ../sysdeps/unix/sysv/linux/pwrite64.c:27#2 0x0000000001143014 in SyncFileIO::execute (this=0xd0948c8, request=...)at /mariadb/10.5/storage/innobase/os/os0file.cc:1481#3 0x000000000114e5ee in os_file_io (in_type=..., file=11, buf=0xce72000,n=512, offset=141312, err=0xd094f2c)at /mariadb/10.5/storage/innobase/os/os0file.cc:4726#4 0x0000000001147a29 in os_file_pwrite (type=..., file=11,buf=0xce72000 "\200", n=512, offset=141312, err=0xd094f2c)at /mariadb/10.5/storage/innobase/os/os0file.cc:4810#5 0x0000000001147509 in os_file_write_func (type=...,name=0xb779460 "./ib_logfile0", file=11, buf=0xce72000, offset=141312,n=512) at /mariadb/10.5/storage/innobase/os/os0file.cc:4842#6 0x000000000114bc59 in os_aio_func (type=..., mode=24,name=0xb779460 "./ib_logfile0", file=..., buf=0xce72000, offset=141312,n=512, read_only=false, m1=0x10b7ea90, m2=0x0)at /mariadb/10.5/storage/innobase/os/os0file.cc:6504#7 0x000000000143370d in pfs_os_aio_func (type=..., mode=24,name=0xb779460 "./ib_logfile0", file=..., buf=0xce72000, offset=141312,n=512, read_only=false, m1=0x10b7ea90, m2=0x0,src_file=0x1848a26 "/mariadb/10.5/storage/innobase/fil/fil0fil.cc",src_line=4304) at /mariadb/10.5/storage/innobase/include/os0file.ic:253#8 0x0000000001433044 in fil_io (type=..., sync=true, page_id=...,zip_size=16384, byte_offset=10240, len=512, buf=0xce72000, message=0x0,ignore_missing_space=false)at /mariadb/10.5/storage/innobase/fil/fil0fil.cc:4299#9 0x0000000001111aeb in log_write_buf (buf=0xce72000 "\200", len=512,pad_len=0, start_lsn=147968, new_data_offset=58)at /mariadb/10.5/storage/innobase/log/log0log.cc:759#10 0x0000000001110e7a in log_write_up_to (lsn=148282, flush_to_disk=true,rotate_key=false) at /mariadb/10.5/storage/innobase/log/log0log.cc:1009#11 0x00000000012e7557 in trx_flush_log_if_needed_low (lsn=148282)at /mariadb/10.5/storage/innobase/trx/trx0trx.cc:1201#12 0x00000000012e493b in trx_flush_log_if_needed (lsn=148282, trx=0xc172170)at /mariadb/10.5/storage/innobase/trx/trx0trx.cc:1223#13 0x00000000012e53d4 in trx_prepare (trx=0xc172170)at /mariadb/10.5/storage/innobase/trx/trx0trx.cc:2075#14 0x00000000012e51b2 in trx_prepare_for_mysql (trx=0xc172170)at /mariadb/10.5/storage/innobase/trx/trx0trx.cc:2087#15 0x0000000001054938 in innobase_xa_prepare (hton=0xb4f0168, thd=0xb3723e8,prepare_trx=true)at /mariadb/10.5/storage/innobase/handler/ha_innodb.cc:16789#16 0x0000000000c48ac1 in prepare_or_error (ht=0xb4f0168, thd=0xb3723e8,all=true) at /mariadb/10.5/sql/handler.cc:1223#17 0x0000000000c488e1 in ha_prepare (thd=0xb3723e8)at /mariadb/10.5/sql/handler.cc:1261#18 0x0000000000b705be in trans_xa_prepare (thd=0xb3723e8)at /mariadb/10.5/sql/xa.cc:500#19 0x00000000008d4945 in mysql_execute_command (thd=0xb3723e8)at /mariadb/10.5/sql/sql_parse.cc:5915#20 0x00000000008c22b0 in mysql_parse (thd=0xb3723e8,rawbuf=0x17e14310 "XA PREPARE 'xatest'", length=19,parser_state=0xd09bcb8, is_com_multi=false, is_next_command=false)at /mariadb/10.5/sql/sql_parse.cc:7868…(gdb) frame 2#2 0x0000000001143014 in SyncFileIO::execute (this=0xd0948c8, request=...)at /mariadb/10.5/storage/innobase/os/os0file.cc:1481(gdb) p *this$1 = {m_fh = 11, m_buf = 0xce72000, m_n = 512, m_offset = 141312}(gdb) monitor get_vbits 0xce72000 51200000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 000000ffffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ffffffffffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ffffffffffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ffffffffffffffff ffffffff ffffffff ffffffff ffffffff ffffffff ff000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 0000000000000000 00000000 00000000 00000000 00000000 00000000 00000000 ffffffff(gdb)The uninitialized bytes appear to be the redo log block checksum (the last 4 bytes), as well as the 124 bytes in the payload area:
p/x ((char*)m_buf)[191]@124$4 = {0x0 <repeats 122 times>, 0x1f, 0x0}This appears to be right after the XID xatest:
(gdb) p *(char*)m_buf@m_n$5 = "\200\000\001\"\001:\000\021\000\000\000\004\000\000\000\000\000\236\000\n\t\222\000\r\000\000\000\000\000\000\200\000\000\000\000\000\000\236\000\201\063\001\066\000\r\000\000\000\000\000\000\200\000\000\000\000\000\000\031\000\201\067\000\000\000\000\036\002\000\201\067\000(\202\303\002\000\201\067\000*\202\303\002\000\201\067\002\033\202\303\024\000\201\067\000\b\v\000\024\004\200\000\000\001\037\246\005\003\000\003\000\001\200\004\200\006\200\a\000c#\000\005\005\200\000\000\001\000\000\000\000\000\036\203\000\000\001\067\002\303\002\000\201\067\000\070\005\001\000\201\067\002\035\001\004\000\201\067\002\067\001\004\000\201\067\002;\006\004\000\201\067\002?\000\036\000\201\067\002C\000\200xatest", '\000' <repeats 122 times>, "\037", '\000' <repeats 194 times>, "\335\300\273!"The following change fixes this, and also reduces the redo log volume somewhat:
diff --git a/storage/innobase/trx/trx0undo.cc b/storage/innobase/trx/trx0undo.ccindex 6267a8edd53..dde95dc1bce 100644--- a/storage/innobase/trx/trx0undo.cc+++ b/storage/innobase/trx/trx0undo.cc@@ -662,6 +662,10 @@ trx_undo_write_xid(const XID* xid, /*!< in: X/Open XA Transaction Identification */mtr_t* mtr) /*!< in: mtr */{+ ut_ad(xid->gtrid_length >= 0);+ ut_ad(xid->bqual_length >= 0);+ ut_ad(xid->gtrid_length + xid->bqual_length < XIDDATASIZE);+mlog_write_ulint(log_hdr + TRX_UNDO_XA_FORMAT,static_cast<ulint>(xid->formatID),MLOG_4BYTES, mtr);@@ -673,10 +677,13 @@ trx_undo_write_xid(mlog_write_ulint(log_hdr + TRX_UNDO_XA_BQUAL_LEN,static_cast<ulint>(xid->bqual_length),MLOG_4BYTES, mtr);-+ const ulint xid_length = static_cast<ulint>(xid->gtrid_length+ + xid->bqual_length);mlog_write_string(log_hdr + TRX_UNDO_XA_XID,reinterpret_cast<const byte*>(xid->data),- XIDDATASIZE, mtr);+ xid_length, mtr);+ mlog_memset(log_hdr + TRX_UNDO_XA_XID + xid_length,+ XIDDATASIZE - xid_length, 0, mtr);}In trx_rseg_write_wsrep_checkpoint() there is a similar problem.
The function mlog_memset() (and the redo log record type MLOG_MEMSET) was introduced in MariaDB Server 10.4. In earlier versions, we will have to use mlog_write_string().
I suppose that the uninitialized data in buf_flush_try_neighbors() is the undo log block that is being flushed to the data file some time after the redo log. I did not see that failure after applying the above fix.