[MDEV-14868] MariaDB server crashes after using ROLLBACK TO when encrypt_tmp_files=ON Created: 2018-01-04  Updated: 2018-02-08  Resolved: 2018-02-08

Status: Closed
Project: MariaDB Server
Component/s: Encryption
Affects Version/s: 10.1, 10.2
Fix Version/s: 10.1.32, 10.2.13

Type: Bug Priority: Critical
Reporter: Yura Sorokin Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: None
Environment:

CentOS 7 64-bit

Attachments: File a000-master.opt     File a000.test    
Issue Links:
Blocks
is blocked by MDEV-10259 mysqld crash with certain statement l... Closed
Sprint: 10.2.13

 Description   

On a server started with encrypt-tmp-files=ON and binlog-format=row
ROLLBACK TO sp
causes server to crash in the follow-up COMMIT

CREATE TABLE t (a TEXT) ENGINE = InnoDB;
 
BEGIN;
 
  INSERT INTO t VALUES (REPEAT('a', 20000));
 
  SAVEPOINT sp;
 
  INSERT INTO t VALUES (REPEAT('a', 20000));
 
  ROLLBACK TO sp;
 
COMMIT;


#0  0x00007ffff63011f7 in raise () from /lib64/libc.so.6
 
#1  0x00007ffff63028e8 in abort () from /lib64/libc.so.6
 
#2  0x00007ffff62fa266 in __assert_fail_base () from /lib64/libc.so.6
 
#3  0x00007ffff62fa312 in __assert_fail () from /lib64/libc.so.6
 
#4  0x0000555555dce308 in MYSQL_BIN_LOG::write_cache (this=this@entry=0x555556edc200 <mysql_bin_log>, thd=<optimized out>, cache=cache@entry=0x7fff9402ffc8) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7051
 
#5  0x0000555555dcea9e in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x555556edc200 <mysql_bin_log>, entry=entry@entry=0x7fffec271110, commit_id=commit_id@entry=0) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:8059
 
#6  0x0000555555dd6c60 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x555556edc200 <mysql_bin_log>, leader=leader@entry=0x7fffec271110) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7796
 
#7  0x0000555555dd7469 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x555556edc200 <mysql_bin_log>, entry=entry@entry=0x7fffec271110) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7593
 
#8  0x0000555555dd79f2 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x555556edc200 <mysql_bin_log>, thd=thd@entry=0x7fff94000b00, cache_mngr=cache_mngr@entry=0x7fff9402fe20, end_ev=end_ev@entry=0x7fffec2712a0, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=using_trx_cache@entry=true) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7267
 
#9  0x0000555555dd7ba2 in binlog_flush_cache (thd=thd@entry=0x7fff94000b00, cache_mngr=cache_mngr@entry=0x7fff9402fe20, end_ev=end_ev@entry=0x7fffec2712a0, all=all@entry=true, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=true) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:1785
 
#10 0x0000555555dd7dc8 in binlog_commit_flush_xid_caches (thd=thd@entry=0x7fff94000b00, cache_mngr=cache_mngr@entry=0x7fff9402fe20, all=all@entry=true, xid=xid@entry=9) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:1891
 
#11 0x0000555555dd7fde in MYSQL_BIN_LOG::log_and_order (this=<optimized out>, thd=0x7fff94000b00, xid=9, all=<optimized out>, need_prepare_ordered=<optimized out>, need_commit_ordered=<optimized out>) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:9530
 
#12 0x0000555555cd3d59 in ha_commit_trans (thd=thd@entry=0x7fff94000b00, all=all@entry=true) at /mnt/hgfs/repos/mariadb-server/sql/handler.cc:1465
 
#13 0x0000555555bc4dd7 in trans_commit (thd=thd@entry=0x7fff94000b00) at /mnt/hgfs/repos/mariadb-server/sql/transaction.cc:306
 
#14 0x0000555555ac745b in mysql_execute_command (thd=thd@entry=0x7fff94000b00) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:5756
 
#15 0x0000555555aca3bd in mysql_parse (thd=thd@entry=0x7fff94000b00, rawbuf=<optimized out>, length=6, parser_state=parser_state@entry=0x7fffec273510, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:7966
 
