Ceph

This SEGV is caused due to a NULL omap iterator.
This can happen if the object belonging to the Primary OSD is missing from underlying filesystem of if the underlying filesystem itself is corrupted.

in this case a lookup(::stat()) on the object fails and returns an ENOENT; which causes get_omap_iterator to return a NULL iterator.

Fix:
assert if the object map iterator returned is NULL; so that I/O's can be served from other osd's.

Dhiraj Kamble wrote:

This SEGV is caused due to a NULL omap iterator.
This can happen if the object belonging to the Primary OSD is missing from underlying filesystem or if the underlying filesystem itself is corrupted.

in this case a lookup(::stat()) on the object fails and returns an ENOENT; which causes get_omap_iterator to return a NULL iterator.

Fix:
assert if the object map iterator returned is NULL; so that I/O's can be served from other osd's.

Hi Greg,

No i did not intend to add any comments.

The reason i thought we should assert is, so that we can serve i/o's from other osd's - incase the object itself has been explicitly removed or is corrupted.

Also i see that we expect build_push_op to return a success in ReplicatedBackend::prep_push; else we assert anyways.

@
void ReplicatedBackend::prep_push(
...
..

int r = build_push_op(pi.recovery_info,
            pi.recovery_progress,
            &new_progress,
            pop,
            &(pi.stat));
  assert(r == 0);                    <<< expect a success; else we assert.
  pi.recovery_progress = new_progress;
}
@

so i thought it would good to assert if the omap iterator is NULL in build_push_op or do you think its good to reset the recovery info and then assert. Anyways i dont see any changes that we could make on a failure return value from build_push_op.

let me know about your thoughts and how can we handle this gracefully.

cheers,
Dhiraj

btw, the steps to reproduce this issue are mentioned by Sahana above & it can be reproduced on a single node too.

For a given object; remove its corresponding file from the filesystem of the primary osd.(../primary_osd/current/pg_dir/)
initate a scrub on the pg to which the object belongs
intitiate a repair on the primary osd.

You'll hit the assert.

Hmm, most likely a bug in repair. We should start by creating a teuthology task which reproduces the bug. Once we have that, we can fix it and add the test to the test suite.

Hi Loic,

please find below the steps to reproduce the issue.

• DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH **
  ceph version 0.84-372-gb0aa846 (b0aa846b3f81225a779de00100e15334fb8156b3)
  @

• DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***

1. id weight type name up/down reweight
   -1 3 root default
   -3 3 rack localrack
   -2 3 host localhost
   0 1 osd.0 up 1
   1 1 osd.1 up 1
   2 1 osd.2 up 1

Steps:

@
#:/build/ceph-firefly84/src# ./rbd create img --size 1024 --image-format 2
#:/build/ceph-firefly84/src# ./rbd map img
/dev/rbd1

#:/build/ceph-firefly84/src# ./rados lspools
rbd

#:/build/ceph-firefly84/src# dd if=/dev/urandom of=/dev/rbd1 bs=4M oflag=direct count=1
1+0 records in
1+0 records out
4194304 bytes (4.2 MB) copied, 0.457051 s, 9.2 MB/s

• DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
  dumped all in format plain
  0.20 1 0 0 0 0 4194304 8 8 active+clean 2014-08-21 15:14:21.859898 11'8 11:103 [1,2,0] 1 [1,2,0] 1 0'0 2014-08-21 15:13:53.645589 0'0 2014-08-21 15:13:53.645589

#:/build/ceph-firefly84/src# ls ./dev/osd0/current/0.20_head/
rbd\udata.100d6b8b4567.0000000000000000__head_567EC760__0

#:/build/ceph-firefly84/src# ls ./dev/osd1/current/0.20_head/
rbd\udata.100d6b8b4567.0000000000000000__head_567EC760__0

#:/build/ceph-firefly84/src# ls ./dev/osd2/current/0.20_head/
rbd\udata.100d6b8b4567.0000000000000000__head_567EC760__0

• DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
  osdmap e11 pg 0.20 (0.20) -> up [1,2,0] acting [1,2,0]

#:/build/ceph-firefly84/src# rm ./dev/osd1/current/0.20_head/rbd\\udata.100d6b8b4567.0000000000000000__head_567EC760__0
#:/build/ceph-firefly84/src# rm ./dev/osd2/current/0.20_head/rbd\\udata.100d6b8b4567.0000000000000000__head_567EC760__0

• DEVELOPER MODE: setting PATH, PYTHONPATH and LD_LIBRARY_PATH ***
  osd.1 instructed to repair

@

Primary osd - osd.1.log:

@2014-08-21 15:32:20.483804 7fa6a6847700 -1 ** Caught signal (Segmentation fault) * in thread 7fa6a6847700

ceph version 0.84-372-gb0aa846 (b0aa846b3f81225a779de00100e15334fb8156b3)
1: (ceph::BackTrace::BackTrace(int)+0x2d) [0x1676821]
2: ./ceph-osd() [0x179eab2]
3: (()+0x10340) [0x7fa6c51d0340]
4: (ReplicatedBackend::build_push_op(ObjectRecoveryInfo const&, ObjectRecoveryProgress const&, ObjectRecoveryProgress*, PushOp*, object_stat_sum_t*)+0x5ff) [0x159cce3]
5: (ReplicatedBackend::prep_push(std::tr1::shared_ptr<ObjectContext>, hobject_t const&, pg_shard_t, eversion_t, interval_set<unsigned long>&, std::map<hobject_t, interval_set<unsigned long>, std::less<hobject_t>, std::allocator<std::pair<hobject_t const, interval_set<unsigned long> > > >&, PushOp*)+0x1a5) [0x1599147]
6: (ReplicatedBackend::prep_push_to_replica(std::tr1::shared_ptr<ObjectContext>, hobject_t const&, pg_shard_t, PushOp*)+0xc6a) [0x1598cb0]
7: (ReplicatedBackend::start_pushes(hobject_t const&, std::tr1::shared_ptr<ObjectContext>, ReplicatedBackend::RPGHandle*)+0x2c1) [0x15aa959]
8: (C_ReplicatedBackend_OnPullComplete::finish(ThreadPool::TPHandle&)+0x103) [0x15d3ddf]
9: (GenContext<ThreadPool::TPHandle&>::complete(ThreadPool::TPHandle&)+0x2a) [0x131a0c8]
10: (ReplicatedPG::BlessedGenContext<ThreadPool::TPHandle&>::finish(ThreadPool::TPHandle&)+0xa7) [0x1626677]
11: (GenContext<ThreadPool::TPHandle&>::complete(ThreadPool::TPHandle&)+0x2a) [0x131a0c8]
12: (GenContextWQ::_process(GenContext<ThreadPool::TPHandle&>*, ThreadPool::TPHandle&)+0x32) [0x13004f8]
13: (ThreadPool::WorkQueueVal<GenContext<ThreadPool::TPHandle&>*, GenContext<ThreadPool::TPHandle&>*>::_void_process(void*, ThreadPool::TPHandle&)+0xb2) [0x13a091a]
14: (ThreadPool::worker(ThreadPool::WorkThread*)+0x734) [0x18da2d6]
15: (ThreadPool::WorkThread::entry()+0x23) [0x18de2c7]
16: (Thread::entry_wrapper()+0x79) [0x18d2a47]
17: (Thread::_entry_func(void*)+0x18) [0x18d29c4]
18: (()+0x8182) [0x7fa6c51c8182]
19: (clone()+0x6d) [0x7fa6c37b630d]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.
@

Missed a step to mention.
before i did a repair on the primary osd; i aslo did a scrub

#:/build/ceph-firefly84/src# ./ceph pg scrub 0.20
#:/build/ceph-firefly84/src# ./ceph osd repair 1

