Bug #45795
closedPrimaryLogPG.cc: 627: FAILED ceph_assert(!get_acting_recovery_backfill().empty())
0%
Description
I'm running into this assert while trying to exercise krbd with replica reads (particularly balanced reads):
-3> 2020-05-31T01:41:03.454+0000 7feef4815700 10 osd.4 pg_epoch: 160 pg[3.e(unlocked)] -- Watch(140522136622944,client.4455) HandleWatchTimeout
-2> 2020-05-31T01:41:03.454+0000 7feef4815700 10 osd.4 pg_epoch: 160 pg[3.e( v 160'3343 (0'0,160'3343] local-lis/les=19/20 n=217 ec=19/19 lis/c=19/19 les/c/f=20/20/0 sis=19) [7,4] r=1 lpr=19 luod=0'0 crt=160'3341 mlcod 159'3328 active
mbc={}] handle_watch_timeout obc 0x55d0e1f2f440
-1> 2020-05-31T01:41:03.462+0000 7feef4815700 -1 /build/ceph-16.0.0-2020-g64aa691/src/osd/PrimaryLogPG.cc: In function 'bool PrimaryLogPG::is_degraded_or_backfilling_object(const hobject_t&)' thread 7feef4815700 time 2020-05-31T01:41:
03.458493+0000
/build/ceph-16.0.0-2020-g64aa691/src/osd/PrimaryLogPG.cc: 627: FAILED ceph_assert(!get_acting_recovery_backfill().empty())
ceph version 16.0.0-2020-g64aa691 (64aa6910df80dea3468fff35edf20c3c10ff9b1b) pacific (dev)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x154) [0x55d0d40d2c8c]
2: (ceph::__ceph_assertf_fail(char const*, char const*, int, char const*, char const*, ...)+0) [0x55d0d40d2e67]
3: (()+0xb8b437) [0x55d0d424e437]
4: (PrimaryLogPG::handle_watch_timeout(std::shared_ptr<Watch>)+0xb8) [0x55d0d4276258]
5: (HandleWatchTimeout::complete(int)+0x118) [0x55d0d41e9618]
6: (SafeTimer::timer_thread()+0x1ac) [0x55d0d47b4bac]
7: (SafeTimerThread::entry()+0xd) [0x55d0d47b5f7d]
8: (()+0x76db) [0x7fef1801c6db]
9: (clone()+0x3f) [0x7fef16dbc88f]
0> 2020-05-31T01:41:03.466+0000 7feef4815700 -1 *** Caught signal (Aborted) **
in thread 7feef4815700 thread_name:safe_timer
Updated by Samuel Just almost 4 years ago
Did that fire on the replica? At a guess, the problem is that notifies are being sent to replicas, which would be wrong.
Updated by Samuel Just almost 4 years ago
- Description updated (diff)
It probably isn't https://tracker.ceph.com/issues/15391.
Updated by Ilya Dryomov almost 4 years ago
Samuel Just wrote:
Did that fire on the replica? At a guess, the problem is that notifies are being sent to replicas, which would be wrong.
Yeah, I think the problem is that notifies are marked as reads (i.e. only CEPH_OSD_FLAG_READ is set), meaning that they meet the criteria for sending to replica. This is the case both in Objecter and the kernel client.
Since notifies aren't really reads and have side effects, should we look into marking them as writes?
Updated by Samuel Just almost 4 years ago
Well, osd-side notifies are reads in that they don't result in mutation. I think lingerops in general probably should be always go to the primary.
Updated by Ilya Dryomov almost 4 years ago
I see. Watch being a write and notify being a read has always tripped me, but I guess I looked at it from the side effects POV and haven't considered when the actual mutation occurs.
I'll plan to implement that tomorrow.
Updated by Ilya Dryomov almost 4 years ago
After more digging, this doesn't appear to be related to notifies being sent to replicas.
The issue seems to be with serving from replica when an object has an established watch. If can_serve_replica_read() check is satisfied, we look up the object context. If not found, we fetch the object_info_t and then call populate_obc_watchers() because the PG is active. populate_obc_watchers() sees the recorded watch, treats it as unconnected and arms HandleWatchTimeout. When it fires, we hit the assert.
librbd doesn't run into this issue because it sets balance/localize only on specific OSD ops. In the kernel client I took Objecter's global_op_flags approach, so balance/localize are set much more liberally (Greg introduced global_op_flags together with CEPH_OSD_FLAG_LOCALIZE_READS precisely for this purpose).
Updated by Samuel Just almost 4 years ago
Ah, that makes sense. It should suffice to simply not populate_obc_watchers if replica.
Updated by Ilya Dryomov almost 4 years ago
- Status changed from New to Fix Under Review
Updated by Kefu Chai almost 4 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Nathan Cutler almost 4 years ago
- Copied to Backport #46007: octopus: PrimaryLogPG.cc: 627: FAILED ceph_assert(!get_acting_recovery_backfill().empty()) added
Updated by Nathan Cutler almost 4 years ago
- Status changed from Pending Backport to Resolved
While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".