Ceph » rgw

Reproducible on my end at least... Whenever I try to update my radosgw daemons from mimic to nautilus,
they predictably fail on one of the first requests they handle. The backtrace in the crash report wasn't
terribly useful (attached as rgw.crash). Even with increased logging there really was nothing obvious
(attached as rgw.log)

I've sort of ignore the problem because mimic release was still working fine and I figured it was such a
reproducible bug, you guys would probably find and fix it. But it has been a while and even the latest
release still crashes, so I grabbed the debug symbols and ran radosgw under gdb to get some better info.

In gdb, I find that the actual problem appears to be the following

tcmalloc: large alloc 93825032937472 bytes == (nil) @  0x7ffff7b961e7 0x7fffeea67815 0x7fffeeae5497 0x555555a3704f
0x555555c5f823 0x555555c8933c 0x555555c895b9 0x555555c08d4c 0x555555930210 0x555555933278 0x55555587b4c7
0x55555587c9d9 0x555555e563ef

# my attempt at getting a backtrace follows...
(gdb) info symbol 0x7ffff7b961e7                                                                                                           
tc_malloc + 455 in section google_malloc of /usr/lib/x86_64-linux-gnu/libtcmalloc.so.4                                                     
(gdb) info symbol 0x7fffeea67815                                                                                                           
operator new(unsigned long) + 21 in section .text of /usr/lib/ceph/libceph-common.so.0                                                     
(gdb) info symbol 0x7fffeeae5497                                                                                                           
std::__cxx11::basic_string<char, std::char_traits<char>,
  std::allocator<char> >::_M_assign(std::__cxx11::basic_string<char,
  std::char_traits<char>, std::allocator<char> > const&) + 167 in section .text of /usr/lib/ceph/libceph-common.so.0                                         
(gdb) info symbol 0x555555a3704f                                                                                                           
RGWObjManifest::obj_iterator::update_location() + 431 in section .text of /usr/bin/radosgw                                                 
(gdb) info symbol 0x555555c5f823
RGWObjManifest::obj_iterator::operator++() + 307 in section .text of /usr/bin/radosgw                                                      
(gdb) info symbol 0x555555c8933c
RGWRados::iterate_obj(RGWObjectCtx&, RGWBucketInfo const&, rgw_obj const&, long, long,
  unsigned long, int (*)(rgw_raw_obj const&, long, long, long, bool, RGWObjState*, void*), void*) + 2412 in section .text of /usr/bin/radosgw                                                     
(gdb) info symbol 0x555555c895b9
RGWRados::Object::Read::iterate(long, long, RGWGetDataCB*) + 393 in section .text of /usr/bin/radosgw                                      
(gdb) info symbol 0x555555c08d4c
RGWGetObj::execute() + 3132 in section .text of /usr/bin/radosgw

Because tc_malloc doesn't have debug symbols and it is called from many places, I haven't been able to
get a good conditional breakpoint, so a lot of the following stack dumps are taken while single stepping
trying to find which code is called before we fail, but may not always be a failure.

So it turns out my daemons reliably crash while fetching a 12 byte testfile that I pull periodically with
Nagios to check if the servers are working. And when I step through I find that we crash the second time
we hit src/rgw/rgw\_rados.cc:7050

  if (astate->has_manifest) {
    /* now get the relevant object stripe */
    RGWObjManifest::obj_iterator iter = astate->manifest.obj_find(ofs);

    RGWObjManifest::obj_iterator obj_end = astate->manifest.obj_end();

>>> for (; iter != obj_end && ofs <= end; ++iter) {
      off_t stripe_ofs = iter.get_stripe_ofs();
      off_t next_stripe_ofs = stripe_ofs + iter.get_stripe_size();

      while (ofs < next_stripe_ofs && ofs <= end) {
        read_obj = iter.get_location().get_raw_obj(this);
        uint64_t read_len = std::min(len, iter.get_stripe_size() - (ofs - stripe_ofs));
        read_ofs = iter.location_ofs() + (ofs - stripe_ofs);

Both times iter and obj_end are the same (content-wise, pointers are different). At the second
iteration ofs is 12 and end is 11. However we never actually get to test that condition as
\++iter is called first and we end up in RGWObjManifest::obj\_iterator::operator++().

Here manifest->explicit_obj is true, and as we enter the function explicit_iter is

$2 = {first = 0, second = {loc = {bucket = {tenant = "", name = "test", marker = "default.1021717.1",
bucket_id = "default.1021717.1", explicit_placement = {data_pool = {name = ".rgw.buckets", ns = ""},
data_extra_pool = {name = "", ns = ""}, index_pool = {name = ".rgw.buckets.index", ns = ""}},
oid = ".bucket.meta.test:default.1021717.1"}, key = {name = "testfile", instance = "", ns = ""},
in_extra_data = false, index_hash_source = ""}, loc_ofs = 0, size = 12}}

Then ++explicit_iter is called and explicit_iter becomes

$3 = {first = 1, second = {loc = {bucket = {tenant = <error: Cannot access memory at address 0xc>,
name = <error reading variable: Cannot create a lazy string with address 0x0, and a non-zero length.>,
marker = <error reading variable: Cannot create a lazy string with address 0x0, and a non-zero length.>,
bucket_id = <error reading variable: Cannot create a lazy string with address 0x0, and a non-zero length.>,
explicit_placement = {data_pool = {name = <error reading variable: Cannot create a lazy string with address 0x0,
and a non-zero length.>, ns = <error: Cannot access memory at address 0x7374656b>},
data_extra_pool = {name = <error reading variable: Cannot create a lazy string with address 0x0,
and a non-zero length.>, ns = <error reading variable: Cannot create a lazy string with address 0x0,
and a non-zero length.>}, index_pool = {name = <error reading variable: Cannot create a lazy string with
address 0x0, and a non-zero length.>, ns = <error reading variable: Cannot create a lazy string with
address 0x0, and a non-zero length.>}}, oid = <error reading variable: Cannot create a lazy string with
address 0x0, and a non-zero length.>}, key = {name = <error reading variable: Cannot create a lazy string
with address 0x0, and a non-zero length.>, instance = <error reading variable: Cannot create a lazy string
with address 0x0, and a non-zero length.>, ns = <error reading variable: Cannot create a lazy string with
address 0x0, and a non-zero length.>}, in_extra_data = false, index_hash_source = <error reading variable:
Cannot create a lazy string with address 0x0, and a non-zero length.>}, loc_ofs = 0, size = 12}}

And we end up crashing in RGWObjManifest::obj_iterator::update_location() where location is set to the
uninitialized state in explicit_iter->second.loc.

Let me know if you need me to try to get some more data.