Ceph » RADOS

 -14> 2023-01-13T14:56:19.343+0000 7fc997d11700 20 osd.4 pg_epoch: 191 pg[3.1a( v 174'400 (0'0,174'400] local-lis/les=133/134 n=26 ec=133/19 lis/c=133/133 les/c/f=134/134/0 sis=191 pruub=15.550573349s) [4,1] r=0 lpr=191 pi=[133,191)/1 luod=0'0 lua=132'370 crt=174'400 lcod 174'398 mlcod 0'0 active pruub 215.163299561s@ mbc={} ps=[66~2,69~6,70~2,75~3,7f~3,84~2,87~3,8e~1,94~1]] on_new_interval scrubbing flags:
   -13> 2023-01-13T14:56:19.343+0000 7fc997d11700 15 osd.4 scrub-queue::determine_scrub_time suggested: 2023-01-13T14:56:19.348 hist: 2023-01-13T14:53:15.278 v:true/true must:y pool-min:0 (plnd:)
   -12> 2023-01-13T14:56:19.343+0000 7fc997d11700 20 osd.4 scrub-queue::register_with_osd pg[3.1a] state at entry: <not registered>
   -11> 2023-01-13T14:56:19.343+0000 7fc997d11700 10 osd.4 update_schedule: pg[3.1a] adjusted: 2023-01-13T14:56:19.348 (not-queued)
   -10> 2023-01-13T14:56:19.343+0000 7fc997d11700 10 osd.4 scrub-queue::register_with_osd pg[3.1a] sched-state changed from <not registered> to <registered> (@2023-01-13T14:56:19.348)
    -9> 2023-01-13T14:56:19.343+0000 7fc997d11700 10 osd.4 pg_epoch: 191 pg[3.1a( v 174'400 (0'0,174'400] local-lis/les=133/134 n=26 ec=133/19 lis/c=133/133 les/c/f=134/134/0 sis=191 pruub=15.550573349s) [4,1] r=0 lpr=191 pi=[133,191)/1 luod=0'0 lua=132'370 crt=174'400 lcod 174'398 mlcod 0'0 active pruub 215.163299561s@ mbc={} ps=[66~2,69~6,70~2,75~3,7f~3,84~2,87~3,8e~1,94~1]] scrubber<ActiveReplica>: on_primary_change: interval changed (133 -> 191). Aborting active scrub.
    -8> 2023-01-13T14:56:19.343+0000 7fc997d11700 10 osd.4 pg_epoch: 191 pg[3.1a( v 174'400 (0'0,174'400] local-lis/les=133/134 n=26 ec=133/19 lis/c=133/133 les/c/f=134/134/0 sis=191 pruub=15.550573349s) [4,1] r=0 lpr=191 pi=[133,191)/1 luod=0'0 lua=132'370 crt=174'400 lcod 174'398 mlcod 0'0 active pruub 215.163299561s@ mbc={} ps=[66~2,69~6,70~2,75~3,7f~3,84~2,87~3,8e~1,94~1]] scrubber<ActiveReplica>: scrub_clear_state
    -7> 2023-01-13T14:56:19.343+0000 7fc997d11700 10 osd.4 pg_epoch: 191 pg[3.1a( v 174'400 (0'0,174'400] local-lis/les=133/134 n=26 ec=133/19 lis/c=133/133 les/c/f=134/134/0 sis=191 pruub=15.550573349s) [4,1] r=0 lpr=191 pi=[133,191)/1 luod=0'0 lua=132'370 crt=174'400 lcod 174'398 mlcod 0'0 active pruub 215.163299561s@ mbc={} ps=[66~2,69~6,70~2,75~3,7f~3,84~2,87~3,8e~1,94~1]] scrubber<ActiveReplica>: clear_pgscrub_state
    -6> 2023-01-13T14:56:19.343+0000 7fc997d11700 10 osd.4 pg_epoch: 191 pg[3.1a( v 174'400 (0'0,174'400] local-lis/les=133/134 n=26 ec=133/19 lis/c=133/133 les/c/f=134/134/0 sis=191 pruub=15.550573349s) [4,1] r=0 lpr=191 pi=[133,191)/1 luod=0'0 lua=132'370 crt=174'400 lcod 174'398 mlcod 0'0 active pruub 215.163299561s@ mbc={} ps=[66~2,69~6,70~2,75~3,7f~3,84~2,87~3,8e~1,94~1]] scrubber<ActiveReplica>: clear_scrub_reservations
    -5> 2023-01-13T14:56:19.343+0000 7fc997d11700 20 osd.4 scrub-queue::dec_scrubs_remote : 1 -> 0 (max 3, local 0)
    -4> 2023-01-13T14:56:19.343+0000 7fc997d11700 20 osd.4 pg_epoch: 191 pg[3.1a( v 174'400 (0'0,174'400] local-lis/les=133/134 n=26 ec=133/19 lis/c=133/133 les/c/f=134/134/0 sis=191 pruub=15.550573349s) [4,1] r=0 lpr=191 pi=[133,191)/1 luod=0'0 lua=132'370 crt=174'400 lcod 174'398 mlcod 0'0 active pruub 215.163299561s@ mbc={} ps=[66~2,69~6,70~2,75~3,7f~3,84~2,87~3,8e~1,94~1]] update_calc_stats actingset 1,4 upset 1,4 acting_recovery_backfill
    -3> 2023-01-13T14:56:19.359+0000 7fc997d11700 -1 /build/ceph-18.0.0-1762-gcb17f286/src/osd/PeeringState.cc: In function 'void PeeringState::update_calc_stats()' thread 7fc997d11700 time 2023-01-13T14:56:19.348816+0000
/build/ceph-18.0.0-1762-gcb17f286/src/osd/PeeringState.cc: 3553: FAILED ceph_assert(!acting_recovery_backfill.empty())

 ceph version 18.0.0-1762-gcb17f286 (cb17f286272f7ae9dbdf8117ca7b077b0a5cf650) reef (dev)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x128) [0x55d542083f11]
 2: ceph-osd(+0xcd10cd) [0x55d5420840cd]
 3: (PeeringState::update_calc_stats()+0x1c42) [0x55d54248ad32]
 4: (PeeringState::prepare_stats_for_publish(std::optional<pg_stat_t> const&, object_stat_collection_t const&)+0xf8) [0x55d54248b2f8]
 5: (PG::publish_stats_to_osd()+0xf7) [0x55d5421f3287]
 6: (PgScrubber::clear_pgscrub_state()+0x99) [0x55d54237f4c9]
 7: (PgScrubber::scrub_clear_state()+0x42) [0x55d54237f632]
 8: (PgScrubber::on_primary_change(std::basic_string_view<char, std::char_traits<char> >, requested_scrub_t const&)+0x207) [0x55d542380f77]
 9: (PeeringState::on_new_interval()+0x257) [0x55d54247af67]
 10: (PeeringState::start_peering_interval(std::shared_ptr<OSDMap const>, std::vector<int, std::allocator<int> > const&, int, std::vector<int, std::allocator<int> > const&, int, ceph::os::Transaction&)+0x59f) [0x55d54247c67f]
 11: (PeeringState::Reset::react(PeeringState::AdvMap const&)+0x26b) [0x55d54248eeeb]

start_peering_interval() clears acting_recovery_backfill, but with https://github.com/ceph/ceph/pull/48545/commits/1295b3752c8305cb57f69676beb22de07d575e01 we added a call to scrub_clear_state, which in turn results in calling publish_stats_to_osd and update_calc_stats, and we end up hitting this assert.

(gdb) bt
#0  raise (sig=<optimized out>) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000055d54284b1ba in reraise_fatal (signum=6) at ./src/global/signal_handler.cc:88
#2  handle_oneshot_fatal_signal (signum=6) at ./src/global/signal_handler.cc:363
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x00007fc9bc60d859 in __GI_abort () at abort.c:79
#6  0x000055d542083f6b in ceph::__ceph_assert_fail (assertion=0x7fc997d0be20 "", file=0x7fc997d0c0c0 "h\f\260C\325U", line=<optimized out>, func=<optimized out>) at ./src/common/assert.cc:75
#7  0x000055d5420840cd in ceph::__ceph_assert_fail (ctx=...) at ./src/common/assert.cc:80
#8  0x000055d54248ad32 in PeeringState::update_calc_stats (this=0x55d54d309f78) at ./src/log/Entry.h:35
#9  0x000055d54248b2f8 in PeeringState::prepare_stats_for_publish (this=this@entry=0x55d54d309f78, pg_stats_publish=std::optional<pg_stat_t> [no contained value], unstable_stats=...) at ./src/osd/PeeringState.cc:3835
#10 0x000055d5421f3287 in PG::publish_stats_to_osd (this=0x55d54d309000) at ./src/osd/PG.cc:825
#11 0x000055d54237f4c9 in PgScrubber::clear_pgscrub_state (this=0x55d5486bf800) at ./src/osd/scrubber/pg_scrubber.cc:2318
#12 0x000055d54237f632 in PgScrubber::scrub_clear_state (this=0x55d5486bf800) at ./src/osd/scrubber/pg_scrubber.cc:2300
#13 0x000055d542380f77 in PgScrubber::on_primary_change (this=0x55d5486bf800, caller="on_new_interval", request_flags=...) at ./src/osd/scrubber/pg_scrubber.cc:527
#14 0x000055d54247af67 in PeeringState::on_new_interval (this=0x55d54d309f78) at ./src/osd/PeeringState.cc:807
#15 0x000055d54247c67f in PeeringState::start_peering_interval (this=0x55d54d309f78, lastmap=std::shared_ptr<const OSDMap> (use count 11, weak count 1) = {...}, newup=..., new_up_primary=4, newacting=..., new_acting_primary=4, t=...)
    at ./src/osd/PeeringState.cc:669
#16 0x000055d54248eeeb in PeeringState::Reset::react (this=0x55d549ba9d10, advmap=...) at /usr/include/c++/11/ext/atomicity.h:109
#17 0x000055d5424db091 in boost::statechart::custom_reaction<PeeringState::AdvMap>::react<PeeringState::Reset, boost::statechart::event_base, void const*> (eventType=<synthetic pointer>: <optimized out>, evt=..., stt=...)
    at ./obj-x86_64-linux-gnu/boost/include/boost/polymorphic_cast.hpp:98

... etc.

(gdb) f 10
#10 0x000055d5421f3287 in PG::publish_stats_to_osd (this=0x55d54d309000) at ./src/osd/PG.cc:825
825      auto stats =
(gdb) info args
this = 0x55d54d309000
(gdb) p * this
..... lots of output .....
{ .... acting_recovery_backfill = std::set with 0 elements ... }

I'm not sure at which point `acting_recovery_backfill` should have been filled, but I can see in all the relevant frames (frame 10 pictured here), that acting_recovery_backfill is empty.

Didn't mean to change those fields.

Per the prev comment.