[MDEV-13253] After rebuilding redo logs, InnoDB can leak data from redo log buffer Created: 2017-07-06  Updated: 2017-09-07  Resolved: 2017-09-07

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.2
Fix Version/s: 10.0.33, 10.1.27, 10.2.9, 10.3.2

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-11782 Redefine the innodb_encrypt_log format Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-amd64/builds/5501/steps/test/logs/stdio

encryption.innodb_encrypt_log_corruption 'innodb' w4 [ fail ]
 
        Test ended at 2017-06-23 09:43:46
 
 
 
CURRENT_TEST: encryption.innodb_encrypt_log_corruption
 
--- /usr/local/mariadb-10.2.7-linux-x86_64/mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.result	2017-06-23 09:02:40.000000000 +0200
 
+++ /usr/local/mariadb-10.2.7-linux-x86_64/mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.reject	2017-06-23 09:43:46.000000000 +0200
 
@@ -70,7 +70,7 @@
 
 FOUND 1 /InnoDB: MLOG_FILE_NAME incorrect:bogus/ in mysqld.1.err
 
 FOUND 1 /InnoDB: ############### CORRUPT LOG RECORD FOUND ##################/ in mysqld.1.err
 
 FOUND 1 /InnoDB: Log record type 55, page 151:488\. Log parsing proceeded successfully up to 1213973\. Previous log record type 56, is multi 0 Recv offset 9, prev 0/ in mysqld.1.err
 
-FOUND 1 /len 22. hex 38000000000012860cb7809781e80006626f67757300. asc 8               bogus / in mysqld.1.err
 
+NOT FOUND /len 22. hex 38000000000012860cb7809781e80006626f67757300. asc 8               bogus / in mysqld.1.err
 
 FOUND 1 /InnoDB: Set innodb_force_recovery to ignore this error/ in mysqld.1.err
 
 # Test a corrupted MLOG_FILE_NAME record.
 
 # valid header, invalid checkpoint 1, valid checkpoint 2, invalid block
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Marko Mäkelä [ 2017-09-07 ]

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.

Comment by Marko Mäkelä [ 2017-09-07 ]

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);

Comment by Marko Mäkelä [ 2017-09-07 ]

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.

Comment by Jan Lindström (Inactive) [ 2017-09-07 ]

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.

Comment by Marko Mäkelä [ 2017-09-07 ]

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).

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