WriteBatchThreadedTest heap-use-after-free

[adamretter]

Run: org.rocksdb.WriteBatchThreadedTest testing now -> threadedWrites[WriteBatchThreadedTest(threadCount=1)]
Run: org.rocksdb.WriteBatchThreadedTest testing now -> threadedWrites[WriteBatchThreadedTest(threadCount=10)]   
Run: org.rocksdb.WriteBatchThreadedTest testing now -> threadedWrites[WriteBatchThreadedTest(threadCount=50)]   
=================================================================
==31683==ERROR: AddressSanitizer: heap-use-after-free on address 0x0b000030e948 at pc 0x3fff632ac024 bp 0x3fff60ffa750 sp 0x3fff60ffa770
READ of size 1 at 0x0b000030e948 thread T2604 (pool-4-thread-2)
==31683==AddressSanitizer: while reporting a bug found another one. Ignoring.
    #0 0x3fff632ac020 in rocksdb::Slice::operator[](unsigned long) const include/rocksdb/slice.h:65
    #1 0x3fff63747204 in rocksdb::ReadRecordFromWriteBatch(rocksdb::Slice*, char*, unsigned int*, rocksdb::Slice*, rocksdb::Slice*, rocksdb::Slice*, rocksdb::Slice*) db/write_batch.cc:283
    #2 0x3fff63747e74 in rocksdb::WriteBatch::Iterate(rocksdb::WriteBatch::Handler*) const db/write_batch.cc:377
    #3 0x3fff6374df10 in rocksdb::WriteBatchInternal::InsertInto(rocksdb::WriteThread::Writer*, rocksdb::ColumnFamilyMemTables*, rocksdb::FlushScheduler*, bool, unsigned long, rocksdb::DB*, bool)
 db/write_batch.cc:1328
    #4 0x3fff634e9470 in rocksdb::DBImpl::WriteImpl(rocksdb::WriteOptions const&, rocksdb::WriteBatch*, rocksdb::WriteCallback*, unsigned long*, unsigned long, bool) db/db_impl_write.cc:95
    #5 0x3fff634e8db0 in rocksdb::DBImpl::Write(rocksdb::WriteOptions const&, rocksdb::WriteBatch*) db/db_impl_write.cc:50
    #6 0x3fff63280a90 in Java_org_rocksdb_RocksDB_write0 java/rocksjni/rocksjni.cc:382
    #7 0x3fff665ff71c  (<unknown module>)

0x0b000030e948 is located 2248 bytes inside of 3841-byte region [0x0b000030e080,0x0b000030ef81)
freed by thread T22 (Finalizer threa) here:
    #0 0x3fff7bc9d4c0 in operator delete(void*) (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0xbd4c0)   
    #1 0x3fff77797554 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() (/usr/lib/powerpc64le-linux-gnu/libstdc++.so.6+0x177554)
    #2 0x3fff637461e8 in rocksdb::WriteBatch::~WriteBatch() db/write_batch.cc:172
    #3 0x3fff63746260 in rocksdb::WriteBatch::~WriteBatch() db/write_batch.cc:172
    #4 0x3fff632bb808 in Java_org_rocksdb_WriteBatch_disposeInternal java/rocksjni/write_batch.cc:288
    #5 0x3fff665ff98c  (<unknown module>)

previously allocated by thread T2604 (pool-4-thread-2) here:
    #0 0x3fff7bc9cd80 in operator new(unsigned long) (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0xbcd80)
    #1 0x3fff77796a08 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_create(unsigned long&, unsigned long) (/usr/lib/powerpc64le-linux-gnu/libstdc++.so.6+0
x176a08)
    #2 0x3fff77797228 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_mutate(unsigned long, unsigned long, char const*, unsigned long) (/usr/lib/powerpc64le
-linux-gnu/libstdc++.so.6+0x177228)
    #3 0x3fff777997e4 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_append(char const*, unsigned long) (/usr/lib/powerpc64le-linux-gnu/libstdc++.so.6+0x17
97e4)
    #4 0x3fff7779999c in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::append(char const*, unsigned long) (/usr/lib/powerpc64le-linux-gnu/libstdc++.so.6+0x17999
c)
    #5 0x3fff636ca740 in rocksdb::PutLengthPrefixedSlice(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >*, rocksdb::Slice const&) util/coding.h:249
    #6 0x3fff63749554 in rocksdb::WriteBatchInternal::Put(rocksdb::WriteBatch*, unsigned int, rocksdb::Slice const&, rocksdb::Slice const&) db/write_batch.cc:489
    #7 0x3fff63749834 in rocksdb::WriteBatch::Put(rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&, rocksdb::Slice const&) db/write_batch.cc:499
    #8 0x3fff63337230 in rocksdb::WriteBatch::Put(rocksdb::Slice const&, rocksdb::Slice const&) include/rocksdb/write_batch.h:71
    #9 0x3fff632b8a24 in Java_org_rocksdb_WriteBatch_put__J_3BI_3BI::{lambda(rocksdb::Slice, rocksdb::Slice)#1}::operator()(rocksdb::Slice, rocksdb::Slice) const (/tmp/librocksdbjni1000713311211598828.so+0xb48a24)
    #10 0x3fff632bc948 in _M_invoke /usr/include/c++/5/functional:1871
    #11 0x3fff632c2498 in std::function<void (rocksdb::Slice, rocksdb::Slice)>::operator()(rocksdb::Slice, rocksdb::Slice) const /usr/include/c++/5/functional:2267
    #12 0x3fff632c1fe4 in rocksdb::JniUtil::kv_op(std::function<void (rocksdb::Slice, rocksdb::Slice)>, JNIEnv_*, _jobject*, _jbyteArray*, int, _jbyteArray*, int) java/./rocksjni/portal.h:2655
    #13 0x3fff632b8c10 in Java_org_rocksdb_WriteBatch_put__J_3BI_3BI java/rocksjni/write_batch.cc:108
    #14 0x3fff66621d54  (<unknown module>)