Note: i deleted the files from the primary as well as another replica. (osds: 1 & 2)

The following reproduces it reliably on my laptop:

ulimit -c 300000
./stop.sh
rm -fr dev out ;  mkdir -p dev ; CEPH_NUM_MON=1 CEPH_NUM_OSD=3 ./vstart.sh -d -n -X -l mon osd
./rbd create img --size 1024 --image-format 2
sudo ./rbd map img
sudo dd if=/dev/urandom of=/dev/rbd1 bs=4M oflag=direct count=1
ceph osd tree
rm dev/osd[01]/current/*/*rbd*data*
ceph pg scrub 0.2
ceph osd repair 0
sleep 60
ceph osd tree

#1  0x000000000179ecbc in reraise_fatal (signum=11) at global/signal_handler.cc:59
#2  0x000000000179ef8f in handle_fatal_signal (signum=11) at global/signal_handler.cc:105
#3  <signal handler called>
#4  0x000000000159cd71 in ReplicatedBackend::build_push_op (this=0x3878b40, recovery_info=..., progress=..., out_progress=0x7ffc6c7a8100, out_op=0x39c0000, stat=0x389f448) at osd/ReplicatedPG.cc:8760
#5  0x00000000015991d5 in ReplicatedBackend::prep_push (this=0x3878b40, obc=..., soid=..., peer=..., version=..., data_subset=..., clone_subsets=..., pop=0x39c0000) at osd/ReplicatedPG.cc:8369
#6  0x0000000001598d3e in ReplicatedBackend::prep_push_to_replica (this=0x3878b40, obc=..., soid=..., peer=..., pop=0x39c0000) at osd/ReplicatedPG.cc:8324
#7  0x00000000015aa9e7 in ReplicatedBackend::start_pushes (this=0x3878b40, soid=..., obc=..., h=0x3b17bf0) at osd/ReplicatedPG.cc:10202
#8  0x00000000015d3e31 in C_ReplicatedBackend_OnPullComplete::finish (this=0x39e3bd0, handle=...) at osd/ReplicatedPG.cc:2218
#9  0x000000000131a0dc in GenContext<ThreadPool::TPHandle&>::complete (this=0x39e3bd0, t=...) at ./include/Context.h:45
#10 0x00000000016266c9 in ReplicatedPG::BlessedGenContext<ThreadPool::TPHandle&>::finish (this=0x3d35420, t=...) at osd/ReplicatedPG.h:262
#11 0x000000000131a0dc in GenContext<ThreadPool::TPHandle&>::complete (this=0x3d35420, t=...) at ./include/Context.h:45
#12 0x00000000013004e8 in GenContextWQ::_process (this=0x38ed900, c=0x3d35420, tp=...) at ./common/WorkQueue.h:421
#13 0x00000000013a092e in ThreadPool::WorkQueueVal<GenContext<ThreadPool::TPHandle&>*, GenContext<ThreadPool::TPHandle&>*>::_void_process (this=0x38ed900, handle=...) at ./common/WorkQueue.h:191
#14 0x00000000018da69a in ThreadPool::worker (this=0x38ec730, wt=0x38a4d30) at common/WorkQueue.cc:128
#15 0x00000000018de68b in ThreadPool::WorkThread::entry (this=0x38a4d30) at common/WorkQueue.h:318
#16 0x00000000018d2e0b in Thread::entry_wrapper (this=0x38a4d30) at common/Thread.cc:60
#17 0x00000000018d2d88 in Thread::_entry_func (arg=0x38a4d30) at common/Thread.cc:45
#18 0x00007ffc8c1b3182 in start_thread (arg=0x7ffc6c7a9700) at pthread_create.c:312
#19 0x00007ffc8a7a130d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Even simpler and does not require root privileges

rm -f core
ulimit -c 300000
./stop.sh
rm -fr dev out ;  mkdir -p dev ; CEPH_NUM_MON=1 CEPH_NUM_OSD=3 ./vstart.sh -d -n -X -l mon osd
./rados --pool rbd put SOMETHING /etc/group
rm dev/osd1/current/*/*SOMETHING* # osd.1 is the primary
ceph pg scrub 0.7
sleep 60
ceph osd tree

