|
On a related note, when built with cmake -DWITH_ASAN, MariaDB Server 10.1 reports memory leaks for encryption.innodb_first_page,innodb_plugin but not for xtradb.
These leaks go away if the rbt_create() and rbt_free() calls for buf_pool->flush_rbt are removed from buf0flu.cc.
There also is a leak reported for innodb.innodb_corrupt_bit.
AddressSanitizer does not track uninitialized data, so I will have to compile the server without ASAN and run with Valgrind.
|
|
MDEV-11730 Memory leak in innodb.innodb_corrupt_bit
Now the only remaining memory leak in 10.1 that I am aware of is the one for encryption.innodb_first_page.
|
|
One more thing: The combination of MemorySanitizer and AddressSanitizer should offer everything that Valgrind offers. In MySQL 5.7, these are mapped to the build options WITH_MSAN and WITH_ASAN.
Alas, last time I tried, WITH_MSAN would faild to build MySQL, because gen_lex_hash or some similar tool would trigger MemorySanitizer errors.
I believe that we should aim to enable both WITH_ASAN and WITH_MSAN runs on buildbot, to replace or augment Valgrind.
|
|
serg, svoj, opinions on the above are welcome.
|
|
On replacing the valgrind? Sure, if they do the same but are faster. But first we need to implement these options, then enable then on at least one builder, let them run for a while, and then if they'll prove to be a superset of valgrind, we can remove the valgrind builder.
|
|
I tried building 10.1 with -fsanitizer=memory (copying and adapting the WITH_ASAN code in the top-level CMakeLists.txt), but it failed with unresolved references to __msan functions when linking libstrings, even though -fsanitizer=memory was present in the clang-4.0 invocation for linking.
It seems that <sanitizer/msan_interface.h> has counterparts for the <valgrind/memcheck.h> primitives that InnoDB UNIV_MEM_ macros are referring to. I am looking forward to running some tests with MemorySanitizer once the linking problems have been solved.
|
|
I ran the full --suite=encryption in 10.1 with --valgrind, and the only errors I got were an assertion failure (see MDEV-9359 for details), followed by Valgrind leak reports. There were no other errors from Valgrind, except for a --show-reachable warning for mysqltest.cc which is repeatable with this (reduced from an uncommitted test):
The only other failure was a result difference (probably badly written test that should be cleaned up similar to MDEV-8139):
CURRENT_TEST: encryption.encrypt_and_grep
|
--- /home/marko/mariadb/server/mysql-test/suite/encryption/r/encrypt_and_grep.result 2017-01-10 14:29:30.908958369 +0200
|
+++ /home/marko/mariadb/server/mysql-test/suite/encryption/r/encrypt_and_grep.reject 2017-01-10 17:30:21.735822715 +0200
|
@@ -33,7 +33,7 @@
|
# t1 yes on expecting NOT FOUND
|
NOT FOUND /foobar/ in t1.ibd
|
# t2 ... on expecting NOT FOUND
|
-NOT FOUND /temp/ in t2.ibd
|
+FOUND /temp/ in t2.ibd
|
# t3 no on expecting FOUND
|
FOUND /dummy/ in t3.ibd
|
# ibdata1 expecting NOT FOUND
|
|
mysqltest: Result length mismatch
|
|
|
Still reproducible for me on 10.1 5044dae239:
$ perl ./mtr encryption.innodb_encryption_is,cbc,xtradb --valgrind
|
...
|
==============================================================================
|
|
--------------------------------------------------------------------------
|
|
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
encryption.innodb_encryption_is 'cbc,xtradb' [ fail ] Found warnings/errors in server log file!
|
Test ended at 2017-01-10 19:29:32
|
line
|
==16554== Thread 15:
|
==16554== Conditional jump or move depends on uninitialised value(s)
|
==16554== at 0xC285CB: buf_page_is_checksum_valid_innodb(unsigned char const*, unsigned long, unsigned long) (buf0buf.cc:653)
|
==16554== by 0xC28A2E: buf_page_is_corrupted(bool, unsigned char const*, unsigned long) (buf0buf.cc:859)
|
==16554== by 0xCB3B5D: fil_space_encrypt(unsigned long, unsigned long, unsigned long, unsigned char*, unsigned long, unsigned char*) (fil0crypt.cc:697)
|
==16554== by 0xC34E27: buf_page_encrypt_before_write(buf_page_t*, unsigned char*, unsigned long) (buf0buf.cc:6366)
|
==16554== by 0xC40E16: buf_flush_write_block_low(buf_page_t*, buf_flush_t, bool) (buf0flu.cc:950)
|
==16554== by 0xC4137F: buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1109)
|
==16554== by 0xC41951: buf_flush_try_neighbors(unsigned long, unsigned long, buf_flush_t, unsigned long, unsigned long) (buf0flu.cc:1324)
|
==16554== by 0xC41C76: buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) (buf0flu.cc:1412)
|
==16554== by 0xC42763: buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) (buf0flu.cc:1741)
|
==16554== by 0xC42AFD: buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, bool, flush_counters_t*) (buf0flu.cc:1817)
|
==16554== by 0xC43229: buf_flush_list(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:2097)
|
==16554== by 0xC43EBC: page_cleaner_do_flush_batch(unsigned long, unsigned long) (buf0flu.cc:2410)
|
==16554== by 0xC4513E: buf_flush_page_cleaner_thread (buf0flu.cc:2792)
|
==16554== by 0x4E3D0A3: start_thread (pthread_create.c:309)
|
==16554== by 0x6CB787C: clone (clone.S:111)
|
==16554== Conditional jump or move depends on uninitialised value(s)
|
==16554== at 0x4C2ED52: __memcmp_sse4_1 (vg_replace_strmem.c:972)
|
==16554== by 0xCB3B7D: fil_space_encrypt(unsigned long, unsigned long, unsigned long, unsigned char*, unsigned long, unsigned char*) (fil0crypt.cc:698)
|
==16554== by 0xC34E27: buf_page_encrypt_before_write(buf_page_t*, unsigned char*, unsigned long) (buf0buf.cc:6366)
|
==16554== by 0xC40E16: buf_flush_write_block_low(buf_page_t*, buf_flush_t, bool) (buf0flu.cc:950)
|
==16554== by 0xC4137F: buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1109)
|
==16554== by 0xC41951: buf_flush_try_neighbors(unsigned long, unsigned long, buf_flush_t, unsigned long, unsigned long) (buf0flu.cc:1324)
|
==16554== by 0xC41C76: buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) (buf0flu.cc:1412)
|
==16554== by 0xC42763: buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) (buf0flu.cc:1741)
|
==16554== by 0xC42AFD: buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, bool, flush_counters_t*) (buf0flu.cc:1817)
|
==16554== by 0xC43229: buf_flush_list(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:2097)
|
==16554== by 0xC43EBC: page_cleaner_do_flush_batch(unsigned long, unsigned long) (buf0flu.cc:2410)
|
==16554== by 0xC4513E: buf_flush_page_cleaner_thread (buf0flu.cc:2792)
|
==16554== by 0x4E3D0A3: start_thread (pthread_create.c:309)
|
==16554== by 0x6CB787C: clone (clone.S:111)
|
^ Found warnings in /data/bld/10.1-valgrind/mysql-test/var/log/mysqld.1.err
|
ok
|
I build with -DCMAKE_BUILD_TYPE=Debug -DWITH_VALGRIND=YES
|
|
elenst I am unable to repeat that one. But with a patch, I got Valgrind warnings for innodb.innodb_bug53290, both innodb_plugin and xtradb in 10.1:
==23742== Uninitialised byte(s) found during client check request
|
==23742== at 0xD96D51: row_merge_write_eof(unsigned char*, unsigned char*, int, unsigned long*, fil_space_crypt_struct*, unsigned char*, unsigned long) (row0merge.cc:1379)
|
My patch enables some extra InnoDB instrumentation for Valgrind:
diff --git a/storage/innobase/include/univ.i b/storage/innobase/include/univ.i
|
index 81190c3ad2e..4190b70d57c 100644
|
--- a/storage/innobase/include/univ.i
|
+++ b/storage/innobase/include/univ.i
|
@@ -172,7 +172,7 @@ command. Not tested on Windows. */
|
#define UNIV_COMPILE_TEST_FUNCS
|
*/
|
|
-#if defined(HAVE_valgrind)&& defined(HAVE_VALGRIND_MEMCHECK_H)
|
+#if defined(HAVE_valgrind) && defined(HAVE_VALGRIND)
|
# define UNIV_DEBUG_VALGRIND
|
#endif /* HAVE_VALGRIND */
|
#if 0
|
|
|
I was able to repeat the error on perro. Using vgdb and --manual-gdb, I got a stack trace with parameter values:
#0 0x0000000000d6dba1 in buf_page_is_checksum_valid_innodb (read_buf=0x1c81e000 "T-\273u", checksum_field1=1412283253, checksum_field2=603857976)
|
at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0buf.cc:653
|
#1 0x0000000000d6e002 in buf_page_is_corrupted (check_lsn=true, read_buf=0x1c81e000 "T-\273u", zip_size=0) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0buf.cc:859
|
#2 0x0000000000dff617 in fil_space_encrypt (space=4, offset=1, lsn=1629813, src_frame=0xfa20000 "T-\273u", zip_size=0, dst_frame=0x1c814000 "T-\273u")
|
at /home/mariadb/git/10.1-marko/storage/xtradb/fil/fil0crypt.cc:697
|
#3 0x0000000000d7a925 in buf_page_encrypt_before_write (bpage=0xf4706e0, src_frame=0xfa20000 "T-\273u", space_id=4) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0buf.cc:6366
|
#4 0x0000000000d871bf in buf_flush_write_block_low (bpage=0xf4706e0, flush_type=BUF_FLUSH_LIST, sync=false) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:950
|
#5 0x0000000000d8774c in buf_flush_page (buf_pool=0xbbaf878, bpage=0xf4706e0, flush_type=BUF_FLUSH_LIST, sync=false) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:1109
|
#6 0x0000000000d87db8 in buf_flush_try_neighbors (space=4, offset=1, flush_type=BUF_FLUSH_LIST, n_flushed=1, n_to_flush=100) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:1324
|
#7 0x0000000000d881b8 in buf_flush_page_and_try_neighbors (bpage=0xf4706e0, flush_type=BUF_FLUSH_LIST, n_to_flush=100, count=0x17403980) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:1412
|
#8 0x0000000000d88f23 in buf_do_flush_list_batch (buf_pool=0xbbaf878, min_n=100, lsn_limit=18446744073709551615) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:1741
|
#9 0x0000000000d8939d in buf_flush_batch (buf_pool=0xbbaf878, flush_type=BUF_FLUSH_LIST, min_n=100, lsn_limit=18446744073709551615, limited_lru_scan=false, n=0x17403ac0)
|
at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:1817
|
#10 0x0000000000d89ac7 in buf_flush_list (min_n=200, lsn_limit=18446744073709551615, n_processed=0x17403d88) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:2097
|
#11 0x0000000000d8ab1c in page_cleaner_do_flush_batch (n_to_flush=200, lsn_limit=18446744073709551615) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:2410
|
#12 0x0000000000d8c310 in buf_flush_page_cleaner_thread (arg=0x0) at /home/mariadb/git/10.1-marko/storage/xtradb/buf/buf0flu.cc:2792
|
offset=1 would be page number 1 or the change buffer bitmap page. That would be initialized by ibuf_bitmap_page_init(). All those calls are preceded by fsp_init_file_page() which zero-initializes the whole page. I do not know the encryption code well enough to be sure if it does something wrong. I tried adding a call to fil_encrypt_buf(), but that did not help:
if (!page_compressed) memset(dst_frame, 0, page_size);
|
vgdb did not fully work for me, so I was unable to determine the V bits so far.
|
|
I think I nailed it down:
==52984== Uninitialised byte(s) found during client check request
|
==52984== at 0xE0003D: fil_space_decrypt(fil_space_crypt_struct*, unsigned char*, unsigned long, unsigned char*, dberr_t*) (fil0crypt.cc:860)
|
…
|
/home/mariadb/git/10.1-marko/storage/xtradb/fil/fil0crypt.cc:856: 0x183464c0[16384] undefined at 38
|
Here is the relevant part of my patch. The memset() was a possibly futile/redundant attempt at fixing:
diff --git a/storage/xtradb/fil/fil0crypt.cc b/storage/xtradb/fil/fil0crypt.cc
|
index 2999bea2765..3c330152584 100644
|
--- a/storage/xtradb/fil/fil0crypt.cc
|
+++ b/storage/xtradb/fil/fil0crypt.cc
|
@@ -570,6 +570,8 @@ fil_encrypt_buf(
|
|
if (page_compressed) {
|
header_len += (FIL_PAGE_COMPRESSED_SIZE + FIL_PAGE_COMPRESSION_METHOD_SIZE);
|
+ } else {
|
+ memset(dst_frame, 0, page_size); // TODO: clear less
|
}
|
|
/* FIL page header is not encrypted */
|
@@ -851,6 +853,7 @@ fil_space_decrypt(
|
memset(tmp_frame + FIL_PAGE_FILE_FLUSH_LSN_OR_KEY_VERSION, 0, 8);
|
}
|
|
+ UNIV_MEM_ASSERT_RW(tmp_frame, page_size);
|
srv_stats.pages_decrypted.inc();
|
|
return true; /* page was decrypted */
|
|
|
Some more observations:
- The test creates and drops two encrypted tables.
- The calls to fil_space_encrypt() and fil_space_decrypt() for these tables are often missed when the DROP TABLE is executed soon enough. Usually the host perro does not miss the flush, but sometimes also it does miss it. On my laptop it was always missed.
- A flush of all pages can be forced by --source include/restart_mysqld.inc before the DROP TABLE statement.
- When the server is built -DWITH_SSL=bundled, there is no issue.
- One difference that -DWITH_SSL=bundled makes is that EVP_CipherUpdate() will be in mysys/yassl.cc instead of a dynamic library such as /lib/x86_64-linux-gnu/libcrypto.so.1.0.0
The next step is to repeat and diagnose the issue with vgdb using the default WITH_SSL setting.
|
|
The version of gdb installed on perro has some error in the remote target protocol that limits the use of vgdb. I cannot repeat the problem when using --manual-gdb and the system-default valgrind&vgdb. I think that we need a system where gdb and vgdb can play together and MariaDB can be compiled -DWITH_SSL=system.
One thing that should also be tested is the data file portability. Are the files portable between -DWITH_SSL=system and -DWITH_SSL=bundled?
|
|
For what it is worth, I cannot repeat this locally when building -DWITH_SSL=system and libssl1.0-dev version 1.0.2j-5.
|
|
I cannot repeat this with libssl 1.0.2g either. For what it is worth, perro has an older version installed: 1.0.1-4ubuntu5.12
|
|
Finally, I got access to a working vgdb on a system where this can be repeated. That system is using libssl1.0.0 version 1.0.1k-3+deb8u5.
Program received signal SIGTRAP, Trace/breakpoint trap.
|
[Switching to Thread 30899]
|
0x0000000000bfe891 in buf_page_is_checksum_valid_innodb (read_buf=0x1d01e000 "!\265\224\222", checksum_field1=565548178, checksum_field2=4272144276) at /home/buildbot/10.1/storage/xtradb/buf/buf0buf.cc:653
|
653 && checksum_field1 != buf_calc_page_new_checksum(read_buf)) {
|
(gdb) p srv_page_size
|
$1 = 16384
|
(gdb) monitor get_vbits 0x1d01e000 16384
|
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
|
00000000 0000ffff ffffffff ffffffff ffffffff ffff0000 00000000 00000000
|
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
|
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
|
The last 4 lines would repeat as is. This means that Valgrind thinks that every 8×4×4=128 bytes, there are 16 bytes that appear uninitialized (bit pattern 0xff).
It is possible that this has something to do with the data contents (most of the page is initialized to zero):
(gdb) p/x *read_buf@16384
|
$5 = {0x21, 0xb5, 0x94, 0x92, 0x0, 0x0, 0x0, 0x1, 0x0 <repeats 13 times>, 0x18, 0xde, 0x92, 0x0, 0x5, 0x0 <repeats 11 times>, 0x4, 0x0 <repeats 16338 times>, 0xfe, 0xa3, 0xbf, 0x94, 0x0, 0x18, 0xde, 0x92}
|
It could be a false alarm, because the contents of read_buf is identical to src_frame in fil_space_encrypt(). All V bits of src_frame are 0 (indicating that src_frame is fully initialized).
I think that we should test file compatibility between libssl1.0.0 versions 1.0.1 and 1.0.2, just in case. And maybe we should check the libssl changelog if there is anything about Valgrind.
|
|
As far as I understand, the OpenSSL (libcrypto.so) interface is in the file mysys_ssl/my_crypt.cc, for both AES encryption and decryption. The problem should be in one of the functions EVP_CipherInit_ex(), EVP_CipherUpdate(), or EVP_CipherFinal_ex(). In the bundled library, these are implemented in the file mysys_ssl/yassl.cc.
The OpenSSL FAQ 14 suggests compiling the library with -DPURIFY in order to avoid errors related to the way how the random number generator in OpenSSL works. We are using my_random_bytes() to initialize st_encryption_scheme::iv. If Valgrind thinks that some bits there are uninitialized, that would explain the problem. Other than that, I have hard time believing that a symmetric in-place cipher such as AES could depend on a random number generator.
|
|
I cannot repeat this failure any more on perro (using valgrind-3.7.0 and libssl1.0.0 version 1.0.1-4ubuntu5.12), either MariaDB 10.1 or 10.2. During the test
./mtr --manual-gdb encryption.innodb_encryption_is,cbc,xtradb
|
InnoDB is invoking my_random_bytes() for 16 bytes twice, and both times, Valgrind 3.7.0 (using vgdb and the gdb command monitor get_vbits) tells that all 16 bytes are fully initialized.
So, it looks like something has been fixed in the environment since I last checked this. I really should have checked the initialization vector last time when I repeated the issue (and judged that it is a false alarm).
|
|
I think something was wrong with the experiment above. Not only it makes no sense to try with the ancient valgrind 3.7.0, but also it doesn't even work with the current 10.1 tree, it fails as
CURRENT_TEST: encryption.innodb_encryption_is
|
valgrind: Bad option: --soname-synonyms=somalloc=libjemalloc*
|
valgrind: Use --help for more information or consult the user manual.
|
So I can't see how it could pass.
Anyway, it's reproducible just as it was with e.g. valgrind 3.12.0
|
10.1 68d632bc5a1437282dde5460b7a0d3d887fd5483
|
==33860== Thread 15:
|
==33860== Conditional jump or move depends on uninitialised value(s)
|
==33860== at 0xC519F40: buf_page_is_checksum_valid_innodb(unsigned char const*, unsigned long, unsigned long) (buf0buf.cc:572)
|
==33860== by 0xC51A43F: buf_page_is_corrupted(bool, unsigned char const*, unsigned long, fil_space_t const*) (buf0buf.cc:780)
|
==33860== by 0xC5A86BF: fil_space_encrypt(unsigned long, unsigned long, unsigned long, unsigned char*, unsigned long, unsigned char*) (fil0crypt.cc:700)
|
==33860== by 0xC526FE5: buf_page_encrypt_before_write(buf_page_t*, unsigned char*, unsigned long) (buf0buf.cc:6152)
|
==33860== by 0xC5332C1: buf_flush_write_block_low(buf_page_t*, buf_flush_t, bool) (buf0flu.cc:909)
|
==33860== by 0xC5337E7: buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1058)
|
==33860== by 0xC533F24: buf_flush_try_neighbors(unsigned long, unsigned long, buf_flush_t, unsigned long, unsigned long) (buf0flu.cc:1266)
|
==33860== by 0xC534308: buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) (buf0flu.cc:1340)
|
==33860== by 0xC534E18: buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) (buf0flu.cc:1583)
|
==33860== by 0xC535245: buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, flush_counters_t*) (buf0flu.cc:1646)
|
==33860== by 0xC5357DB: buf_flush_list(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:1841)
|
==33860== by 0xC536611: page_cleaner_do_flush_batch(unsigned long, unsigned long) (buf0flu.cc:2052)
|
==33860== by 0xC537A57: buf_flush_page_cleaner_thread (buf0flu.cc:2320)
|
==33860== by 0x6108E99: start_thread (pthread_create.c:308)
|
==33860== by 0x6A11CBC: clone (clone.S:112)
|
==33860== Conditional jump or move depends on uninitialised value(s)
|
==33860== at 0x4C30626: __memcmp_sse4_1 (vg_replace_strmem.c:1094)
|
==33860== by 0xC5A86D9: fil_space_encrypt(unsigned long, unsigned long, unsigned long, unsigned char*, unsigned long, unsigned char*) (fil0crypt.cc:701)
|
==33860== by 0xC526FE5: buf_page_encrypt_before_write(buf_page_t*, unsigned char*, unsigned long) (buf0buf.cc:6152)
|
==33860== by 0xC5332C1: buf_flush_write_block_low(buf_page_t*, buf_flush_t, bool) (buf0flu.cc:909)
|
==33860== by 0xC5337E7: buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1058)
|
==33860== by 0xC533F24: buf_flush_try_neighbors(unsigned long, unsigned long, buf_flush_t, unsigned long, unsigned long) (buf0flu.cc:1266)
|
==33860== by 0xC534308: buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) (buf0flu.cc:1340)
|
==33860== by 0xC534E18: buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) (buf0flu.cc:1583)
|
==33860== by 0xC535245: buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, flush_counters_t*) (buf0flu.cc:1646)
|
==33860== by 0xC5357DB: buf_flush_list(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:1841)
|
==33860== by 0xC536611: page_cleaner_do_flush_batch(unsigned long, unsigned long) (buf0flu.cc:2052)
|
==33860== by 0xC537A57: buf_flush_page_cleaner_thread (buf0flu.cc:2320)
|
==33860== by 0x6108E99: start_thread (pthread_create.c:308)
|
==33860== by 0x6A11CBC: clone (clone.S:112)
|
|
|
elenst, indeed, if I try to start the test with ./mtr --valgrind (which I would never use when debugging), then valgrind 3.7.0 will indeed complain about the unrecognized option --soname-synonyms which was added already in 2015.
It looks like I used an almost year-old revision of 10.1.14 where I was unable to repeat the problem.
I can repeat the problem with 10.1-mdev11686 on perro, when running --manual-gdb and starting Valgrind+gdb instead of gdb.
Just like with the older revision that I tested, there is a fault at startup, which might be suppressed in --valgrind (I did not use any suppressions). And according to Valgrind, the crypt_data.iv is fully set.
…
|
2017-03-06 19:17:54 366200576 [Note] InnoDB: Dumping buffer pool(s) not yet started
|
==57931== Conditional jump or move depends on uninitialised value(s)
|
==57931== at 0x5C385BC: ASN1_STRING_set (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
|
==57931== by 0x5C262AC: ASN1_mbstring_ncopy (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
|
==57931== by 0x5C264A3: ASN1_mbstring_copy (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
|
==57931== by 0x5C2740C: ASN1_STRING_to_UTF8 (in /lib/x86_64-linux-gnu/libcrypto.so.1.0.0)
|
…
|
==57931== Continuing ...
|
2017-03-06 19:18:15 67314496 [Note] Server socket created on IP: '127.0.0.1'.
|
2017-03-06 19:18:15 67314496 [Note] /home/mariadb/git/10.1-mdev11686/sql/mysqld: ready for connections.
|
Version: '10.1.22-MariaDB-debug' socket: '/home/mariadb/git/10.1-mdev11686/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution
|
2017-03-06 19:18:16 68254464 [Note] InnoDB: Created tablespace for space 4 name test/t1 key_id 1 encryption 1.
|
==57931== Thread 10:
|
==57931== Conditional jump or move depends on uninitialised value(s)
|
==57931== at 0xC519F40: buf_page_is_checksum_valid_innodb(unsigned char const*, unsigned long, unsigned long) (buf0buf.cc:572)
|
…
|
Program received signal SIGTRAP, Trace/breakpoint trap.
|
[Switching to Thread 58112]
|
0x000000000c519f40 in buf_page_is_checksum_valid_innodb (
|
read_buf=0xd61a780 "!\265\224\222", checksum_field1=565548178,
|
checksum_field2=4272144276)
|
at /home/mariadb/git/10.1-mdev11686/storage/innobase/buf/buf0buf.cc:572
|
572 && checksum_field1 != buf_calc_page_new_checksum(read_buf)) {
|
(gdb) up
|
#1 0x000000000c51a440 in buf_page_is_corrupted (check_lsn=true,
|
read_buf=0xd61a780 "!\265\224\222", zip_size=0, space=0xd60d468)
|
at /home/mariadb/git/10.1-mdev11686/storage/innobase/buf/buf0buf.cc:780
|
780 if (buf_page_is_checksum_valid_innodb(read_buf,
|
(gdb) up
|
#2 0x000000000c5a86c0 in fil_space_encrypt (space=4, offset=1, lsn=1629842,
|
src_frame=0xe7b0000 "!\265\224\222", zip_size=0,
|
dst_frame=0xd614000 "!\265\224\222")
|
at /home/mariadb/git/10.1-mdev11686/storage/innobase/fil/fil0crypt.cc:700
|
700 bool corrupted = buf_page_is_corrupted(true, tmp_mem, zip_size, tspace);
|
(gdb) p crypt_data.iv
|
$1 = "\245\373\302\n&!=\202MWL\243\357)8}"
|
(gdb) p crypt_data
|
$2 = (fil_space_crypt_t *) 0x11dbe308
|
(gdb) p &crypt_data.iv
|
$3 = (unsigned char (*)[16]) 0x11dbe308
|
(gdb) monitor get_vbits 0x11dbe308 16
|
00000000 00000000 00000000 00000000
|
(gdb) monitor get_vbits 0xe7b000 16384
|
[snip an output of 16384 zeros, indicating that src_frame in fil_space_encrypt() is fully initialized]
|
(gdb) p/x *src_frame@16384
|
$5 = {0x21, 0xb5, 0x94, 0x92, 0x0, 0x0, 0x0, 0x1, 0x0 <repeats 13 times>,
|
0x18, 0xde, 0x92, 0x0, 0x5, 0x0 <repeats 11 times>, 0x4,
|
0x0 <repeats 16338 times>, 0xfe, 0xa3, 0xbf, 0x94, 0x0, 0x18, 0xde, 0x92}
|
(gdb) p/x *tmp_mem@16384
|
$6 = {0x21, 0xb5, 0x94, 0x92, 0x0, 0x0, 0x0, 0x1, 0x0 <repeats 13 times>,
|
0x18, 0xde, 0x92, 0x0, 0x5, 0x0 <repeats 11 times>, 0x4,
|
0x0 <repeats 16338 times>, 0xfe, 0xa3, 0xbf, 0x94, 0x0, 0x18, 0xde, 0x92}
|
# Note that the two buffers above are identical!
|
(gdb) p tmp_mem
|
$7 = (unsigned char *) 0xd61a780 "!\265\224\222"
|
(gdb) monitor get_vbits 0xd61a780 16384
|
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
|
00000000 0000ffff ffffffff ffffffff ffffffff ffff0000 00000000 00000000
|
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
|
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
|
…
|
This still looks like a wrong alarm, just like last time. This time I only confirmed that the cause cannot be that Valgrind would think that the initialization vector contains uninitialized bits.
I believe that some arithmetic operations in the libssl 1.0.1 AES implementation could be confusing the V-bit bookkeeping of Valgrind. The bookkeeping is not foolproof, and some work-arounds could have been optimized away by recent compilers; see for example MDEV-11349 commit 2/2.
Still, it is worth noting that I did not repeat the issue with the 10.1 commit from April 2016 nor with a July 2016 revision. It turns out that some debug code to decrypt a copy of the page immediately after encryption was added in MDEV-9931, September 22, 2016.
I suspect that Valgrind would complain about decryption even with earlier versions, but that would require a different type of a test:
- start the server with encryption
- create and populate an encrypted table
- restart the server
- read from the encrypted table
Do we want to track this down further? Do we want to add some VALGRIND_MAKE_MEM_DEFINED() to MariaDB, conditional on the libssl1.0.0 version, to suppress this? (I would definitely not want to suppress anything for the 1.0.2 and later versions of libssl1.0.0.)
|
|
Indeed, I cannot reproduce it on Xenial with libssl 1.0.2g.
I can still reproduce it on Jessie with libssl 1.0.1t and valgrind 3.12.0 (and 3.10.0). It happens reliably when I run the test on disk, and much less reliably when I run it in shm – maybe it just does not do flush in time?
I'm still not sure what to do about it – to try to add a suppression, or just tolerate it since it does not show up in valgrind tests on buildbot, – but since it's clearly not a 10.2 problem and, according to Marko's comment above, not a critical problem, I'm demoting it from Critical to Minor and removing 10.2-ga label.
|
|
I wonder if this one could be closed.
|
|
The failure disappeared in two steps.
First, after this commit in 10.1.34,
commit f5eb37129f24893ab095e78c6fd2ef87e2c460cf
|
Author: Marko Mäkelä <marko.makela@mariadb.com>
|
Date: Wed Jun 13 16:15:21 2018 +0300
|
|
MDEV-13103 Deal with page_compressed page corruption
|
the first part went away and only the second part left:
==15757== Thread 16:
|
==15757== Conditional jump or move depends on uninitialised value(s)
|
==15757== at 0x4C2ED52: __memcmp_sse4_1 (vg_replace_strmem.c:972)
|
==15757== by 0xC62C79: fil_space_encrypt(fil_space_t const*, unsigned long, unsigned long, unsigned char*, unsigned char*) (fil0crypt.cc:745)
|
==15757== by 0xBEA6E2: buf_page_encrypt_before_write(fil_space_t*, buf_page_t*, unsigned char*) (buf0buf.cc:6413)
|
==15757== by 0xBF611B: buf_flush_write_block_low(buf_page_t*, buf_flush_t, bool) (buf0flu.cc:964)
|
==15757== by 0xBF6727: buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool) (buf0flu.cc:1140)
|
==15757== by 0xBF6CF9: buf_flush_try_neighbors(unsigned long, unsigned long, buf_flush_t, unsigned long, unsigned long) (buf0flu.cc:1355)
|
==15757== by 0xBF701E: buf_flush_page_and_try_neighbors(buf_page_t*, buf_flush_t, unsigned long, unsigned long*) (buf0flu.cc:1443)
|
==15757== by 0xBF7B08: buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long) (buf0flu.cc:1772)
|
==15757== by 0xBF7E9F: buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, bool, flush_counters_t*) (buf0flu.cc:1848)
|
==15757== by 0xBF85CB: buf_flush_list(unsigned long, unsigned long, unsigned long*) (buf0flu.cc:2128)
|
==15757== by 0xBF9281: page_cleaner_do_flush_batch(unsigned long, unsigned long) (buf0flu.cc:2443)
|
==15757== by 0xBFA562: buf_flush_page_cleaner_thread (buf0flu.cc:2842)
|
==15757== by 0x4E3D0A3: start_thread (pthread_create.c:309)
|
==15757== by 0x6E7262C: clone (clone.S:111)
|
Then very recently, after this commit,
commit 0b36c27e0c06b798b7322ab07d8464b69a7b716c
|
Author: Marko Mäkelä <marko.makela@mariadb.com>
|
Date: Fri Jan 31 10:06:55 2020 +0200
|
|
MDEV-20307: Remove a useless debug check to save stack space
|
the remaining part disappeared as well, and the test now passes.
marko, if you're okay with both – that is, if it's an expected result and not just masking effect – please feel free to close it.
|
|
elenst, thank you for the observation. In MDEV-20307 I indeed removed the debug check from fil_space_encrypt() that would ensure that the page decompresses correctly. The check was useless, because we do have enough test coverage where an encrypted page will be read and decrypted from a data file. Any test that involves server restart or recovery or backup of encrypted tables should do that.
Valgrind was not happy about that debug check, either because its V bits tracking got confused by the encryption code, or because there indeed was something wrong with that check. Either way, the code has been removed now.
I know that Valgrind has correctness problems with some bitwise operations, and my attempts at working around those problems only seem to work on GCC, not recent versions of clang. An example of attempting to please Valgrind when using clang is MDEV-11349.
|