crimson/osd: implement op discarding for pglog-based recovery.

crimson, in regards to the classical OSD, doesn't discard
`MOSDPGPush` nor `MOSDPGPull` messages that were sent in
a epoch earlier than `last_peering_reset`.

This was the problem behind the following crash observed
at Sepia:

```
rzarzynski@teuthology:/home/teuthworker/archive/rzarzynski-2021-12-07_08:51:40-rados-master-distro-basic-smithi$ less ./6550163/remote/smithi190/log/ceph-osd.1.log.gz
...
DEBUG 2021-12-07 09:23:18,543 [shard 0] osd - handle_push: MOSDPGPush(2.1 32/29 {PushOp(2:8ae28953:::benchmark_data_smithi190_40039_object884:head, version: 19'102, data_included: [0~1], data_size: 1, omap_heade
r_size: 0, omap_entries_size: 0, attrset_size: 1, recovery_info: ObjectRecoveryInfo(2:8ae28953:::benchmark_data_smithi190_40039_object884:head@19'102, size: 1, copy_subset: [0~1], clone_subset: {}, snapset: 0={}
:{}, object_exist: 0), after_progress: ObjectRecoveryProgress(!first, data_recovered_to:1, data_complete:true, omap_recovered_to:, omap_complete:true, error:false), before_progress: ObjectRecoveryProgress(first,
 data_recovered_to:0, data_complete:false, omap_recovered_to:, omap_complete:false, error:false))}) v4
DEBUG 2021-12-07 09:23:18,543 [shard 0] osd - _handle_push
DEBUG 2021-12-07 09:23:18,544 [shard 0] osd - submit_push_data
...
DEBUG 2021-12-07 09:23:18,545 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 crt=19'236 m
lcod 0'0 remapped NOTIFY last_complete now 19'101 log.complete_to at end
ERROR 2021-12-07 09:23:18,545 [shard 0] none - /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.0.0-89
04-g6dfda01c/rpm/el8/BUILD/ceph-17.0.0-8904-g6dfda01c/src/osd/PeeringState.cc:4198 : In function 'void PeeringState::recover_got(const hobject_t&, eversion_t, bool, ObjectStore::Transaction&)', ceph_assert(%s)
info.last_complete == info.last_update
Aborting on shard 0.
Backtrace:
Reactor stalled for 1270 ms on shard 0. Backtrace: 0xb14ab 0x470b5f58 0x46e2303d 0x46e3eeed 0x46e3f2b2 0x46e3f476 0x46e3f726 0x12b1f 0xc8e3b 0x3ffd3682 0x3ffd8b7b 0x3ffda08e 0x3ffda753 0x3ffcfdcb 0x3ffd02e2 0x3f
fd0ada 0x12b1f 0x3737e 0x21db4 0x3feb09be 0x3cd7fc6e 0x3bec409f 0x3c13d963 0x3c250005 0x3c250b21 0x3c251436 0x3c251fa7 0x3a2cc920 0x3a2fa631 0x3a2fb2cd 0x46df4da1 0x46e3d04a 0x46fc744b 0x46fc9420 0x46a79302 0x46
a7db6b 0x3a18b7f2 0x23492 0x39d30edd
 0# gsignal in /lib64/libc.so.6
 1# abort in /lib64/libc.so.6
 2# ceph::__ceph_assert_fail(char const*, char const*, int, char const*) in ceph-osd
 3# PeeringState::recover_got(hobject_t const&, eversion_t, bool, ceph::os::Transaction&) in ceph-osd
 4# PGRecovery::on_local_recover(hobject_t const&, ObjectRecoveryInfo const&, bool, ceph::os::Transaction&) in ceph-osd
```

The sequence of events
---------------------------

The merged log had entries to `19'236`:

```
DEBUG 2021-12-07 09:22:06,727 [shard 0] osd - pg_advance_map(id=74, detail=PGAdvanceMap(pg=2.1 from=23 to=24 do_init)): complete
TRACE 2021-12-07 09:22:06,729 [shard 0] osd - call_with_interruption_impl: may_interrupt: false, local interrupt_condintion: 0x603000699800, global interrupt_cond: 0x0,N7crimson3osd20IOInterruptConditionE
TRACE 2021-12-07 09:22:06,729 [shard 0] osd - set: interrupt_cond: 0x603000699800, ref_count: 1
DEBUG 2021-12-07 09:22:06,729 [shard 0] osd - do_peering_event handling epoch_sent: 24 epoch_requested: 23 MLogRec from 2 log log((0'0,19'236], crt=19'236) pi ([18,22] all_participants=0,1,2,3 intervals=([18,21] acting 2,3)) pg_lease(ru 89.867439270s ub 89.867439270s int 16.000000000s) +create_info for pg: 2.1
DEBUG 2021-12-07 09:22:06,729 [shard 0] osd -  pg_epoch 24 pg[2.1( empty local-lis/les=0/0 n=0 ec=12/12 lis/c=18/18 les/c/f=19/19/0 sis=23) [0,1]/[2] r=-1 lpr=23 pi=[18,23)/1 crt=0'0 mlcod 0'0 unknown state<Started/Stray>: got info+log from osd.2 2.1( v 19'236 (0'0,19'236] local-lis/les=23/24 n=0 ec=12/12 lis/c=18/18 les/c/f=19/19/0 sis=23) log((0'0,19'236], crt=19'236)
DEBUG 2021-12-07 09:22:06,729 [shard 0] osd - merge_log log((0'0,19'236], crt=19'236) from osd.2 into log((0'0,0'0], crt=0'0)
DEBUG 2021-12-07 09:22:06,729 [shard 0] osd - merge_log extending head to 19'236
DEBUG 2021-12-07 09:22:06,729 [shard 0] osd -   ? 19'236 (0'0) modify   2:8a93bbd4:::foo.7:head by client.4668.0:1 2021-12-07T09:21:57.301709+0000 0 ObjectCleanRegions clean_offsets: [9033~18446744073709542582], clean_omap: 1, new_object: 0
...
DEBUG 2021-12-07 09:22:06,739 [shard 0] osd -   ? 19'103 (0'0) modify   2:9cf5b466:::benchmark_data_smithi190_40039_object890:head by client.4423.0:891 2021-12-07T09:21:44.366732+0000 0 ObjectCleanRegions clean_
offsets: [1~18446744073709551614], clean_omap: 1, new_object: 0
DEBUG 2021-12-07 09:22:06,739 [shard 0] osd -   ? 19'102 (0'0) modify   2:8ae28953:::benchmark_data_smithi190_40039_object884:head by client.4423.0:885 2021-12-07T09:21:44.292066+0000 0 ObjectCleanRegions clean_offsets: [1~18446744073709551614], clean_omap: 1, new_object: 0
DEBUG 2021-12-07 09:22:06,739 [shard 0] osd -   ? 19'101 (0'0) modify   2:80595656:::benchmark_data_smithi190_40039_object883:head by client.4423.0:884 2021-12-07T09:21:44.285634+0000 0 ObjectCleanRegions clean_offsets: [1~18446744073709551614], clean_omap: 1, new_object: 0
```

The PG log was `complete_to 19'102` when recovering previous object.

```
DEBUG 2021-12-07 09:23:18,394 [shard 0] osd -  pg_epoch 32 pg[2.1( v 19'236 lc 19'100 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 c
rt=19'236 mlcod 0'0 active+remapped got missing 2:80595656:::benchmark_data_smithi190_40039_object883:head v 19'101
DEBUG 2021-12-07 09:23:18,394 [shard 0] osd -  pg_epoch 32 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 c
rt=19'236 lcod 19'100 mlcod 0'0 active+remapped last_complete now 19'101 log.complete_to 19'102
```

```
DEBUG 2021-12-07 09:23:18,397 [shard 0] osd -  pg_epoch 32 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 c
rt=19'236 lcod 19'100 mlcod 0'0 active+remapped recovery_committed_to version 19'101 now ondisk
```

Then `PGAdvance` event happened...

```
DEBUG 2021-12-07 09:23:18,468 [shard 0] osd - pg_advance_map(id=149, detail=PGAdvanceMap(pg=2.1 from=32 to=33)): start
```

... and the PG 2.1 went to `Reset`:

