Marko Mäkelä added a comment - 2017-09-07 07:50 The linked Buildbot logs do not seem to be available any more. I cannot check the failure of the test encryption.innodb_encrypt_log_corruption. It looks like the intentionally corrupted record was detected, but somehow the record dump was not found in the output. My best guess is that in the server error log, the output was interleaved with a message from some other thread. That happens from time to time. For encryption.innodb_encrypt_log, I have good news. I was able to reproduce a failure locally, with this type of result difference: CURRENT_TEST: encryption.innodb_encrypt_log --- /mariadb/10.3/mysql-test/suite/encryption/r/innodb_encrypt_log.result 2017-09-07 08:40:29.686385188 +0300 +++ /mariadb/10.3/mysql-test/suite/encryption/r/innodb_encrypt_log.reject 2017-09-07 08:41:40.528705075 +0300 @@ -52,7 +52,7 @@ INSERT INTO t0 VALUES(NULL, 5, 5, 'public', 'gossip'); # Kill the server # ib_logfile0 expecting NOT FOUND -NOT FOUND /private|secret|sacr(ed|ament)|success|story|secur(e|ity)/ in ib_logfile0 +FOUND 12 /private|secret|sacr(ed|ament)|success|story|secur(e|ity)/ in ib_logfile0 # ib_logfile0 expecting FOUND FOUND 3 /public|gossip/ in ib_logfile0 # ibdata1 expecting NOT FOUND With painstaking analysis, I determined that the offending clear-text redo log block is at the end of the redo log, as indicated by the LOG_BLOCK_HDR_DATA_LEN field that contains 0x26, meaning that the block should end at file offset 0x5c26: 00005c00: 0000 1268 0026 0012 0000 0002 0000 0013 ...h.&.......... 00005c10: 031f 9e07 0e1e f200 0d00 0000 0000 0080 ................ 00005c20: 0000 0000 0000 6563 7265 7420 2020 2020 ......ecret 00005c30: 201f a607 0400 0200 0200 0480 0834 ce02 ............4.. 00005c40: eda6 070a 0002 0002 000c 8008 29a0 02ed ............)... 00005c50: 9400 8149 000d 0b82 ed16 0880 0000 0000 ...I............ 00005c60: 0002 ee08 0703 0038 0000 0002 ee26 070b .......8.....&.. 00005c70: 0007 0001 8008 8006 8007 0004 0004 000c ................ 00005c80: 000c 1a13 5cee 0000 0000 110a 8800 0001 ....\........... 00005c90: 4932 4d80 0000 0280 0000 0273 6163 7265 I2M........sacre 00005ca0: 6420 2020 2020 2073 7563 6365 7373 2020 d success 00005cb0: 2020 201f a607 0400 0200 0200 0480 0834 ............4 00005cc0: e002 eea6 070a 0002 0002 000c 8008 29ba ..............). 00005cd0: 02ee 9400 8149 000d 0b82 ee16 0880 0000 .....I.......... 00005ce0: 0000 0002 ef08 0703 0038 0000 0002 ef26 .........8.....& 00005cf0: 070b 0007 0001 8008 8006 8007 0004 0004 ................ 00005d00: 000c 000c 1a4e 5cef 0000 0000 110a 8800 .....N\......... 00005d10: 0001 4932 5e80 0000 0380 0000 0373 746f ..I2^........sto 00005d20: 7279 2020 2020 2020 2073 6563 7572 6520 ry secure 00005d30: 2020 2020 201f a607 0400 0200 0200 0480 ........... 00005d40: 0834 f202 efa6 070a 0002 0002 000c 8008 .4.............. 00005d50: 29d4 02ef 9400 8149 000d 0b82 ef16 0880 )......I........ 00005d60: 0000 0000 0002 f008 0703 0038 0000 0002 ...........8.... 00005d70: f026 070b 0007 0001 8008 8006 8007 0004 .&.............. 00005d80: 0004 000c 000c 1a89 5cf0 0000 0000 110a ........\....... 00005d90: 8800 0001 4932 6f80 0000 0480 0000 0473 ....I2o........s 00005da0: 6563 7572 6974 7920 2020 2073 6163 7261 ecurity sacra 00005db0: 6d65 6e74 2020 201f a607 0400 0200 0200 ment ......... 00005dc0: 0480 0835 0402 f0a6 0709 0002 0002 000c ...5............ 00005dd0: 8008 22ec 02f0 9400 8149 000d 0b82 f016 .."......I...... 00005de0: 0880 0000 0000 0002 f108 0703 0038 0000 .............8.. 00005df0: 0002 f126 070b 0007 0001 8008 193d 8588 ...&.........=.. When writing redo log, InnoDB should zero out the garbage to avoid information leaks like this. This data is encrypted in the data files, and it was originally encrypted in the redo log. The data got exposed after redo log encryption was disabled and some other data was redo-logged. The other data must be found clear-text in the new unencrypted redo log, but there is absolutely no reason to write any old (originally encrypted) recovered redo log records there.

