Ceph » RADOS

shard 122(5) looks suspicious, it seems to not have been queried from the pg query output but all_unfound_are_queried_or_lost reports it was queried but discover_all_missing does report it.

2020-12-01T20:04:33.397+0000 7fd2d384e700 10 osd.121 pg_epoch: 8293941 pg[119.385s0( v 8293928'781618 (8280506'778630,8293928'781618] local-lis/les=8080280/8080281 n=54305 ec=5864462/5696301 lis/c=8080280/7905412 les/c/f=8080281/7905429/8076205 sis=8080280) [121,20,61,69,31,2]/[121,124,61,69,NONE,2]p121(0) backfill=[20(1),31(4)] r=0 lpr=8080280 pi=[7905412,8080280)/6 crt=8293928'781618 lcod 8293920'781617 mlcod 0'0 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=68},1={(0+1)=68},2={(1+0)=68},3={(0+0)=68},4={(0+0)=68},5={(0+0)=68}}] all_unfound_are_queried_or_lost all of might_have_unfound 1(3),2(5),7(1),9(3),10(3),13(5),14(1),20(1),23(5),25(3),31(4),36(4),61(2),65(4),69(3),73(5),81(4),94(4),122(5),124(1),145(5) have been queried or are marked lost

"might_have_unfound": [
                {
                    "osd": "122(5)",
                    "status": "not queried" 
                },

2020-12-01T20:04:33.397+0000 7fd2d384e700 20 osd.121 pg_epoch: 8293941 pg[119.385s0( v 8293928'781618 (8280506'778630,8293928'781618] local-lis/les=8080280/8080281 n=54305 ec=5864462/5696301 lis/c=8080280/7905412 les/c/f=8080281/7905429/8076205 sis=8080280) [121,20,61,69,31,2]/[121,124,61,69,NONE,2]p121(0) backfill=[20(1),31(4)] r=0 lpr=8080280 pi=[7905412,8080280)/6 crt=8293928'781618 lcod 8293920'781617 mlcod 0'0 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=68},1={(0+1)=68},2={(1+0)=68},3={(0+0)=68},4={(0+0)=68},5={(0+0)=68}}] update_calc_stats no peer_missing found for 122(5)
2020-12-01T20:04:33.397+0000 7fd2d384e700 20 osd.121 pg_epoch: 8293941 pg[119.385s0( v 8293928'781618 (8280506'778630,8293928'781618] local-lis/les=8080280/8080281 n=54305 ec=5864462/5696301 lis/c=8080280/7905412 les/c/f=8080281/7905429/8076205 sis=8080280) [121,20,61,69,31,2]/[121,124,61,69,NONE,2]p121(0) backfill=[20(1),31(4)] r=0 lpr=8080280 pi=[7905412,8080280)/6 crt=8293928'781618 lcod 8293920'781617 mlcod 0'0 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=68},1={(0+1)=68},2={(1+0)=68},3={(0+0)=68},4={(0+0)=68},5={(0+0)=68}}] update_calc_stats shard 122(5) objects 0 missing 54305

still digging

[NVM, used the command wrong]

I spot checked an object in 119.385

sjust@reesi002:~$ sudo ceph pg 119.385 list_unfound | head -n 30

