Ceph » RADOS

https://tracker.ceph.com/issues/49136 may have a different root cause, so marking is it as related and not duplicate for now.

Observed the assert on master:
/a/sseshasa-2021-07-14_10:37:09-rados-wip-sseshasa-testing-2021-07-14-1320-distro-basic-smithi/6270005

/a/yuriw-2021-08-06_16:31:19-rados-wip-yuri-master-8.6.21-distro-basic-smithi/6324561 - no logs

/a/yuriw-2022-02-09_22:52:18-rados-wip-yuri5-testing-2022-02-09-1322-pacific-distro-default-smithi/6672070

/a/yuriw-2022-06-23_21:29:45-rados-wip-yuri4-testing-2022-06-22-1415-pacific-distro-default-smithi/6895353

http://pulpito.front.sepia.ceph.com/rfriedma-2022-08-06_12:17:03-rados-wip-rf-snprefix-distro-default-smithi/6960416/

Is the code under debug_verify_stored_missing maintained?

Even if we don't want to deep dive into right now, we should refactor the assertion:

            if (debug_verify_stored_missing) {
              auto miter = missing.get_items().find(i->soid);
              if (i->is_delete()) {
                ceph_assert(miter == missing.get_items().end() ||
                       (miter->second.need == i->version &&
                        miter->second.have == eversion_t()));
              } else {
                ceph_assert(miter != missing.get_items().end());
                ceph_assert(miter->second.need == i->version);
                ceph_assert(miter->second.have == eversion_t());
              }
              checked.insert(i->soid);
            } 

Ronen: @debug_verify_stored_missing a an input parameter with default value. Unfortunately, it doesn't look like a dead one:

void PG::read_state(ObjectStore *store)
{
  // ...
  recovery_state.init_from_disk_state(
    std::move(info_from_disk),
    std::move(past_intervals_from_disk),
    [this, store] (PGLog &pglog) {
      ostringstream oss;
      pglog.read_log_and_missing(
        store,
        ch,
        pgmeta_oid,
        info,
        oss,
        cct->_conf->osd_ignore_stale_divergent_priors,
        cct->_conf->osd_debug_verify_missing_on_start);

/a/lflores-2024-01-10_23:43:40-rados-wip-yuri11-testing-2024-01-10-1124-pacific-distro-default-smithi/7512901

/a/yuriw-2024-07-22_15:45:18-rados-wip-yuri2-testing-2024-07-19-0817-distro-default-smithi/7812729

scrub note: reopened the PR.

from logs in: /a/yuriw-2024-07-22_15:45:18-rados-wip-yuri2-testing-2024-07-19-0817-distro-default-smithi/7812729

osd.8 is the one that hit the assert: (./remote/smithi012/log/ceph-osd.8.log.gz)

2024-07-22T16:35:16.906+0000 7f7abf9a5640 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.0.0-5164-gc5a6b481/rpm/el9/BUILD/ceph-19.0.0-5164-gc5a6b481/src/osd/PGLog.h: In function 'static void PGLog:
:read_log_and_missing(ceph::common::CephContext*, ObjectStore*, ObjectStore::CollectionHandle&, ghobject_t, const pg_info_t&, PGLog::IndexedLog&, missing_type&, std::ostringstream&, bool, bool*, const DoutPrefixProvider*, std::set<std::__cxx11::basic_string<char> >*, bool) [with missing_type = pg_missing_set<t
rue>; ObjectStore::CollectionHandle = boost::intrusive_ptr<ObjectStore::CollectionImpl>; std::ostringstream = std::__cxx11::basic_ostringstream<char>]' thread 7f7abf9a5640 time 2024-07-22T16:35:16.905750+0000
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/19.0.0-5164-gc5a6b481/rpm/el9/BUILD/ceph-19.0.0-5164-gc5a6b481/src/osd/PGLog.h: 1581: FAILED ceph_assert(miter == missing.get_items().end() || (miter->second.need == i->version && miter->second.have == eversion_t()))

 ceph version 19.0.0-5164-gc5a6b481 (c5a6b4817430650136a4e4cb6fdd11bb824a2b16) squid (dev)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x11e) [0x562894fc183e]
 2: ceph-osd(+0x3fd9fa) [0x562894fc19fa]
 3: ceph-osd(+0x38fc53) [0x562894f53c53]
 4: (OSD::load_pgs()+0x606) [0x562895128ee6]
 5: (OSD::init()+0x21b7) [0x56289511e857]
 6: main()
 7: /lib64/libc.so.6(+0x29590) [0x7f7abfe29590]
 8: __libc_start_main()
 9: _start()

we are trying to find oid: benchmark_data_smithi135_39125_object19245

osd.8 also prints before the assertion the read_log_and_missing items that we are decoding from the omap:

2024-07-22T16:35:16.869+0000 7f7abf9a5640 20 read_log_and_missing 41'1162 (0'0) modify   3:33146baf:::benchmark_data_smithi135_39125_object19245:head by client.4681.0:19246 2024-07-22T16:31:57.677819+0000 0 ObjectCleanRegions clean_offsets: [(65536, 18446744073709486079)], clean_omap: true, new_object: false
2024-07-22T16:35:16.890+0000 7f7abf9a5640 20 read_log_and_missing 119'6295 (41'1162) delete   3:33146baf:::benchmark_data_smithi135_39125_object19245:head by client.4681.0:122116 2024-07-22T16:33:49.603339+0000 0 ObjectCleanRegions clean_offsets: [(65536, 18446744073709486079)], clean_omap: false, new_object:>