For the problem to show the file being removed has to be the primary.

The problem does not show if waiting after the object is inserted. It is a race condition.

rm -f core
ulimit -c 300000
./stop.sh
rm -fr dev out ;  mkdir -p dev ; CEPH_NUM_MON=1 CEPH_NUM_OSD=3 ./vstart.sh -d -n -X -l mon osd
./rados --pool rbd put SOMETHING /etc/group
# sleep 60 # comment this out and the problem does not show
rm dev/osd1/current/*/*SOMETHING* # osd.1 is the primary
ceph pg scrub 0.7
sleep 60
ceph osd tree

The stack trace created by the minimal script is different from the one reported above, but it fails at the same point.

#0  0x00007ffce2d7520b in raise (sig=11) at ../nptl/sysdeps/unix/sysv/linux/pt-raise.c:37
#1  0x000000000179ecbc in reraise_fatal (signum=11) at global/signal_handler.cc:59
#2  0x000000000179ef8f in handle_fatal_signal (signum=11) at global/signal_handler.cc:105
#3  <signal handler called>
#4  0x000000000159cd71 in ReplicatedBackend::build_push_op (this=0x4872780, recovery_info=..., progress=..., out_progress=0x7ffcc3361270, out_op=0x4846d00, stat=0x48989c8) at osd/ReplicatedPG.cc:8760
#5  0x00000000015991d5 in ReplicatedBackend::prep_push (this=0x4872780, obc=..., soid=..., peer=..., version=..., data_subset=..., clone_subsets=..., pop=0x4846d00) at osd/ReplicatedPG.cc:8369
#6  0x0000000001598d3e in ReplicatedBackend::prep_push_to_replica (this=0x4872780, obc=..., soid=..., peer=..., pop=0x4846d00) at osd/ReplicatedPG.cc:8324
#7  0x00000000015aa9e7 in ReplicatedBackend::start_pushes (this=0x4872780, soid=..., obc=..., h=0x4bae5a0) at osd/ReplicatedPG.cc:10202
#8  0x00000000017019e6 in ReplicatedBackend::recover_object (this=0x4872780, hoid=..., v=..., head=..., obc=..., _h=0x4bae5a0) at osd/ReplicatedBackend.cc:75
#9  0x00000000015aa5d5 in ReplicatedPG::prep_object_replica_pushes (this=0x497c800, soid=..., v=..., h=0x4bae5a0) at osd/ReplicatedPG.cc:10175
#10 0x00000000015abc1b in ReplicatedPG::recover_replicas (this=0x497c800, max=5, handle=...) at osd/ReplicatedPG.cc:10278
#11 0x00000000015a6f0c in ReplicatedPG::start_recovery_ops (this=0x497c800, max=5, prctx=0x7ffcc3362860, handle=..., ops_started=0x7ffcc33627b8) at osd/ReplicatedPG.cc:9851
#12 0x00000000012ed9d8 in OSD::do_recovery (this=0x48e6000, pg=0x497c800, handle=...) at osd/OSD.cc:7892
#13 0x000000000130cd50 in OSD::RecoveryWQ::_process (this=0x48e7438, pg=0x497c800, handle=...) at osd/OSD.h:2045
#14 0x000000000139f2df in ThreadPool::WorkQueue<PG>::_void_process (this=0x48e7438, p=0x497c800, handle=...) at ./common/WorkQueue.h:256
#15 0x00000000018da69a in ThreadPool::worker (this=0x48e6730, wt=0x48dd540) at common/WorkQueue.cc:128
#16 0x00000000018de68b in ThreadPool::WorkThread::entry (this=0x48dd540) at common/WorkQueue.h:318
#17 0x00000000018d2e0b in Thread::entry_wrapper (this=0x48dd540) at common/Thread.cc:60
#18 0x00000000018d2d88 in Thread::_entry_func (arg=0x48dd540) at common/Thread.cc:45
#19 0x00007ffce2d6d182 in start_thread (arg=0x7ffcc3363700) at pthread_create.c:312
#20 0x00007ffce135b30d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

<sjusthm> the next step is to write a failing teuthology test to reproduce
<sjusthm> and then adapt build_push_op to do what scrub does when it discovers an inconsistent object
<sjusthm> ideally, you want to make that path fairly general so we can hook any other places where the osd sees something inconsistent into the same thing
<sjusthm> the basic concept is you will add the object to the primary's missing set
<sjusthm> and then run recovery on it
<sjusthm> making sure to update the missing_loc machinery
<sjusthm> you can look at the repair code for how that currently works
<sjusthm> after that, we will want to give the replicas a way to propogate "oh crap, I don't have this object I'm supposed to have" back to the primary where the primary can then mark its local copy of the replica missing set to be missing that object and run recovery
<sjusthm> the long term goal is for the primary and replicas whenever they find something obviously wrong with an object to be able to behave as if the inconsistency was discovered through scrub/repair
<sjusthm> instead of just crashing
<sjusthm> the path should also spam the central log since it might be an indication of a flaky disk
<sjusthm> the bug here is that build_push_op can't deal with an object which the missing set should be there isn't there
<sjusthm> the missing set does not contain that object
<sjusthm> so the recovery machinery chose to simply push it from the primary to the replica
<sjusthm> and build_push_op goes to look for it
<sjusthm> the ObjectStore doesn't find it and gives back a NULL iterator
<sjusthm> so that path needs to handle an erroneously missing object (which would only happen if someone is maliciously messing with the ondisk store or if the filesystem is messed up)

When scrub scans objects it will update the corresponding entry in the map given in argument

The result is used by the next state of the scrub process

When build_push_op unexpectedly finds a non existent object, while recovering, the context is quite different. Since the scrub process builds its own set of information from scratch whenever it is run , it is unclear how build_push_op could contribute back the information : "hey, I discovered this object is missing !".

An idea, which is not a fix but may help. When the following sequence is done:

/stop.sh
rm -fr dev out ;  mkdir -p dev ; CEPH_NUM_MON=1 CEPH_NUM_OSD=3 ./vstart.sh -d -n -X -l mon osd
./rados --pool rbd put SOMETHING /etc/group
rm dev/osd1/current/*/*SOMETHING* # osd.1 is the primary
ceph pg repair 0.7 