Marko Mäkelä added a comment - 2017-09-07 08:03 The fix is simple. After applying the fix to log_block_init() only, 4×20 repeats of the test encryption.innodb_encrypt_log passed for me. The change to recv_reset_logs() is extra safety, in case redo log is being written in larger blocks than 512 bytes. diff --git a/storage/innobase/include/log0log.ic b/storage/innobase/include/log0log.ic index 58da7bacc6f..568995d3d2f 100644 --- a/storage/innobase/include/log0log.ic +++ b/storage/innobase/include/log0log.ic @@ -294,7 +294,9 @@ log_block_init( log_block_set_hdr_no(log_block, no); log_block_set_data_len(log_block, LOG_BLOCK_HDR_SIZE); - log_block_set_first_rec_group(log_block, 0); + memset(log_block + LOG_BLOCK_FIRST_REC_GROUP, 0, + OS_FILE_LOG_BLOCK_SIZE - LOG_BLOCK_TRL_SIZE + - LOG_BLOCK_FIRST_REC_GROUP); } /** Append a string to the log. diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc index b5bd132d198..eeb743cb180 100644 --- a/storage/innobase/log/log0recv.cc +++ b/storage/innobase/log/log0recv.cc @@ -3525,6 +3525,7 @@ recv_reset_logs( log_sys->next_checkpoint_no = 0; log_sys->last_checkpoint_lsn = 0; + memset(log_sys->buf, 0, log_sys->buf_size); log_block_init(log_sys->buf, log_sys->lsn); log_block_set_first_rec_group(log_sys->buf, LOG_BLOCK_HDR_SIZE);

Marko Mäkelä added a comment - 2017-09-07 08:11 Before MDEV-11782 in MariaDB 10.2.4, enabling or disabling redo log encryption would not cause the redo log to be reinitialized. Thus, in the test scenario, MariaDB 10.1 would produce a redo log that contains both unencrypted and encrypted records in the first place. But it might still be good practice to not write garbage data to redo log files.

Jan Lindström (Inactive) added a comment - 2017-09-07 08:20 I do not see any easy way to avoid these memsets when not needed, and hopefully they do not have significant effect on performance especially when encryption is not enabled. ok to push.

Marko Mäkelä added a comment - 2017-09-07 08:54 The main performance impact should be in log_write_low(). Unfortunately, that is being executed while holding the log_sys->mutex. Another alternative would be to clear the garbage in log_group_write_buf(), but that would involve looking inside the individual log blocks (at least the last ones), to zero out the garbage in the last block. For avoiding the information leak from a previously encrypted log to an unencrypted log, it does suffice to reset the log_sys->buf in recv_reset_logs() and to leave log_block_init() unchanged. That would cause no performance impact outside the startup task of resizing or reinitializing the redo log file(s). I think that that change would be reasonable in 10.0 already (the first version that implements redo log resizing).