From 599ff0f688436d0d984058d41fb0b911b9a0a1a1 Mon Sep 17 00:00:00 2001 From: Andrew Kryczka Date: Mon, 4 Apr 2022 22:17:35 -0700 Subject: [PATCH 1/2] Fix GetMergeOperands() heap-use-after-free on flushed memtable The unit test repro gives the following error prior to the fix: ``` ==2175705==ERROR: AddressSanitizer: heap-use-after-free on address 0x61f0000012a5 at pc 0x7f0fc36e76ce bp 0x7ffc103e9ca0 sp 0x7ffc103e9450 READ of size 5 at 0x61f0000012a5 thread T0 #0 0x7f0fc36e76cd in __interceptor_memcpy /home/engshare/third-party2/gcc/9.x/src/gcc-10.x/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:790 #1 0x7f0fc35a207e in std::char_traits::copy(char*, char const*, unsigned long) /home/engshare/third-party2/libgcc/9.x/src/gcc-9.x/x86_64-facebook-linux/libstdc++-v3/include/bits/char_traits.h:365 #2 0x7f0fc35a207e in std::__cxx11::basic_string, std::allocator >::_S_copy(char*, char const*, unsigned long) /home/engshare/third-party2/libgcc/9.x/src/gcc-9.x/x86_64-facebook-linux/libstdc++-v3/include/bits/basic_string.h:351 #3 0x7f0fc35a207e in std::__cxx11::basic_string, std::allocator >::_M_replace(unsigned long, unsigned long, char const*, unsigned long) /home/engshare/third-party2/libgcc/9.x/src/gcc-9.x/x86_64-facebook-linux/libstdc++-v3/include/bits/basic_string.tcc:440 #4 0x8679ca in std::__cxx11::basic_string, std::allocator >::assign(char const*, unsigned long) /mnt/gvfs/third-party2/libgcc/4959b39cfbe5965a37c861c4c327fa7c5c759b87/9.x/platform009/9202ce7/include/c++/9.3.0/bits/basic_string.h:1422 #5 0x8679ca in rocksdb::PinnableSlice::PinSelf(rocksdb::Slice const&) include/rocksdb/slice.h:171 #6 0x8679ca in rocksdb::DBImpl::GetImpl(rocksdb::ReadOptions const&, rocksdb::Slice const&, rocksdb::DBImpl::GetImplOptions&) db/db_impl/db_impl.cc:1930 #7 0x547324 in rocksdb::DBImpl::GetMergeOperands(rocksdb::ReadOptions const&, rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&, rocksdb::PinnableSlice*, rocksdb::GetMergeOperandsOptions*, int*) db/db_impl/db_impl.h:203 #8 0x547324 in rocksdb::DBMergeOperandTest_FlushedMergeOperandReadAfterFreeBug_Test::TestBody() db/db_merge_operand_test.cc:117 #9 0x7241da in void testing::internal::HandleSehExceptionsInMethodIfSupported(testing::Test*, void (testing::Test::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3899 #10 0x7241da in void testing::internal::HandleExceptionsInMethodIfSupported(testing::Test*, void (testing::Test::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3935 #11 0x701a47 in testing::Test::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3973 #12 0x702040 in testing::Test::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3965 #13 0x702040 in testing::TestInfo::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4149 #14 0x7025f7 in testing::TestInfo::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4124 #15 0x7025f7 in testing::TestCase::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4267 #16 0x704217 in testing::TestCase::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4253 #17 0x704217 in testing::internal::UnitTestImpl::RunAllTests() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:6633 #18 0x72505a in bool testing::internal::HandleSehExceptionsInMethodIfSupported(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3899 #19 0x72505a in bool testing::internal::HandleExceptionsInMethodIfSupported(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3935 #20 0x704aa1 in testing::UnitTest::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:6242 #21 0x4c4aff in RUN_ALL_TESTS() third-party/gtest-1.8.1/fused-src/gtest/gtest.h:22110 #22 0x4c4aff in main db/db_merge_operand_test.cc:404 #23 0x7f0fc3108dc4 in __libc_start_main ../csu/libc-start.c:308 #24 0x5445fd in _start (/data/users/andrewkr/rocksdb/db_merge_operand_test+0x5445fd) 0x61f0000012a5 is located 1061 bytes inside of 3264-byte region [0x61f000000e80,0x61f000001b40) freed by thread T0 here: #0 0x7f0fc375b6af in operator delete(void*, unsigned long) /home/engshare/third-party2/gcc/9.x/src/gcc-10.x/libsanitizer/asan/asan_new_delete.cc:177 #1 0x743be8 in rocksdb::SuperVersion::~SuperVersion() db/column_family.cc:432 #2 0x8052aa in rocksdb::DBImpl::CleanupSuperVersion(rocksdb::SuperVersion*) db/db_impl/db_impl.cc:3534 #3 0x8676c2 in rocksdb::DBImpl::ReturnAndCleanupSuperVersion(rocksdb::ColumnFamilyData*, rocksdb::SuperVersion*) db/db_impl/db_impl.cc:3544 #4 0x8676c2 in rocksdb::DBImpl::GetImpl(rocksdb::ReadOptions const&, rocksdb::Slice const&, rocksdb::DBImpl::GetImplOptions&) db/db_impl/db_impl.cc:1911 #5 0x547324 in rocksdb::DBImpl::GetMergeOperands(rocksdb::ReadOptions const&, rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&, rocksdb::PinnableSlice*, rocksdb::GetMergeOperandsOptions*, int*) db/db_impl/db_impl.h:203 #6 0x547324 in rocksdb::DBMergeOperandTest_FlushedMergeOperandReadAfterFreeBug_Test::TestBody() db/db_merge_operand_test.cc:117 #7 0x7241da in void testing::internal::HandleSehExceptionsInMethodIfSupported(testing::Test*, void (testing::Test::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3899 #8 0x7241da in void testing::internal::HandleExceptionsInMethodIfSupported(testing::Test*, void (testing::Test::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3935 #9 0x701a47 in testing::Test::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3973 #10 0x702040 in testing::Test::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3965 #11 0x702040 in testing::TestInfo::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4149 #12 0x7025f7 in testing::TestInfo::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4124 #13 0x7025f7 in testing::TestCase::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4267 #14 0x704217 in testing::TestCase::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:4253 #15 0x704217 in testing::internal::UnitTestImpl::RunAllTests() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:6633 #16 0x72505a in bool testing::internal::HandleSehExceptionsInMethodIfSupported(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3899 #17 0x72505a in bool testing::internal::HandleExceptionsInMethodIfSupported(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:3935 #18 0x704aa1 in testing::UnitTest::Run() third-party/gtest-1.8.1/fused-src/gtest/gtest-all.cc:6242 #19 0x4c4aff in RUN_ALL_TESTS() third-party/gtest-1.8.1/fused-src/gtest/gtest.h:22110 #20 0x4c4aff in main db/db_merge_operand_test.cc:404 #21 0x7f0fc3108dc4 in __libc_start_main ../csu/libc-start.c:308 #22 0x5445fd in _start (/data/users/andrewkr/rocksdb/db_merge_operand_test+0x5445fd) ... ``` Test Plan: following the fix in this PR, the unit test passes --- db/db_impl/db_impl.cc | 6 ++++-- db/db_merge_operand_test.cc | 37 ++++++++++++++++++++++++++++++++++++- 2 files changed, 40 insertions(+), 3 deletions(-) diff --git a/db/db_impl/db_impl.cc b/db/db_impl/db_impl.cc index 98709dd92da..e4b275e569c 100644 --- a/db/db_impl/db_impl.cc +++ b/db/db_impl/db_impl.cc @@ -1889,6 +1889,8 @@ Status DBImpl::GetImpl(const ReadOptions& read_options, const Slice& key, return s; } } + TEST_SYNC_POINT("DBImpl::GetImpl:PostMemTableGet:0"); + TEST_SYNC_POINT("DBImpl::GetImpl:PostMemTableGet:1"); PinnedIteratorsManager pinned_iters_mgr; if (!done) { PERF_TIMER_GUARD(get_from_output_files_time); @@ -1906,8 +1908,6 @@ Status DBImpl::GetImpl(const ReadOptions& read_options, const Slice& key, { PERF_TIMER_GUARD(get_post_process_time); - ReturnAndCleanupSuperVersion(cfd, sv); - RecordTick(stats_, NUMBER_KEYS_READ); size_t size = 0; if (s.ok()) { @@ -1934,6 +1934,8 @@ Status DBImpl::GetImpl(const ReadOptions& read_options, const Slice& key, PERF_COUNTER_ADD(get_read_bytes, size); } RecordInHistogram(stats_, BYTES_PER_READ, size); + + ReturnAndCleanupSuperVersion(cfd, sv); } return s; } diff --git a/db/db_merge_operand_test.cc b/db/db_merge_operand_test.cc index f00c6872ff3..6be90e1d33f 100644 --- a/db/db_merge_operand_test.cc +++ b/db/db_merge_operand_test.cc @@ -47,7 +47,7 @@ class DBMergeOperandTest : public DBTestBase { : DBTestBase("db_merge_operand_test", /*env_do_fsync=*/true) {} }; -TEST_F(DBMergeOperandTest, MergeOperandReadAfterFreeBug) { +TEST_F(DBMergeOperandTest, CacheEvictedMergeOperandReadAfterFreeBug) { // There was a bug of reading merge operands after they are mistakely freed // in DB::GetMergeOperands, which is surfaced by cache full. // See PR#9507 for more. @@ -86,6 +86,41 @@ TEST_F(DBMergeOperandTest, MergeOperandReadAfterFreeBug) { ASSERT_EQ(values[3].ToString(), "v4"); } +TEST_F(DBMergeOperandTest, FlushedMergeOperandReadAfterFreeBug) { + // Repro for a bug where a memtable containing a merge operand could be + // deleted before the merge operand was saved to the result. + auto options = CurrentOptions(); + options.merge_operator = MergeOperators::CreateStringAppendOperator(); + Reopen(options); + + ASSERT_OK(Merge("key", "value")); + + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->LoadDependency( + {{"DBImpl::GetImpl:PostMemTableGet:0", + "DBMergeOperandTest::FlushedMergeOperandReadAfterFreeBug:PreFlush"}, + {"DBMergeOperandTest::FlushedMergeOperandReadAfterFreeBug:PostFlush", + "DBImpl::GetImpl:PostMemTableGet:1"}}); + ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->EnableProcessing(); + + auto flush_thread = port::Thread([&]() { + TEST_SYNC_POINT( + "DBMergeOperandTest::FlushedMergeOperandReadAfterFreeBug:PreFlush"); + ASSERT_OK(Flush()); + TEST_SYNC_POINT( + "DBMergeOperandTest::FlushedMergeOperandReadAfterFreeBug:PostFlush"); + }); + + PinnableSlice value; + GetMergeOperandsOptions merge_operands_info; + merge_operands_info.expected_max_number_of_operands = 1; + int number_of_operands; + ASSERT_OK(db_->GetMergeOperands(ReadOptions(), db_->DefaultColumnFamily(), + "key", &value, &merge_operands_info, + &number_of_operands)); + + flush_thread.join(); +} + TEST_F(DBMergeOperandTest, GetMergeOperandsBasic) { Options options; options.create_if_missing = true; From 480d4083d8aa2dbd3d90df73690d3408c4320432 Mon Sep 17 00:00:00 2001 From: Andrew Kryczka Date: Mon, 4 Apr 2022 22:21:51 -0700 Subject: [PATCH 2/2] test slightly more --- db/db_merge_operand_test.cc | 1 + 1 file changed, 1 insertion(+) diff --git a/db/db_merge_operand_test.cc b/db/db_merge_operand_test.cc index 6be90e1d33f..bca35b258e1 100644 --- a/db/db_merge_operand_test.cc +++ b/db/db_merge_operand_test.cc @@ -117,6 +117,7 @@ TEST_F(DBMergeOperandTest, FlushedMergeOperandReadAfterFreeBug) { ASSERT_OK(db_->GetMergeOperands(ReadOptions(), db_->DefaultColumnFamily(), "key", &value, &merge_operands_info, &number_of_operands)); + ASSERT_EQ(1, number_of_operands); flush_thread.join(); }