{
    "num_missing": 68,
    "num_unfound": 68,
    "objects": [
        {
            "oid": {
                "oid": "10006fc22f8.00000000",
                "key": "",
                "snapid": -2,
                "hash": 1542341509,
                "max": 0,
                "pool": 119,
                "namespace": "" 
            },
            "need": "7936015'645867",
            "have": "0'0",
            "flags": "none",
            "clean_regions": "clean_offsets: [], clean_omap: 0, new_object: 1",
            "locations": [
                "61(2)",
                "121(0)",
                "124(1)" 
            ]
        },

It's actually present on osd 69:

sjust@mira060:~$ sudo ./cephadm shell --name osd.69
Inferring fsid 28f7427e-5558-4ffd-ae1a-51ec3042759a
Inferring config /var/lib/ceph/28f7427e-5558-4ffd-ae1a-51ec3042759a/osd.69/config
Using recent ceph image quay.ceph.io/ceph-ci/ceph:a7b62340ad27b26642bb54ec916a97c7e1f07a34
cd /vacd /varroot@mira060:/# cd /var/lib/ceph/osd/ceph-69/
root@mira060:/var/lib/ceph/osd/ceph-69# ceph-objectstore-tool --data-path . --op list --pg 119.385 | less
root@mira060:/var/lib/ceph/osd/ceph-69# ceph-objectstore-tool --data-path . --op list --pg 119.385 | grep 10006fc22f8.00000000
["119.385s3",{"oid":"10006fc22f8.00000000","key":"","snapid":-2,"hash":1542341509,"max":0,"pool":119,"namespace":"","shard_id":3,"max":0}]

Unfortunately, it's present but an older version

root@mira060:/var/lib/ceph/osd/ceph-69# ceph-objectstore-tool --data-path . '["119.385s3",{"oid":"10006fc22f8.00000000","key":"","snapid":-2,"hash":1542341509,"max":0,"pool":119,"namespace":"","shard_id":3,"max":0}]' dump      
{
    "id": {
        "oid": "10006fc22f8.00000000",
        "key": "",
        "snapid": -2,
        "hash": 1542341509,
        "max": 0,
        "pool": 119,
        "namespace": "",
        "shard_id": 3,
        "max": 0
    },
    "info": {
        "oid": {
            "oid": "10006fc22f8.00000000",
            "key": "",
            "snapid": -2,
            "hash": 1542341509,
            "max": 0,
            "pool": 119,
            "namespace": "" 
        },
        "version": "7935315'645757",
...

[Wrong, used the wrong shard field]

122 doesn't seem to have a 119.385 instance.

My current working assumption is that PeeringState::activate is willing to backfill a non-contiguous replica which happens to have a necessary copy of an unreadable object. This wasn't possible before durable missing sets and trimming past last_complete, but it's possible now:

acting [0,1,2,3,NULL,NULL] write to version 20
acting [0,1,2,NULL,4,NULL] write to version 30, tail 10
acting [0,1,2,3,NULL,NULL] write to version 60, tail 40
acting [0,1,2,3,4(backfill),NULL]

This sequence is possible because in the last interval, osd.3 will simply have 10 missing set entries which will end up trimmed leaving the pg with unfound objects which become permanently so once osd.4 is marked backfill.

If this guess is correct one or more of the following 8 osds should have a copy of {"oid":"10006fc22f8.00000000","key":"","snapid":-2,"hash":1542341509,"max":0,"pool":119,"namespace":"","shard_id":?,"max":0}

        "peer": "31(4)", 
            "last_update": "8322636'789214",
            "last_complete": "8322636'789214",
            "log_tail": "8304626'786030",
            "last_backfill": "MIN",
        "peer": "36(4)",
            "last_update": "7942013'651879",
            "last_complete": "7942013'651879",
            "log_tail": "7937936'649586",
            "last_backfill": "MIN",
        "peer": "65(4)",
            "last_update": "7941969'651868",
            "last_complete": "7941969'651868",
            "log_tail": "7937936'649586",
            "last_backfill": "MIN",
        "peer": "81(4)",
            "last_update": "7941969'651868",
            "last_complete": "7941969'651868",
            "log_tail": "7937936'649586",
            "last_backfill": "MIN",
        "peer": "94(4)",
            "last_update": "7941920'651866",
            "last_complete": "7941920'651866",
            "log_tail": "7937936'649586",
            "last_backfill": "MIN",

        "peer": "13(5)", <-- apparently empty
            "last_update": "7936103'646007",
            "last_complete": "7936103'646007",
            "log_tail": "7927639'643715",
            "last_backfill": "MIN",
        "peer": "23(5)", <-- apparently empty
            "last_update": "8078679'702826",
            "last_complete": "8078679'702826",
            "log_tail": "8071492'700187",
            "last_backfill": "MIN",
        "peer": "145(5)", <-- apparently empty
            "last_update": "7936058'645952",
            "last_complete": "7936058'645952",
            "log_tail": "7927639'643715",
            "last_backfill": "MIN",

Yeah, osd.31 has a copy:

root@mira093:/var/lib/ceph/osd/ceph-31# ceph-objectstore-tool --data-path . '["119.385s4",{"oid":"10006fc22f8.00000000","key":"","snapid":-2,"hash":1542341509,"max":0,"pool":119,"namespace":"","shard_id":4,"max":0}]' dump {
"id": {
"oid": "10006fc22f8.00000000",
"key": "",
"snapid": -2,
"hash": 1542341509,
"max": 0,
"pool": 119,
"namespace": "",
"shard_id": 4,
"max": 0
},
"info": {
"oid": {
"oid": "10006fc22f8.00000000",
"key": "",
"snapid": -2,
"hash": 1542341509,
"max": 0,
"pool": 119,
"namespace": ""
},
"version": "7936015'645867",
"prior_version": "7935315'645757",

Ok, with osd.31 we have 4 copies of the correct version of this object. However, min_size is 5, so one would assume that we should have a 5th copy somewhere. Here's a somewhat more complicated sequence that could explain it using recovery-below-min-size:

epoch 9 acting [0,1,2,3,4,5] 0,1,2,3,4,5 commit up to 9'90
epoch 10 acting [0,1,2,3,4,NULL] 0,1,2,3 start at commit up to 10'110 but 4 only commits to 10'100
epoch 12 peered [0,1,2,NULL,4,6(backfill)] recovery below min_size, 4 is fast-forwarded to 10'110 with 10 missing objects, 6 has an empty pg created with last_backfill=MIN, recovery_unfound
epoch 13 acting [0,1,2,NULL,4,5] logs are contiguous, osds recover everything but the 10 objects missing on 5 and write up to 13'1000
epoch 14 acting [0,1,2,3(backfill),NULL,5] osd.3 has the 4th copies of the objects from 10'100~10'110, but gets marked backfill during activate() because its log is non-contiguous

Nvm, we'd rollback in epoch 11 above and recovery below min_size would not set last_epoch_started so we should still be unable to perform writes until we have min_size copies of prior interval objects. Still thinking about that part, but I think the activate() bug above is still the primary problem.

proc_master_log -> merge_log -> log.roll_forward_to -> advance_can_rollback_to

I think recovery below min_size (peered) is clearing can_rollback_to. That probably explains how osd.69's copy didn't end up authoritative.

epoch 100 [0, 1, 2, 3 , 4, 5 ] (100'950, 100'1000]
epoch 110 [0, 1, 2, 3 , 4, N ] 0,1,2,3 (100'960, 110'1020] 4 (100'955, 110'1010]
epoch 111 [0, 1, 2, 3 , N, 6b] (100'960, 110'1020] 6 empty, 0,1,2,3 crt = 110'1020
epoch 112 [0, 1, 2, N , 4, 5 ] (112'1050, 112'2000] 10 objects unfound
epoch 113 [0, 1, 2, 3b, 4, 5 ] 3 has been marked backfill despite having the only copy

2021-02-05T05:08:40.959 INFO:tasks.ceph.ceph_manager.ceph:PG 3.1a is not active+clean
2021-02-05T05:08:40.959 INFO:tasks.ceph.ceph_manager.ceph:{'pgid': '3.1a', 'version': "854'670", 'reported_seq': '3258', 'reported_epoch': '1214', 'state': 'active+recovery_unfound+undersized+degraded+remapped', 'last_fresh': '2021-02-05T05:08:33.464519+0000', 'last_change': '2021-02-05T04:48:31.561421+0000', 'last_active': '2021-02-05T05:08:33.464519+0000', 'last_peered': '2021-02-05T05:08:33.464519+0000', 'last_clean': '2021-02-05T04:46:59.032407+0000', 'last_became_active': '2021-02-05T04:48:28.963999+0000', 'last_became_peered': '2021-02-05T04:48:28.963999+0000', 'last_unstale': '2021-02-05T05:08:33.464519+0000', 'last_undegraded': '2021-02-05T04:48:28.917627+0000', 'last_fullsized': '2021-02-05T04:48:28.915212+0000', 'mapping_epoch': 542, 'log_start': "0'0", 'ondisk_log_start': "0'0", 'created': 248, 'last_epoch_clean': 419, 'parent': '0.0', 'parent_split_bits': 5, 'last_scrub': "337'483", 'last_scrub_stamp': '2021-02-05T04:45:01.365816+0000', 'last_deep_scrub': "0'0", 'last_deep_scrub_stamp': '2021-02-05T04:39:32.894141+0000', 'last_clean_scrub_stamp': '2021-02-05T04:45:01.365816+0000', 'log_size': 670, 'ondisk_log_size': 670, 'stats_invalid': False, 'dirty_stats_invalid': False, 'omap_stats_invalid': False, 'hitset_stats_invalid': False, 'hitset_bytes_stats_invalid': False, 'pin_stats_invalid': False, 'manifest_stats_invalid': False, 'snaptrimq_len': 209, 'stat_sum': {'num_bytes': 41926656, 'num_objects': 22, 'num_object_clones': 20, 'num_object_copies': 132, 'num_objects_missing_on_primary': 0, 'num_objects_missing': 0, 'num_objects_degraded': 6, 'num_objects_misplaced': 0, 'num_objects_unfound': 2, 'num_objects_dirty': 22, 'num_whiteouts': 0, 'num_read': 70, 'num_read_kb': 76186, 'num_write': 118, 'num_write_kb': 30480, 'num_scrub_errors': 0, 'num_shallow_scrub_errors': 0, 'num_deep_scrub_errors': 0, 'num_objects_recovered': 107, 'num_bytes_recovered': 113426432, 'num_keys_recovered': 0, 'num_objects_omap': 0, 'num_objects_hit_set_archive': 0, 'num_bytes_hit_set_archive': 0, 'num_flush': 0, 'num_flush_kb': 0, 'num_evict': 0, 'num_evict_kb': 0, 'num_promote': 0, 'num_flush_mode_high': 0, 'num_flush_mode_low': 0, 'num_evict_mode_some': 0, 'num_evict_mode_full': 0, 'num_objects_pinned': 0, 'num_legacy_snapsets': 0, 'num_large_omap_objects': 0, 'num_objects_manifest': 0, 'num_omap_bytes': 0, 'num_omap_keys': 0, 'num_objects_repaired': 0}, 'up': [11, 1, 10, 5, 0, 9], 'acting': [11, 2147483647, 2147483647, 5, 0, 9], 'avail_no_missing': ['11(0)', '5(3)', '7(1)', '8(2)', '9(5)'], 'object_location_counts': [{'shards': '0(4),5(3),9(5),11(0)', 'objects': 20}, {'shards': '5(3),9(5),11(0)', 'objects': 2}], 'blocked_by': [], 'up_primary': 11, 'acting_primary': 11, 'purged_snaps': []}
2021-02-05T05:08:40.960 INFO:tasks.thrashosds.thrasher:Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 116, in wrapper
    return func(self)
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 1195, in _do_thrash
    timeout=self.config.get('timeout')
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 2585, in wait_for_recovery
    'wait_for_recovery: failed before timeout expired'
AssertionError: wait_for_recovery: failed before timeout expired

2021-02-05T05:08:40.960 ERROR:tasks.thrashosds.thrasher:exception:
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 1070, in do_thrash
    self._do_thrash()
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 116, in wrapper
    return func(self)
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 1195, in _do_thrash
    timeout=self.config.get('timeout')
  File "/home/teuthworker/src/git.ceph.com_ceph_74275226ac79999bfd40e683dc9a1309e76033bf/qa/tasks/ceph_manager.py", line 2585, in wait_for_recovery
    'wait_for_recovery: failed before timeout expired'
AssertionError: wait_for_recovery: failed before timeout expired

/a/teuthology-2021-02-03_03:31:04-rados-pacific-distro-basic-smithi/5852263 - with logs

https://tracker.ceph.com/issues/48613#note-13

I think this has the same root cause as https://tracker.ceph.com/issues/48613. Accepting IO below min_size I think could plausibly account for all of the above.

Samuel Just wrote:

I think this has the same root cause as https://tracker.ceph.com/issues/48613. Accepting IO below min_size I think could plausibly account for all of the above.

OK, so close as a duplicate of #48613 which was fixed by https://github.com/ceph/ceph/pull/40572 ?