so we have 2 objects with different versions inside the missing, when we are not finding the oid from the getattr, we are finding that oid in the missing, but we are not matching the i->version to the miter that found (first one) version.

@Nitzan Mordechai

I've seen this twice under #69540 which has been marked as a duplicate of #45702

/a/ljsanders-2025-03-06_16:33:48-rados-wip-aainscow-for-lee-sanders26-distro-default-smithi/8173891
and
/a/ljsanders-2025-03-15_10:21:04-rados-wip-jamiepryde-for-lee-sanders6-distro-default-smithi/8191486/

But #45702 is marked as Fix Under Review. The PR: https://github.com/ceph/ceph/pull/48088
has been closed by the bot due to inactivity.

How do we get this moving?

I've reopneded the fux.

ok, need to refresh my analyze: recreate it again with some more debug messages (/a/nmordech-2025-03-26_10:34:16-rados:thrash-erasure-code-wip-nitzan-pglog-missing-validation-centos9-only-distro-default-smithi/8210737/)

2025-03-26T11:58:29.156+0000 7fa0818188c0 15 read_log_and_missing  missing 1233'15635 (1099'7269) delete   7:f22ae0ef:::benchmark_data_smithi157_109865_object117014:head by client.17885.0:251872 2025-03-26T11:58:05.713439+0000 0 ObjectCleanRegions clean_offsets: [65536~184467440737094
86079], clean_omap: false, new_object: false
2025-03-26T11:58:29.156+0000 7fa0818188c0 15 Found missing entry: need=1233'15635 vs expected 1233'15635, have=1099'7269 vs expected 0'0
2025-03-26T11:58:29.170+0000 7fa0818188c0 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/20.0.0-692-g5a05f4a9/rpm/el9/BUILD/ceph-20.0.0-692-g5a05f4a9/src/osd/PGLog.h: In func
tion 'static void PGLog::read_log_and_missing(ceph::common::CephContext*, ObjectStore*, ObjectStore::CollectionHandle&, ghobject_t, const pg_info_t&, PGLog::IndexedLog&, missing_type&, std::ostringstream&, bool, bool*, const DoutPrefixProvider*, std::set<std::__cxx11::basic_string<cha
r> >*, bool) [with missing_type = pg_missing_set<true>; ObjectStore::CollectionHandle = boost::intrusive_ptr<ObjectStore::CollectionImpl>; std::ostringstream = std::__cxx11::basic_ostringstream<char>]' thread 7fa0818188c0 time 2025-03-26T11:58:29.169006+0000
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/20.0.0-692-g5a05f4a9/rpm/el9/BUILD/ceph-20.0.0-692-g5a05f4a9/src/osd/PGLog.h: 1582: FAILED ceph_assert(miter == missing.get_items().end() || (miter->second.need == i->version && miter->second.have == eversion_t()))

we found missing record (delete) that hit:
ceph_assert(miter missing.get_items().end() ||
(miter->second.need i->version &&
miter->second.have == eversion_t()));

• need: 1233'15635 (the delete op’s version)
• have: 1099'7269 (a non‑default on‑disk version)

the "have" should be the default value 0'0, but it's not.

if we check the log before - A modify op is logged as:

read_log_and_missing 1099'7269 (0'0) modify   7:f22ae0ef:::benchmark_data_smithi157_109865_object117014:head by client.17885.0:117015 ...

Later, a delete op is logged as:

read_log_and_missing 1233'15635 (1099'7269) delete   7:f22ae0ef:::benchmark_data_smithi157_109865_object117014:head by client.17885.0:251872 ...

We are updating the existing missing record with a deleted record, but the "have" was not reset during the update.

i found PR: https://github.com/ceph/ceph/pull/29893 that introduced several changes:
The missing.add() interface and the pg_missing_item constructor originally accepted a “new_object” parameter. That flag was used to mark an item as “new” (e.g. calling clean_regions.mark_object_new() or even mark_fully_dirty()) when the “have” field was the default.

The PR removed the “new_object” parameter and the associated logic. As a result, when processing a delete op, if the object exists on disk the code now passes the on‑disk version as “have” (1099'7269) rather than resetting it to eversion_t() (0'0).

removing the new_object is probably the root cause of that missing record that failed the validation.

/a/skanta-2025-03-27_08:02:07-rados-wip-bharath10-testing-2025-03-27-0430-distro-default-smithi/8212845

PR under review...

Awaiting review.

Fix was approved and taken into testing.