#16 0x0000555555acc20f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fff94000b00, packet=packet@entry=0x7fff9400b161 "COMMIT", packet_length=packet_length@entry=6, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:1824
 
#17 0x0000555555ace3d6 in do_command (thd=0x7fff94000b00) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:1369
 
#18 0x0000555555bb7828 in do_handle_one_connection (connect=connect@entry=0x555557ec5390) at /mnt/hgfs/repos/mariadb-server/sql/sql_connect.cc:1420
 
#19 0x0000555555bb7955 in handle_one_connection (arg=arg@entry=0x555557ec5390) at /mnt/hgfs/repos/mariadb-server/sql/sql_connect.cc:1326
 
#20 0x000055555636dd8a in pfs_spawn_thread (arg=0x555557ecdb90) at /mnt/hgfs/repos/mariadb-server/storage/perfschema/pfs.cc:1863
 
#21 0x00007ffff7bc6e25 in start_thread () from /lib64/libpthread.so.0
 
#22 0x00007ffff63c434d in clone () from /lib64/libc.so.6

Steps to reproduce:

  1. put the attached files `a000.test` and `a000-master.opt` into `encryption` MTR test suite (`mysql-test/suite/encryption/t`)
  2. run `./mysql-test/mtr --debug-server encryption.a000`

 Comments   
Comment by Elena Stepanova [ 2018-01-04 ]

Thanks for the report and test case.
The assertion failure is reproducible on 10.3 as initially reported, and also 10.2 debug servers.
Release servers and 10.1 instead produce an error, which probably shouldn't happen either:

query 'SHOW BINLOG EVENTS' failed: 1220: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error

Comment by Yura Sorokin [ 2018-01-09 ]

In addition, existing `encryption.tempfiles` MTR test case which is supposed to test similar `ROLLBACK TO SAVEPOINT` issue in the following section

#
 
# Test reinit_io_cache(WRITE_CACHE) with non-zero seek_offset:
 
# Start a transaction, write until the cache goes to disk,
 
# create a savepoint, write more blocks to disk, rollback to savepoint.
 
#
 
create table t1 (a text) engine=innodb;
 
start transaction;
 
insert t1 select repeat(seq, 1000) from seq_1_to_15;
 
savepoint foo;
 
insert t1 select repeat(seq, 1000) from seq_16_to_30;
 
#rollback to savepoint foo;
 
insert t1 select repeat(seq, 1000) from seq_31_to_40;
 
commit;
 
drop table t1;

never had `--encrypt-tmp-files` enabled.

Adding

SELECT @@global.encrypt_tmp_files;

at the beginning of the test will result in

@@ -1,3 +1,6 @@
 
+SELECT @@global.encrypt_tmp_files;
 
+@@global.encrypt_tmp_files
 
+0
 
 CREATE TABLE t1(a INT);
 
 INSERT INTO t1 VALUES(1),(2);
 
 DELETE FROM t1 WHERE a=1;

Adding `tempfiles-master.opt` with `--encrypt-tmp-files=ON` or running `./mysql-test/mtr --debug-server --mysqld=--encrypt-tmp-files=ON encryption.tempfiles` causes the same server crash and corrupted binlog

#0  0x00007fb2d1daf9b1 in pthread_kill () from /lib64/libpthread.so.0
 
#0  0x00007fb2d1daf9b1 in pthread_kill () from /lib64/libpthread.so.0
 
#1  0x0000558059945f85 in my_write_core (sig=6) at /mnt/hgfs/repos/mariadb-server/mysys/stacktrace.c:481
 
#2  0x0000558059257d46 in handle_fatal_signal (sig=6) at /mnt/hgfs/repos/mariadb-server/sql/signal_handler.cc:303
 
#3  <signal handler called>
 
#4  0x00007fb2d04e51f7 in raise () from /lib64/libc.so.6
 
#5  0x00007fb2d04e68e8 in abort () from /lib64/libc.so.6
 
#6  0x00007fb2d04de266 in __assert_fail_base () from /lib64/libc.so.6
 