tentative solution to a problem related to what happens although it does not address the main issue https://github.com/ceph/ceph/pull/2379 . Low hanging fruit to make a little progress ;-)

remove_snap_mapped_object removes the object but apparently does not clear the FDCache because the underlying file does not exist. This should be fixed.

The scrub logic should be abstracted so that information can be contributed to it from various contexts, not just when scrubbing.

The proposed fix greatly reduces the window of opportunity for this problem to happen. It can however still happen and another issue ( #9328 ) was created for the more general solution.

running rados thrasher on the proposed fix branch

The following teuthology job passes:

- thrashosds:
    chance_pgnum_grow: 1
    chance_pgpnum_fix: 1
    timeout: 1200
- rados:
    clients: [client.0]
    ops: 4000
    objects: 500
    ec_pool: true
    op_weights:
      read: 100
      write: 0
      append: 100
      delete: 50
      snap_create: 50
      snap_remove: 50
      rollback: 50
      copy_from: 50
      setattr: 25
      rmattr: 25
- rados:
    clients: [client.0]
    ops: 4000
    objects: 500
    op_weights:
      read: 100
      write: 0
      append: 100
      delete: 50
      snap_create: 50
      snap_remove: 50
      rollback: 50
      copy_from: 50
      setattr: 25
      rmattr: 25