Thread T2604 (pool-4-thread-2) created by T1 (main) here:
    #0 0x3fff7bc1aabc in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3aabc)
    #1 0x3fff7bc1ac68 in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3ac68)
    #2 0x3fff789c41bc in osthread_create (/opt/ibm/java-ppc64le-71/jre/lib/ppc64le/compressedrefs/libj9thr27.so+0x141bc)

Thread T1 (main) created by T0 here:
    #0 0x3fff7bc1aabc in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3aabc)
    #1 0x3fff7bc1ac68 in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3ac68)
    #2 0x3fff7bb74388 in ContinueInNewThread0 (/opt/ibm/java-ppc64le-71/jre/bin/../lib/ppc64le/jli/libjli.so+0x14388)

Thread T22 (Finalizer threa) created by T11 (Finalizer maste) here:
    #0 0x3fff7bc1aabc in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3aabc)
    #1 0x3fff7bc1ac68 in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3ac68)
    #2 0x3fff789c41bc in osthread_create (/opt/ibm/java-ppc64le-71/jre/lib/ppc64le/compressedrefs/libj9thr27.so+0x141bc)

Thread T11 (Finalizer maste) created by T1 (main) here:
    #0 0x3fff7bc1aabc in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3aabc)
    #1 0x3fff7bc1ac68 in __interceptor_pthread_create (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0x3ac68)
    #2 0x3fff789c41bc in osthread_create (/opt/ibm/java-ppc64le-71/jre/lib/ppc64le/compressedrefs/libj9thr27.so+0x141bc)

SUMMARY: AddressSanitizer: heap-use-after-free include/rocksdb/slice.h:65 rocksdb::Slice::operator[](unsigned long) const
Shadow bytes around the buggy address:
  0x036000061cd0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061ce0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061cf0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061d00: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061d10: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x036000061d20: fd fd fd fd fd fd fd fd fd[fd]fd fd fd fd fd fd
  0x036000061d30: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061d40: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061d50: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061d60: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x036000061d70: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Heap right redzone:      fb
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack partial redzone:   f4
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
==31683==ABORTING
Makefile:222: recipe for target 'run_test' failed
make[1]: *** [run_test] Error 1
make[1]: Leaving directory '/home/ubuntu/rocksdb/java'
Makefile:1632: recipe for target 'jtest_run' failed
make: *** [jtest_run] Error 2

[yiwu-arbug]

@adamretter How can I compile java test with ASAN? I'm trying to reproduce.

[adamretter]

@yiwu-arbug details are here - https://github.com/facebook/rocksdb/wiki/JNI-Debugging#asan

[yiwu-arbug]

@adamretter nice wiki!

[siying]

@maysamyabandeh did this hack and the error seems go away:

diff --git a/java/src/test/java/org/rocksdb/WriteBatchThreadedTest.java b/java/src/test/java/org/rocksdb/WriteBatchThreadedTest.java
index 66e1c896..923171a4 100644
--- a/java/src/test/java/org/rocksdb/WriteBatchThreadedTest.java
+++ b/java/src/test/java/org/rocksdb/WriteBatchThreadedTest.java
@@ -66,6 +66,9 @@ public class WriteBatchThreadedTest {
           }
           db.write(new WriteOptions(), wb);

+            wb.put(ByteBuffer.allocate(4).putInt(0).array(),
+                "parallel rocks test".getBytes());
+
           return null;
         }
       });

The theory we have is that, in the write function in RocksDB.java:

  public void write(final WriteOptions writeOpts, final WriteBatch updates)
      throws RocksDBException {
    write0(nativeHandle_, writeOpts.nativeHandle_, updates.nativeHandle_);
  }

Since we get the value of updates.nativeHandle_, Java thinks the write batch is not needed anymore, so it is GCed and executed the finalizer containing the C++ write batch, which is still being used in the native function write0().

CC @sagar0

[siying]

@yiwu-arbug and @maysamyabandeh did another test where we explicitly call wb.close() and the test failure seems to go away.

[adamretter]

@siying I am back in the office now after a short visit back to the UK. I can take a look tomorrow...

[sagar0]

Fix : #2482

[adamretter]

@siying It is hard to believe that this is an issue. However, your explanation is certainly plausible, and from the stack trace given by ASAN:

freed by thread T22 (Finalizer threa) here:
    #0 0x3fff7bc9d4c0 in operator delete(void*) (/usr/lib/gcc/powerpc64le-linux-gnu/5.4.0/libasan.so+0xbd4c0)   
    #1 0x3fff77797554 in std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() (/usr/lib/powerpc64le-linux-gnu/libstdc++.so.6+0x177554)
    #2 0x3fff637461e8 in rocksdb::WriteBatch::~WriteBatch() db/write_batch.cc:172
    #3 0x3fff63746260 in rocksdb::WriteBatch::~WriteBatch() db/write_batch.cc:172
    #4 0x3fff632bb808 in Java_org_rocksdb_WriteBatch_disposeInternal java/rocksjni/write_batch.cc:288
    #5 0x3fff665ff98c  (<unknown module>)

we see that it is the Finalizer threa (Finalizer Thread) which does the deletion, which implies GC!