#7  0x00007fb2d04de312 in __assert_fail () from /lib64/libc.so.6
 
#8  0x0000558059356308 in MYSQL_BIN_LOG::write_cache (this=this@entry=0x55805a464200 <mysql_bin_log>, thd=<optimized out>, cache=cache@entry=0x7fb264008c88) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7051
 
#9  0x0000558059356a9e in MYSQL_BIN_LOG::write_transaction_or_stmt (this=this@entry=0x55805a464200 <mysql_bin_log>, entry=entry@entry=0x7fb2c05f0110, commit_id=commit_id@entry=0) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:8059
 
#10 0x000055805935ec60 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x55805a464200 <mysql_bin_log>, leader=leader@entry=0x7fb2c05f0110) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7796
 
#11 0x000055805935f469 in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x55805a464200 <mysql_bin_log>, entry=entry@entry=0x7fb2c05f0110) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7593
 
#12 0x000055805935f9f2 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x55805a464200 <mysql_bin_log>, thd=thd@entry=0x7fb264000b00, cache_mngr=cache_mngr@entry=0x7fb264008ae0, end_ev=end_ev@entry=0x7fb2c05f02a0, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=using_trx_cache@entry=true) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:7267
 
#13 0x000055805935fba2 in binlog_flush_cache (thd=thd@entry=0x7fb264000b00, cache_mngr=cache_mngr@entry=0x7fb264008ae0, end_ev=end_ev@entry=0x7fb2c05f02a0, all=all@entry=true, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=true) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:1785
 
#14 0x000055805935fdc8 in binlog_commit_flush_xid_caches (thd=thd@entry=0x7fb264000b00, cache_mngr=cache_mngr@entry=0x7fb264008ae0, all=all@entry=true, xid=xid@entry=47) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:1891
 
#15 0x000055805935ffde in MYSQL_BIN_LOG::log_and_order (this=<optimized out>, thd=0x7fb264000b00, xid=47, all=<optimized out>, need_prepare_ordered=<optimized out>, need_commit_ordered=<optimized out>) at /mnt/hgfs/repos/mariadb-server/sql/log.cc:9530
 
#16 0x000055805925bd59 in ha_commit_trans (thd=thd@entry=0x7fb264000b00, all=all@entry=true) at /mnt/hgfs/repos/mariadb-server/sql/handler.cc:1465
 
#17 0x000055805914cdd7 in trans_commit (thd=thd@entry=0x7fb264000b00) at /mnt/hgfs/repos/mariadb-server/sql/transaction.cc:306
 
#18 0x000055805904f45b in mysql_execute_command (thd=thd@entry=0x7fb264000b00) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:5756
 
#19 0x00005580590523bd in mysql_parse (thd=thd@entry=0x7fb264000b00, rawbuf=<optimized out>, length=6, parser_state=parser_state@entry=0x7fb2c05f2510, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:7966
 
#20 0x000055805905420f in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fb264000b00, packet=packet@entry=0x7fb26400b161 "commit", packet_length=packet_length@entry=6, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:1824
 
#21 0x00005580590563d6 in do_command (thd=0x7fb264000b00) at /mnt/hgfs/repos/mariadb-server/sql/sql_parse.cc:1369
 
#22 0x000055805913f828 in do_handle_one_connection (connect=connect@entry=0x55805c4278d0) at /mnt/hgfs/repos/mariadb-server/sql/sql_connect.cc:1420
 
#23 0x000055805913f955 in handle_one_connection (arg=arg@entry=0x55805c4278d0) at /mnt/hgfs/repos/mariadb-server/sql/sql_connect.cc:1326
 
#24 0x00005580598f5d8a in pfs_spawn_thread (arg=0x55805c4305b0) at /mnt/hgfs/repos/mariadb-server/storage/perfschema/pfs.cc:1863
 
#25 0x00007fb2d1daae25 in start_thread () from /lib64/libpthread.so.0
 
#26 0x00007fb2d05a834d in clone () from /lib64/libc.so.6

Generated at Thu Feb 08 08:16:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.