Ceph

ubuntu@teuthology:/a/samuelj-2015-01-12_21:02:00-rados-wip-sam-testing-wip-testing-vanilla-fixes-basic-multi/700477

the bad peer is selected as a good peer because PGBackend::be_select_auth_object things the bad peer is an authoritative candidate

  -224> 2015-01-07 23:46:39.366423 7f1b21b0c700 10 osd.0 pg_epoch: 6 pg[0.17( v 6'14 (0'0,6'14] local-les=5 n=12 ec=1 les/c 5/6 4/4/2) [0,2] r=0 lpr=4 crt=6'12 lcod 6'13 mlcod 6'13 active+clean+scrubbing+deep+inconsistent+repair] be_select_auth_object: selecting osd 0 for obj 190db197/benchmark_data_burnupi59_7159_object114/head//0
  -223> 2015-01-07 23:46:39.366463 7f1b21b0c700 10 osd.0 pg_epoch: 6 pg[0.17( v 6'14 (0'0,6'14] local-les=5 n=12 ec=1 les/c 5/6 4/4/2) [0,2] r=0 lpr=4 crt=6'12 lcod 6'13 mlcod 6'13 active+clean+scrubbing+deep+inconsistent+repair] be_select_auth_object: selecting osd 2 for obj 190db197/benchmark_data_burnupi59_7159_object114/head//0
  -222> 2015-01-07 23:46:39.366508 7f1b21b0c700 20 osd.0 pg_epoch: 6 pg[0.17( v 6'14 (0'0,6'14] local-les=5 n=12 ec=1 les/c 5/6 4/4/2) [0,2] r=0 lpr=4 crt=6'12 lcod 6'13 mlcod 6'13 active+clean+scrubbing+deep+inconsistent+repair] be_compare_scrubmaps noting missing digest on 190db197/benchmark_data_burnupi59_7159_object114/head//0

Maybe the problem is that recovery should not try to recover an object that's already repaired ?

This is what should happen

2015-01-15 22:55:18.006470 7fce91a44700 10 osd.1 pg_epoch: 17 pg[1.3( v 13'1 (0'0,13'1] local-les=17 n=1 ec=3 les/c 17/17 16/16/16) [1,0] r=0 lpr=16 crt=0'0 lcod 0'0 mlcod 0'0 active+clean+scrubbing+deep+repair] be_select_auth_object: selecting osd 0 for obj 847441d7/SOMETHING/head//1
2015-01-15 22:55:18.006540 7fce91a44700 10 osd.1 pg_epoch: 17 pg[1.3( v 13'1 (0'0,13'1] local-les=17 n=1 ec=3 les/c 17/17 16/16/16) [1,0] r=0 lpr=16 crt=0'0 lcod 0'0 mlcod 0'0 active+clean+scrubbing+deep+repair] be_select_auth_object: rejecting osd 1 for obj 847441d7/SOMETHING/head//1, data digest mismatch 0xb4356e27 != 0x2ddbf8f5

2015-01-07 23:46:39.366423 7f1b21b0c700 10 osd.0 pg_epoch: 6 pg[0.17( v 6'14 (0'0,6'14] local-les=5 n=12 ec=1 les/c 5/6 4/4/2) [0,2] r=0 lpr=4 crt=6'12 lcod 6'13 mlcod 6'13 active+clean+scrubbing+deep+inconsistent+repair] be_select_auth_object: selecting osd 0 for obj 190db197/benchmark_data_burnupi59_7159_object114/head//0
2015-01-07 23:46:39.366463 7f1b21b0c700 10 osd.0 pg_epoch: 6 pg[0.17( v 6'14 (0'0,6'14] local-les=5 n=12 ec=1 les/c 5/6 4/4/2) [0,2] r=0 lpr=4 crt=6'12 lcod 6'13 mlcod 6'13 active+clean+scrubbing+deep+inconsistent+repair] be_select_auth_object: selecting osd 2 for obj 190db197/benchmark_data_burnupi59_7159_object114/head//0

2015-01-07 23:46:39.366508 7f1b21b0c700 20 osd.0 pg_epoch: 6 pg[0.17( v 6'14 (0'0,6'14] local-les=5 n=12 ec=1 les/c 5/6 4/4/2) [0,2] r=0 lpr=4 crt=6'12 lcod 6'13 mlcod 6'13 active+clean+scrubbing+deep+inconsistent+repair] be_compare_scrubmaps noting missing digest on 190db197/benchmark_data_burnupi59_7159_object114/head//0

• The file content change while the OSD is running
• deep-scrub / repair does notice something is wrong but does not reject the OSD with the problem nor does it add the osd into peer_missing
• the OSD with the problem is among the authoritative locations from which the object can be retrieved
• during recovery the OSD with the problem is selected and hit the assert because it does not show in peer_missing

https://github.com/ceph/ceph/pull/3389 will provide more information about the problem the next time it happens. I unsuccessfully tried to reproduce it.

<sjustwork> loicd: ok, so what is your current theory?
<loicd> sjustwork: that when the primary is recovering it uses a good peer that turns out to be itself although it is a bad peer, because it was not rejected as it should  have
<loicd> the problem with that theory is that I can't figure out how it happens, although it seems to be consistent with the logs
<sjustwork> /a/samuelj-2015-01-12_21:02:00-rados-wip-sam-testing-wip-testing-vanilla-fixes-basic-multi/700477/remote/ceph-osd.sorted.filtered
<sjustwork> and search backwards from the end for 
-*- loicd looking
<sjustwork> 6c48b997/benchmark_data_plana79_6637_object16/head//0
<sjustwork> from ceph-osd.0.log in that directory, that is our problem object
<sjustwork> what is the bad peer, and where did we attempt to pull from?
<loicd> the bad peer would the primary for 6c48b997/benchmark_data_plana79_6637_object16/head
<loicd> i.e. osd.0
<sjustwork> ok, where did we attempt to pull from?
<loicd> from osd.0 itself
<loicd> benchmark_data_plana79_6637_object16/head//0 v 5'12 on osds 0 from osd.0
<loicd> on osd.0
<sjustwork> oh, but only after we failed to pull from osd 2
<sjustwork> that's interesting
<loicd> that is the primary tries to pull from itself
<loicd> is it ? 
-*- loicd looking
-*- loicd browsing /a/samuelj-2015-01-12_21:02:00-rados-wip-sam-testing-wip-testing-vanilla-fixes-basic-multi/700477/remote/ceph-osd.0.log back from the assert
<sjustwork> just a few lines up
<sjustwork> ceph-osd.sorted.filtered contains all of the lines from all osd logs
<sjustwork> sorted by time
<sjustwork> with that pg grepped out
<loicd> ah, indeed
<sjustwork> btw: 
<sjustwork> for i in ceph-osd.?.log; do grep '^2015.*' $i > $i.filtered & done; wait; sort -m *.filtered > ceph-osd.sorted
<loicd> cool
<loicd> is there a logic that tries to pull from another good peer if a previous good peer has failed ? 
<sjustwork> yes, look through ReplicatedBackend and ReplicatedPG for something like _failed_push
<sjustwork> loicd: what is peer_missing for?
<loicd> contrary to what we had before, the 9406b7f71f91f2f0d6825b5acbc00d7994aeeefd there can be more than one location for a given missing_loc
<sjustwork> that is normal
<sjustwork> in normal recovery, there can be more than one location
<sjustwork> crucial for EC pools
<loicd> yes. I mean that before 9406b7f71f91f2f0d6825b5acbc00d7994aeeefd repair would not add more than one 
<loicd> I'm not sure what you're asking about peer_missing ? 
<loicd> it's going to be used when pulling from the peer that contains what the primary needs
<loicd> I'm however unclear on how / when it is updated. I tried to go over the places where it is set and unset but it's still blury
<sjustwork> loicd: ok, first thing is that it does not contain an entry for the primary
<sjustwork> though I think the peer_missing we pass into the PGBackend has that difference abstracted out
<loicd> which makes sense to me since it is the bad peer ? 
<sjustwork> loicd: ignore scrub/repair for a moment
<loicd> ok
<sjustwork> loicd: peer_missing is core to peering and recovery in general
<sjustwork> we have an entry for every osd in the acting set and every osd we may want to recover from
<sjustwork> because
<sjustwork> for a given osd, the info + the missing set determines which objects are (should be) current on the peer
<loicd> oh, not juste the one that have information about missing / inconsistent objects ! interesting
<sjustwork> that is, the osd has all object from [hobject_t::min(), info.last_backfill] *except* for the entries in its peer_missing set
<sjustwork> *all objects
<sjustwork> *in its missing set
<sjustwork> thus, for all osds which we may need to ask the question "does this osd have this object" 
<sjustwork> we need it's missing set, and we need its info
<sjustwork> thus, we keep a peer_missing and a peer_info map for all acting and recovery source osds
<sjustwork> that's the background
<loicd> ok, so not having peer_missing is not normal, at all, that a good lead
<sjustwork> crucially, we do not keep one for the primary
<loicd> ah, ahum :-)
<sjustwork> because that would just duplicate the primary state
<sjustwork> *but*
<sjustwork> we usually hide that bit from the backend
<sjustwork> so, go take a look at how peer_missing gets passed between ReplicatedPG and PGBackend
-*- loicd looks
<sjustwork> a few other things I am noticing
<sjustwork> prepare_pull() assumes that the fromshard is in peer_missing
<sjustwork> which makes sense
<sjustwork> because we do not pull objects which exist on the primary
<loicd> yes
<loicd> I don't see where peer_missing goes from replicatedpg and pgbackend
<sjustwork> loicd: PGBackend.h
<sjustwork> defines listener methods which pass that information
<sjustwork> *which the backend can use to query that information from the listener
<sjustwork> but I think that's a red herring at the moment
<sjustwork> in repair_objcet
<sjustwork> in the else branch
<sjustwork> nvm, I see where it is being added to the primary missing set
<loicd> ok, maybe_get_shard_missing / get_shard_missing
<sjustwork> yeah, but I don't think that's related to this bug actually
<sjustwork> ugh, now I'm trying to figure out why it failed to pull from 2
<sjustwork> you'll want to find that code path
<sjustwork> it's a bit hacky
<sjustwork> but there is  PGListener callback so that the backend can inform the PG that an object location is actually flaky
<loicd> ok
<loicd> I though it was ReplicatedPG::failed_push but no, the message does not show in the logs
<sjustwork> I...thought it was that also, one sec
<sjustwork> yes it does
<sjustwork> 2015-01-13 01:09:41.992776 7f2d06841700  0 osd.0 pg_epoch: 5 pg[0.17( v 5'13 (0'0,5'13] local-les=5 n=10 ec=1 les/c 5/5 4/4/3) [0,2] r=0 lpr=4 rops=1 crt=5'11 lcod 5'12 mlcod 5'12 active+recovering m=1] _failed_push 6c48b997/benchmark_data_plana79_6637_object16/head//0 from shard 2, reps on 0 unfound? 0
<loicd> hum
<loicd> I was looking at another log
-*- loicd comparing http://tracker.ceph.com/attachments/download/1600/ceph-osd.0-bad.log.gz with /a/samuelj-2015-01-12_21:02:00-rados-wip-sam-testing-wip-testing-vanilla-fixes-basic-multi/700477/remote/ceph-osd.0.log around the _failed_push (that does not show in the redmine archived log)

trying to reproduce by running on bare metal http://pulpito.ceph.com/loic-2015-01-19_19:39:07-rados:basic:tasks:scrub_test.yaml-master---basic-multi/

First, we probably need to not update the oi digest if we are going to repair the object.

Yeah, the bug appears to be a race between the oi update and recover_primary.

Sam's proposed update https://github.com/athanatos/ceph/commit/738f8687d5345965b8c725f9d7f7429aaf28f7a9 currently in https://github.com/ceph/ceph/commits/wip-sam-testing