```
DEBUG 2021-12-07 09:23:18,477 [shard 0] osd -  pg_epoch 32 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped handle_advance_map {1}/{2} -- 1/2
DEBUG 2021-12-07 09:23:18,477 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped state<Started>: Started advmap
DEBUG 2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped new interval newup {1} newacting {2}
DEBUG 2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped state<Started>: should_restart_peering, transitioning to Reset
INFO  2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped exit Started/ReplicaActive/RepRecovering 8.880699 5 0.000298
INFO  2021-12-07 09:23:18,478 [shard 0] osd - Exiting state: Started/ReplicaActive/RepRecovering, entered at 1638868989.5980496, 0.000298968 spent on 5 events
INFO  2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped exit Started/ReplicaActive 27.421174 0 0.000000
INFO  2021-12-07 09:23:18,478 [shard 0] osd - Exiting state: Started/ReplicaActive, entered at 1638868971.057631, 0.0 spent on 0 events
INFO  2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped exit Started 28.590107 0 0.000000
INFO  2021-12-07 09:23:18,478 [shard 0] osd - Exiting state: Started, entered at 1638868969.8887343, 0.0 spent on 0 events
INFO  2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped enter Reset
INFO  2021-12-07 09:23:18,478 [shard 0] osd - Entering state: Reset
DEBUG 2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=29 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped set_last_peering_reset 33
DEBUG 2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=33 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped Clearing blocked outgoing recovery messages
DEBUG 2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=33 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped Beginning to block outgoing recovery messages
DEBUG 2021-12-07 09:23:18,478 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=33 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped state<Reset>: Reset advmap
DEBUG 2021-12-07 09:23:18,479 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=33 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped new interval newup {1} newacting {2}
DEBUG 2021-12-07 09:23:18,479 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=33 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped state<Reset>: should restart peering, calling start_peering_interval again
DEBUG 2021-12-07 09:23:18,479 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [0,1]/[2] r=-1 lpr=33 pi=[18,29)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped set_last_peering_reset 33
DEBUG 2021-12-07 09:23:18,479 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped start_peering_interval: check_new_interval output: check_new_interval interval(29-32 up {0, 1}(0) acting {2}(2)) up_thru 30 up_from 28 last_epoch_clean 19 interval(29-32 up {0, 1}(0) acting {2}(2) maybe_went_rw) : primary up 28-30 includes interval

DEBUG 2021-12-07 09:23:18,479 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=29) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped  noting past ([18,32] all_participants=0,1,2,3 intervals=([26,28] acting 0,1),([29,32] acting 2))
DEBUG 2021-12-07 09:23:18,479 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped on_new_interval
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped on_new_interval upacting_features 0x3f01cfbb7ffdffff from {2}+{1}
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped on_new_interval checking missing set deletes flag. missing = missing(135 may_include_deletes = 1)
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped init_hb_stamps now {}
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped on_new_interval prior_readable_until_ub 0.000000000s (mnow 145.976531982s + 0.000000000s)
INFO  2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 luod=0'0 crt=19'236 mlcod 0'0 active+remapped start_peering_interval up {0, 1} -> {1}, acting {2} -> {2}, acting_primary 2 -> 2, up_primary 0 -> 1, role -1 -> -1, features acting 4540138303579357183 upacting 4540138303579357183
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 crt=19'236 mlcod 0'0 remapped clear_primary_state
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd - on_change,  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 crt=19'236 mlcod 0'0 remapped
DEBUG 2021-12-07 09:23:18,480 [shard 0] osd -  pg_epoch 33 pg[2.1( v 19'236 lc 19'101 (0'0,19'236] local-lis/les=0/0 n=0 ec=12/12 lis/c=29/18 les/c/f=30/19/0 sis=33) [1]/[2] r=-1 lpr=33 pi=[18,33)/2 crt=19'236 mlcod 0'0 remapped NOTIFY check_recovery_sources no source osds () went down
```

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>

diff --git a/src/crimson/osd/replicated_recovery_backend.cc b/src/crimson/osd/replicated_recovery_backend.cc
index 19cf5d2ef27a377f1f1a35fe2a324f2aabfd690e..88c51f9ce9338c968f21e7ce4704cf367cbf0a62 100644 (file)
--- a/src/crimson/osd/replicated_recovery_backend.cc
+++ b/src/crimson/osd/replicated_recovery_backend.cc
@@ -589,6 +589,10 @@ RecoveryBackend::interruptible_future<>
 ReplicatedRecoveryBackend::handle_pull(Ref<MOSDPGPull> m)
 {
   logger().debug("{}: {}", __func__, *m);
+  if (pg.can_discard_replica_op(*m)) {
+    logger().debug("{}: discarding {}", __func__, *m);
+    return seastar::now();
+  }
   return seastar::do_with(m->take_pulls(), [this, from=m->from](auto& pulls) {
     return interruptor::parallel_for_each(pulls,
                                       [this, from](auto& pull_op) {
@@ -709,6 +713,10 @@ RecoveryBackend::interruptible_future<>
 ReplicatedRecoveryBackend::handle_pull_response(
   Ref<MOSDPGPush> m)
 {
+  if (pg.can_discard_replica_op(*m)) {
+    logger().debug("{}: discarding {}", __func__, *m);
+    return seastar::now();
+  }
   const PushOp& pop = m->pushes[0]; //TODO: only one push per message for now.
   if (pop.version == eversion_t()) {
     // replica doesn't have it!
@@ -797,6 +805,10 @@ RecoveryBackend::interruptible_future<>
 ReplicatedRecoveryBackend::handle_push(
   Ref<MOSDPGPush> m)
 {
+  if (pg.can_discard_replica_op(*m)) {
+    logger().debug("{}: discarding {}", __func__, *m);
+    return seastar::now();
+  }
   if (pg.is_primary()) {
     return handle_pull_response(m);
   }