Ceph

(gdb) bt
#0  0x00007fe91b12aba5 in raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007fe91b12e6b0 in abort () at abort.c:92
#2  0x00007fe91b74b6bd in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/libstdc++.so.6
#3  0x00007fe91b749906 in ?? () from /usr/lib/libstdc++.so.6
#4  0x00007fe91b749933 in std::terminate() () from /usr/lib/libstdc++.so.6
#5  0x00007fe91b749a3e in __cxa_throw () from /usr/lib/libstdc++.so.6
#6  0x00007fe91bf5ff7d in ceph::__ceph_assert_fail (assertion=0x446dad "0", file=0x446d1b "./test/osd/RadosModel.h", line=368, 
    func=0x4474c0 "virtual void WriteOp::_finish(TestOp::CallbackInfo*)") at common/assert.cc:70
#7  0x000000000042de6e in WriteOp::_finish (this=0x7fe910088a00, info=0x7fe9101f8fa0) at ./test/osd/RadosModel.h:368
#8  0x0000000000446a7c in TestOp::finish (this=0x7fe910088a00, info=0x7fe9101f8fa0) at test/osd/RadosModel.cc:20
#9  0x0000000000446aeb in write_callback (comp=0x7fe9100884d0, arg=0x7fe9100035f0) at test/osd/RadosModel.cc:34
#10 0x00007fe91be5c034 in librados::RadosClient::C_aio_Ack::finish (this=0x7fe9100062c0, r=0) at librados.cc:657
#11 0x00007fe91be89859 in Objecter::handle_osd_op_reply (this=0x1581060, m=0x16e5c00) at osdc/Objecter.cc:1241
#12 0x00007fe91be42d82 in librados::RadosClient::_dispatch (this=0x157cbf0, m=0x16e5c00) at librados.cc:1069
#13 0x00007fe91be42b82 in librados::RadosClient::ms_dispatch (this=0x157cbf0, m=0x16e5c00) at librados.cc:1039
#14 0x00007fe91bf83287 in Messenger::ms_deliver_dispatch (this=0x15801e0, m=0x16e5c00) at msg/Messenger.h:102
#15 0x00007fe91bf6cb64 in SimpleMessenger::dispatch_entry (this=0x15801e0) at msg/SimpleMessenger.cc:364
#16 0x00007fe91be559b6 in SimpleMessenger::DispatchThread::entry (this=0x1580668) at msg/SimpleMessenger.h:545
#17 0x00007fe91bfd5899 in Thread::_entry_func (arg=0x1580668) at common/Thread.cc:41
#18 0x00007fe91b99d971 in start_thread (arg=<value optimized out>) at pthread_create.c:304
#19 0x00007fe91b1dd92d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#20 0x0000000000000000 in ?? ()
(gdb) f 7
#7  0x000000000042de6e in WriteOp::_finish (this=0x7fe910088a00, info=0x7fe9101f8fa0) at ./test/osd/RadosModel.h:368
368     ./test/osd/RadosModel.h: No such file or directory.
        in ./test/osd/RadosModel.h

another one:

INFO:teuthology.task.thrashosds.thrasher:in_osds:  [1, 2, 4, 0]  out_osds:  [5, 3] dead_osds:  [] live_osds:  [1, 0, 3, 2, 5, 4]
INFO:teuthology.task.thrashosds.thrasher:choose_action: min_in 2 min_out 0 min_live 2 min_dead 0
INFO:teuthology.task.thrashosds.thrasher:Adding osd 5
INFO:teuthology.task.rados.rados.0.out:946: Reading 292
INFO:teuthology.task.rados.rados.0.out:947: Reading 311
INFO:teuthology.task.rados.rados.0.out:948: Reading 393
INFO:teuthology.task.rados.rados.0.out:949: Writing 262 current snap is 0
INFO:teuthology.task.rados.rados.0.out:waiting_on = 3
INFO:teuthology.task.rados.rados.0.out:Writing sepia4713453-262 from 0 to 57 tid 1 ranges are [0~57,444394~685464,1586930~57464]
INFO:teuthology.task.rados.rados.0.out:Writing sepia4713453-262 from 444394 to 1129858 tid 2 ranges are [0~57,444394~685464,1586930~57464]
INFO:teuthology.task.rados.rados.0.out:Writing sepia4713453-262 from 1586930 to 1644394 tid 3 ranges are [0~57,444394~685464,1586930~57464]
INFO:teuthology.task.rados.rados.0.out:950: Writing 269 current snap is 0
INFO:teuthology.task.rados.rados.0.out:waiting_on = 2
INFO:teuthology.task.rados.rados.0.out:Writing sepia4713453-269 from 0 to 57 tid 1 ranges are [0~57,540647~657268]
INFO:teuthology.task.rados.rados.0.err:./test/osd/RadosModel.h: In function 'virtual void ReadOp::_finish(TestOp::CallbackInfo*)' thread 7fe917400700 time 2012-01-28 20:07:51.141077
INFO:teuthology.task.rados.rados.0.err:./test/osd/RadosModel.h: 524: FAILED assert(!old_value.deleted())
INFO:teuthology.task.rados.rados.0.out:Writing sepia4713453-269 from 540647 to 1197915 tid 2 ranges are [0~57,540647~657268]
INFO:teuthology.task.rados.rados.0.err: ceph version 0.41-14-g5e16974 (commit:5e16974c291e78f5a7cdc3c4f680e7817cff3cca)
INFO:teuthology.task.rados.rados.0.err: 1: (ReadOp::_finish(TestOp::CallbackInfo*)+0x387) [0x40ad77]
INFO:teuthology.task.rados.rados.0.err: 2: (librados::RadosClient::C_aio_Ack::finish(int)+0xa4) [0x7fe919ca2d64]
INFO:teuthology.task.rados.rados.0.err: 3: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xf69) [0x7fe919cb27e9]
INFO:teuthology.task.rados.rados.0.err: 4: (librados::RadosClient::_dispatch(Message*)+0x6c) [0x7fe919c923dc]
INFO:teuthology.task.rados.rados.0.err: 5: (librados::RadosClient::ms_dispatch(Message*)+0x33) [0x7fe919c92463]
INFO:teuthology.task.rados.rados.0.err: 6: (SimpleMessenger::dispatch_entry()+0x883) [0x7fe919d418e3]
INFO:teuthology.task.rados.rados.0.err: 7: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x7fe919c9c1ac]
INFO:teuthology.task.rados.rados.0.err: 8: (()+0x7971) [0x7fe9199f5971]
INFO:teuthology.task.rados.rados.0.err: 9: (clone()+0x6d) [0x7fe91923592d]
INFO:teuthology.task.rados.rados.0.err: ceph version 0.41-14-g5e16974 (commit:5e16974c291e78f5a7cdc3c4f680e7817cff3cca)
INFO:teuthology.task.rados.rados.0.err: 1: (ReadOp::_finish(TestOp::CallbackInfo*)+0x387) [0x40ad77]
INFO:teuthology.task.rados.rados.0.err: 2: (librados::RadosClient::C_aio_Ack::finish(int)+0xa4) [0x7fe919ca2d64]
INFO:teuthology.task.rados.rados.0.err: 3: (Objecter::handle_osd_op_reply(MOSDOpReply*)+0xf69) [0x7fe919cb27e9]
INFO:teuthology.task.rados.rados.0.err: 4: (librados::RadosClient::_dispatch(Message*)+0x6c) [0x7fe919c923dc]
INFO:teuthology.task.rados.rados.0.err: 5: (librados::RadosClient::ms_dispatch(Message*)+0x33) [0x7fe919c92463]
INFO:teuthology.task.rados.rados.0.err: 6: (SimpleMessenger::dispatch_entry()+0x883) [0x7fe919d418e3]
INFO:teuthology.task.rados.rados.0.err: 7: (SimpleMessenger::DispatchThread::entry()+0x1c) [0x7fe919c9c1ac]
INFO:teuthology.task.rados.rados.0.err: 8: (()+0x7971) [0x7fe9199f5971]
INFO:teuthology.task.rados.rados.0.err: 9: (clone()+0x6d) [0x7fe91923592d]

Looks like in some cases we are finding objects which should have been deleted.

Summary: An object was deleted, but after a recovery was found to be back ... which is almost surely indicative of a bug in the recovery process.

Just hit this:

- clean_up_local removed an object (due it a 'delete' log entry)
- a read came in and read it before the filestore deleted it.

Well, it was a bit more complex than that; there was some recovery going on, but that's the gist of the bug.

Adding an osr.flush() near the end of PG::activate() to ensure all this crap is on disk before we handling client ops or do any recovery.

359dfb9966d15d997f9e0351a5ed8de1faae62fe