Ceph » RADOS

investigating using: https://github.com/ideepika/ceph/pull/new/wip-tracker-48613

tuethology command:

~/teuthology/virtualenv/bin/teuthology-suite -m smithi --suite rados/thrash-erasure-code --filter="workloads,ec-radosbench,ec-small-objects" --sha1 e73c0970a1f10cdd544d9450bd5ff774224e486b --suite-repo https://github.com/ideepika/ceph.git --suite-branch wip-tracker-48613 -p 150 --limit 100

I did a run with https://github.com/ceph/ceph/pull/38906/commits ( passes )
http://pulpito.front.sepia.ceph.com/ideepika-2021-01-28_15:16:46-rados:thrash-erasure-code-wip-deepika-testing-tracker-48609-distro-basic-smithi/

without( which results in dead job )
http://pulpito.front.sepia.ceph.com/ideepika-2021-01-28_12:01:26-rados:thrash-erasure-code-master-distro-basic-smithi/

config values used:

osd debug inject dispatch delay duration: 0.2
osd debug inject dispatch delay probability: 0.1

'num_objects_unfound': 1
'state': 'active+recovery_unfound+undersized+degraded+remapped'

can reproduce the desired state
/ceph/teuthology-archive/ideepika-2021-02-01_14:53:09-rados:thrash-erasure-code-wip-cbodley-testing-distro-basic-smithi/5846467/teuthology.log

job that didn't go dead, but timedout on recovering:

state: "active+recovering+undersized+degraded+remapped
failure_reason: failed to complete snap trimming before timeout

http://pulpito.front.sepia.ceph.com/ideepika-2021-02-01_14:53:09-rados:thrash-erasure-code-wip-cbodley-testing-distro-basic-smithi/

so an interesting thing that I can see, all the inactive pg's have weird osd_id number in their acting set:

{'pgid': '3.30', 'osds': [2147483647, 0, 0, 2147483647, 4, 2]}, {'pgid': '3.31', 'osds': [2147483647, 4, 2147483647, 0, 2, 2]}, {'pgid': '3.32', 'osds': [0, 4, 4, 5, 2, 6]}, {'pgid': '3.33', 'osds': [4, 6, 0, 5, 2, 0]}, {'pgid': '3.34', 'osds': [4, 2, 2147483647, 0, 5, 2147483647]}, {'pgid': '3.35', 'osds': [2147483647, 2147483647, 0, 4, 4, 2]}, {'pgid': '3.36', 'osds': [2147483647, 2147483647, 0, 0, 2, 4]},

'epoch': 242

{'pgid': '3.30', 'osds': [5, 0, 0, 6, 4, 2]}, {'pgid': '3.31', 'osds': [6, 4, 5, 0, 2, 2]}, {'pgid': '3.32', 'osds': [0, 4, 4, 5, 2, 6]}, {'pgid': '3.33', 'osds': [4, 6, 0, 5, 2, 0]}, {'pgid': '3.34', 'osds': [4, 2, 6, 0, 5, 5]}, {'pgid': '3.35', 'osds': [6, 5, 0, 4, 4, 2]}, {'pgid': '3.36', 'osds': [2147483647, 2147483647, 0, 0, 2, 4]},

epoch 271:

{'pgid': '3.30', 'osds': [5, 0, 0, 6, 4, 2]}, {'pgid': '3.31', 'osds': [6, 4, 5, 0, 2, 2]}, {'pgid': '3.32', 'osds': [0, 4, 4, 5, 2, 6]}, {'pgid': '3.33', 'osds': [4, 6, 0, 5, 2, 0]}, {'pgid': '3.34', 'osds': [4, 2, 6, 0, 5, 5]}, {'pgid': '3.35', 'osds': [6, 5, 0, 4, 4, 2]}, {'pgid': '3.36', 'osds': [6, 5, 0, 0, 2, 4]}, {'pgid': '3.37', 'osds': [6, 5, 6, 6, 2, 4]}], 

epoch 441:

{'pgid': '3.30', 'osds': [5, 0, 0, 6, 4, 2]}, {'pgid': '3.31', 'osds': [6, 4, 5, 0, 2, 2]}, {'pgid': '3.32', 'osds': [0, 4, 4, 5, 2, 6]}, {'pgid': '3.33', 'osds': [4, 6, 0, 5, 2, 0]}, {'pgid': '3.34', 'osds': [4, 2, 6, 0, 5, 5]}, {'pgid': '3.35', 'osds': [6, 5, 0, 4, 4, 2]}, {'pgid': '3.36', 'osds': [6, 5, 0, 0, 2, 4]}

epoch 1229:

{'pgid': '3.30', 'osds': [5, 3, 0, 7, 4, 1]}, {'pgid': '3.31', 'osds': [1, 4, 5, 0, 7, 3]}, {'pgid': '3.32', 'osds': [0, 4, 7, 5, 3, 6]}, {'pgid': '3.33', 'osds': [3, 4, 0, 5, 7, 0]}, {'pgid': '3.34', 'osds': [4, 7, 7, 0, 3, 5]}, {'pgid': '3.35', 'osds': [7, 5, 0, 3, 1, 4]}, {'pgid': '3.36', 'osds': [3, 5, 3, 0, 7, 4]},

'epoch': 1649

{'pgid': '3.30', 'osds': [5, 3, 0, 7, 4, 1]}, {'pgid': '3.31', 'osds': [1, 7, 5, 0, 7, 3]}, {'pgid': '3.32', 'osds': [0, 7, 1, 5, 3, 7]}, {'pgid': '3.33', 'osds': [3, 4, 1, 5, 7, 0]}, {'pgid': '3.34', 'osds': [7, 7, 1, 0, 3, 5]}, {'pgid': '3.35', 'osds': [7, 5, 0, 3, 1, 1]}, {'pgid': '3.36', 'osds': [3, 5, 0, 1, 7, 4]},

{'pgid': '3.30', 'osds': [5, 3, 0, 7, 2147483647, 2]}, {'pgid': '3.31', 'osds': [2147483647, 7, 5, 0, 2, 3]}, {'pgid': '3.32', 'osds': [0, 2, 7, 5, 3, 2147483647]}, {'pgid': '3.33', 'osds': [3, 2147483647, 2147483647, 5, 7, 0]}, {'pgid': '3.34', 'osds': [7, 2147483647, 2147483647, 0, 3, 5]}, {'pgid': '3.35', 'osds': [2147483647, 5, 0, 3, 2147483647, 2]}, {'pgid': '3.36', 'osds': [2147483647, 5, 3, 0, 7, 2147483647]}, {'pgid': '3.37', 'osds': [7, 5, 0, 3, 2, 2147483647]},

epoch': 2673

{'pgid': '3.30', 'osds': [5, 3, 0, 6, 4, 2]}, {'pgid': '3.31', 'osds': [1, 6, 5, 0, 2, 3]}, {'pgid': '3.32', 'osds': [0, 2, 7, 5, 3, 6]}, {'pgid': '3.33', 'osds': [3, 6, 0, 5, 2, 0]}, {'pgid': '3.34', 'osds': [2, 2, 6, 0, 3, 5]}, {'pgid': '3.35', 'osds': [6, 5, 0, 3, 1, 2]}, {'pgid': '3.36', 'osds': [6, 5, 3, 0, 3, 2]}

'epoch': 2781

{'pgid': '3.30', 'osds': [5, 2147483647, 0, 2147483647, 4, 2]}, {'pgid': '3.31', 'osds': [6, 4, 5, 2147483647, 2, 2147483647]}, {'pgid': '3.32', 'osds': [0, 4, 7, 5, 2147483647, 6]}, {'pgid': '3.33', 'osds': [2147483647, 2, 4, 5, 7, 0]}, {'pgid': '3.34', 'osds': [2147483647, 2, 6, 0, 2147483647, 5]}, {'pgid': '3.36', 'osds': [6, 5, 2147483647, 0, 2147483647, 4]}

'epoch': 2781
osd': 3, 'uuid': 'aca1595a-005a-4704-b6d4-b95cd5736a62', 'up': 0, 'in': 1,

strange acting set:

'up': [5, 3, 6, 7, 4, 2], 'acting': [5, 3, 2147483647, 2147483647, 4, 2]

which actually is:

'peering_crush_bucket_mandatory_member': 2147483647

On : http://qa-proxy.ceph.com/teuthology/ideepika-2021-02-01_14:53:09-rados:thrash-erasure-code-wip-cbodley-testing-distro-basic-smithi/5846471/teuthology.log
['3.19', '3.70', '3.88'] to go clean

PR that introduced this metric: https://github.com/ceph/ceph/pull/35906
will continue investigation tomorrow.

Deepika Upadhyay wrote:

so an interesting thing that I can see, all the inactive pg's have weird osd_id number in their acting set:

[...]

'epoch': 242
[...]

epoch 271:
[...]

epoch 441:
[...]

epoch 1229:
[...]

'epoch': 1649
[...]

[...]

epoch': 2673
[...]

'epoch': 2781
[...]

'epoch': 2781
osd': 3, 'uuid': 'aca1595a-005a-4704-b6d4-b95cd5736a62', 'up': 0, 'in': 1,

strange acting set:
[...]

which actually is:
[...]

it stands for CRUSH_ITEM_NONE and is used as a placeholder for EC PGs when there aren't OSDs available to be mapped to them, see crush/crush.h for details

https://tracker.ceph.com/issues/48417#note-14

rados/thrash-erasure-code-big/{ceph cluster/{12-osds openstack} mon_election/classic msgr-failures/fastclose objectstore/bluestore-comp-zstd rados recovery-overrides/{more-async-partial-recovery} supported-random-distro$/{ubuntu_latest} thrashers/fastread thrashosds-health workloads/ec-rados-plugin=jerasure-k=4-m=2}

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

see teuthology: /home/ideepika/crt.log

./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T04:53:51.207+0000 7f05d5a29700 10 osd.11 pg_epoch: 854 pg[3.1as0( v 854'669 (0'0,854'669] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 luod=823'668 crt=823'668 lcod 811'666 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=193] execute_ctx 3:5a96ee3e:::smithi05121792-2:head [append 0~0] ov 854'669 av 854'670 snapc 304=[304,2ff,2fc,2fb,2fa,2f6,2f2,2f0,2ef,2ee,2eb,2e9,2e8,2e7,2e3,2e1,2e0,2dc,2d8,2d4,2d1,2cb,2c7,2c1,2bd,2bb,2b2,2af,2ab,2a0,298,290,255,216,1f0,183] snapset 304=[]:{125=[116,115,10f,10b,106,f6],142=[13f,13b,133,12d],154=[153,151,150],158=[158,157],16c=[16b,166,165,161],189=[189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170],21c=[21c,21a,218,216,210,20a,203,200,1fe,1f8,1f1,1f0,1ea,1dc,1ca,1c0,1bf,1bc,1b8,1b6,1b0,1ae,1a8,1a5,19d,196],230=[230,22d,22c,22b,22a,226,224,221,21f,21e],23e=[23e,23c,23b,239,237,236,235,234,232,231],255=[255,254,251,24f,24d],263=[263,262,261,25f,25e,25d,25a,257],278=[278,275,274,273,270,269,268,267,266],2a7=[2a7,2a5,2a3,2a2,2a0,29f,29e,29c,29b,298,295,290,28d,28a,288,287,282,27e,27c],2bb=[2bb,2b8,2b7],2bd=[2bd],2e3=[2e3,2e1,2e0,2dc]}

see gist: https://gist.github.com/ideepika/16e5255932d2c4dc113f57cc9eadd6a5

```
2021-02-05T04:47:15.098+0000 7f05d9a31700 10 osd.11 470 do_recovery started 0/1 on pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 active+recovering+undersized+degraded mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(1+0)=4},4={(0+0)=4},5={(1+0)=4}} trimq=[f6~1,151~1,171~1]]

exact objects:

2021-02-05T04:47:15.098+0000 7f05d9a31700 10 osd.11 pg_epoch: 470 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 active+recovering+undersized+degraded mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(1+0)=4},4={(0+0)=4},5={(1+0)=4}} trimq=[f6~1,151~1,171~1]] recover_replicas: 3:5a96ee3e:::smithi05121792-2:189 still unfound
2021-02-05T04:47:15.098+0000 7f05d9a31700 10 osd.11 pg_epoch: 470 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 active+recovering+undersized+degraded mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(1+0)=4},4={(0+0)=4},5={(1+0)=4}} trimq=[f6~1,151~1,171~1]] recover_replicas: 3:5a96ee3e:::smithi05121792-2:head still unfound
2021-02-05T04:47:15.098+0000 7f05d9a31700 10 osd.11 pg_epoch: 470 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 active+recovering+undersized+degraded mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(1+0)=4},4={(0+0)=4},5={(1+0)=4}} trimq=[f6~1,151~1,171~1]] recover_replicas: 3:58cffdd8:::smithi05121792-42:18c still unfound
2021-02-05T04:47:15.098+0000 7f05d9a31700 10 osd.11 pg_epoch: 470 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 active+recovering+undersized+degraded mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(1+0)=4},4={(0+0)=4},5={(1+0)=4}} trimq=[f6~1,151~1,171~1]] recover_replicas: 3:58cffdd8:::smithi05121792-42:head still unfound

2021-02-05T04:47:13.882+0000 7f05d5a29700 10 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=463'631 lcod 453'629 mlcod 0'0 unknown mbc={0={(1+0)=12},1={(0+0)=12},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(0+0)=2,(1+0)=10}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.9(5)

2021-02-05T04:47:13.882+0000 7f05d5a29700 10 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=463'631 lcod 453'629 mlcod 0'0 unknown mbc={0={(1+0)=12},1={(0+0)=12},2={(0+0)=12},3={(0+0)=2,(1+0)=10},4={(0+0)=12},5={(0+0)=12}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.5(3)

2021-02-05T04:47:13.870+0000 7f05d5a29700 10 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=463'631 lcod 453'629 mlcod 0'0 unknown mbc={0={(1+0)=10},1={(0+0)=10},2={(0+0)=10},3={(0+0)=10},4={(0+0)=10},5={(0+0)=10}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.11(0)

found on 9(5), osd.5(3), osd.11(0)

2021-02-05T04:47:08.063+0000 7f05d9a31700 20 osd.11 pg_epoch: 463 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=11},1={(0+0)=2,(0+1)=9},2={(0+0)=2,(0+1)=9},3={(1+0)=11},4={(1+0)=11},5={(1+0)=11}} trimq=[f6~1]] rollforward: entry=463'630 (452'626) clone    3:5a96ee3e:::smithi05121792-2:189 by unknown.0.0:0 2021-02-05T04:47:05.093011+0000 0 snaps [189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0

crt=463'631
rollforward: entry=463'630
shouldn't rollforward be greater so that our new crt moves ahead?

grepping for missing object `3:5a96ee3e:::smithi05121792-2:189` on peer osd 5

./smithi134/log/ceph-osd.5.log.gz:2021-02-05T04:47:08.038+0000 7f9bc31db700 10 osd.5 pg_epoch: 463 pg[3.1as3( v 463'630 (0'0,463'630] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) r=3 lpr=462 pi=[418,462)/1 luod=0'0 lua=453'629 crt=453'629 lcod 453'629 mlcod 0'0 active+remapped mbc={}] add_log_entry 463'630 (452'626) clone    3:5a96ee3e:::smithi05121792-2:189 by unknown.0.0:0 2021-02-05T04:47:05.093011+0000 0 snaps [189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0

les = 463
crt=453'629

2021-02-05T04:47:08.038+0000 on osd.5 and 2021-02-05T04:47:08.063+0000 on 11 closest time duration
and same object. state changed from : active+remapped to active+recovery_wait+undersized+degraded+remapped
I think crt should have remained `crt=453'629` and hence should be cause of
problem, let's verify what happened b/w these two epochs

These two unfound objects are of interest to us. Let's figure out why these are unfound.

2021-02-05T17:07:09.111+0000 7f05d5a29700 10 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing 0 missing, 2 unfound
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.0(4): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.1(1): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.5(3): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.7(1): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.7(3): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.8(2): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.9(5): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] discover_all_missing: osd.10(2): we already have pg_missing_t
2021-02-05T17:07:09.111+0000 7f05d5a29700 10 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] find_unfound: no luck, giving up on this pg for now (already out of recovery/backfill)

investigating the 2 unfound objects, `when all_unfound_are_queried_or_lost all of
might_have_unfound` all participating osd's were up;

[11,2147483647,2147483647,5,0,9] osd 11 in acting set:

object 3:58cffdd8:::smithi05121792-42:head v 466'633, is unfound.

object that remained unfound:

./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T17:04:08.490+0000 7f05d5a29700  7 osd.11 pg_epoch: 14939 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] object 3:58cffdd8:::smithi05121792-42:head v 466'633, is unfound.

./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T17:04:08.490+0000 7f05d9a31700 10 osd.11 pg_epoch: 14939 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] handle_backoff backoff ack id 1 [3:58cffdd8:::smithi05121792-42:head,3:58cffdd8:::smithi05121792-42:head)

`[3:58cffdd8:::smithi05121792-42:head,3:58cffdd8:::smithi05121792-42:head)`

object 3:58cffdd8:::smithi05121792-42:head v 466'633, is unfound. 41813,418 3%

activate not all replicas are up-to-date, queueing recovery
(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] update_calc_stats actingset
1(1),5(3),9(5),10(2),11(0) just before unfound

for missing search the object of interest:
[11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized mbc={0={(1+0)=12},1={(0+0)=12

hmm, the object is on: search_for_missing 3:58cffdd8:::smithi05121792-42:head
466'633 is on osd.11(0) which is primary then why??
search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.9(5)

{(0+0)=1},3={(0+0)=1},4={(0+0)=1},5={(0+0)=1}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.11(0)
{(0+0)=2},3={(0+0)=2},4={(0+0)=2},5={(0+0)=2}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.11(0)
{(0+0)=3},3={(0+0)=3},4={(0+0)=3},5={(0+0)=3}}] needs_recovery_map missing {3:58cffdd8:::smithi05121792-42:18c=466'632 flags = none clean_offsets: [], clean_omap: 0, new_object: 1,3:58cffdd8::
{(0+0)=3},3={(0+0)=3},4={(0+0)=3},5={(0+0)=3}}] activate: adding 0(4) as a source
{(0+0)=3},3={(0+0)=3},4={(0+0)=3},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:18c 466'632 also missing on osd.0(4)
{(0+0)=3},3={(0+0)=3},4={(0+0)=3},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 also missing on osd.0(4)
{(0+0)=3},3={(0+0)=3},4={(0+0)=3},5={(0+0)=3}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.0(4)
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] needs_recovery_map missing {3:58cffdd8:::smithi05121792-42:18c=466'632 flags = none clean_offsets: [], clean_omap: 0, new_object: 1,3:58
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] activate: adding 1(1) as a source
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:18c 466'632 also missing on osd.1(1)
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 also missing on osd.1(1)
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 also missing on osd.1(1)
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] needs_recovery_map missing {3:58cffdd8:::smithi05121792-42:18c=466'632 flags = none clean_offsets: [], clean_omap: 0, new_object: 1,3:58
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] activate: adding 5(3) as a source
{(0+0)=3},3={(0+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:18c 466'632 is on osd.5(3)
{(0+0)=3},3={(0+0)=2,(1+0)=1},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.5(3)
{(0+0)=3},3={(0+0)=1,(1+0)=2},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.5(3)
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] needs_recovery_map missing {3:58cffdd8:::smithi05121792-42:18c=466'632 flags = none clean_offsets: [], clean_omap: 0, new_object: 1,3:58
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] activate: adding 9(5) as a source
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:18c 466'632 is on osd.9(5)
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=2,(1+0)=1}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.9(5)
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(0+0)=1,(1+0)=2}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 is on osd.9(5)
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(1+0)=3}}] needs_recovery_map missing {3:58cffdd8:::smithi05121792-42:18c=466'632 flags = none clean_offsets: [], clean_omap: 0, new_object: 1,3:58
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(1+0)=3}}] activate: adding 10(2) as a source
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(1+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:18c 466'632 also missing on osd.10(2)
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(1+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 also missing on osd.10(2)
{(0+0)=3},3={(1+0)=3},4={(0+0)=2,(1+0)=1},5={(1+0)=3}}] search_for_missing 3:5a96ee3e:::smithi05121792-2:189 463'630 also missing on osd.10(2)

so, the unfound object should be on primary 11(0)
backtracking:

the object is found on some shard's including acting primary, but still is
reported as `is_unfound`:

./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.213+0000 7f05d5a29700 10 osd.11 1554 dequeue_op 0x559100750aa0 prio 63 cost 54 latency 0.000150 osd_op(client.4548.0:4564 3.1as0 3.1bbff31a (undecoded) ondisk+retry+write+known_if_redirected e1552) v8 pg pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209]
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.213+0000 7f05d5a29700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] _handle_message: osd_op(client.4548.0:4564 3.1as0 3.1bbff31a (undecoded) ondisk+retry+write+known_if_redirected e1552) v8
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 20 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] do_op: op osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] RETRY=9 ondisk+retry+write+known_if_redirected e1552) v8
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 20 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] op_has_sufficient_caps session=0x5590fcce1de0 pool=3 (unique_pool_0 ) pool_app_metadata={rados={}} need_read_cap=0 need_write_cap=1 classes=[] -> yes
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] do_op osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] RETRY=9 ondisk+retry+write+known_if_redirected e1552) v8 may_write -> write-ordered flags ondisk+retry+write+known_if_redirected
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] readable_with_acting: locs:5(3),9(5),11(0)
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] add_backoff session 0x5590fcce1de0 added Backoff(0x5591354b5480 3.1as0 1 new [3:58cffdd8:::smithi05121792-42:head,3:58cffdd8:::smithi05121792-42:head)  session 0x5590fcce1de0 pg 0x5590faa9d000)
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700  7 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] object 3:58cffdd8:::smithi05121792-42:head v 466'633, is unfound.
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 10 osd.11 1554 dequeue_op 0x559110dd9020 prio 63 cost 0 latency 0.000518 osd_op(client.4548.0:4565 3.1as0 3.1bbff31a (undecoded) ondisk+retry+read+rwordered+known_if_redirected e1552) v8 pg pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209]
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] _handle_message: osd_op(client.4548.0:4565 3.1as0 3.1bbff31a (undecoded) ondisk+retry+read+rwordered+known_if_redirected e1552) v8
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d5a29700 20 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] do_op: op osd_op(client.4548.0:4565 3.1as0 3:58cffdd8:::smithi05121792-42:head [stat] snapc 0=[] RETRY=9 ondisk+retry+read+rwordered+known_if_redirected e1552) v8
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d9a31700 10 osd.11 1554 dequeue_op 0x5591083aa2c0 prio 63 cost 0 latency 0.000450 osd_backoff(3.1as0 ack-block id 1 [3:58cffdd8:::smithi05121792-42:head,3:58cffdd8:::smithi05121792-42:head) e1554) v1 pg pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209]
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d9a31700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] _handle_message: osd_backoff(3.1as0 ack-block id 1 [3:58cffdd8:::smithi05121792-42:head,3:58cffdd8:::smithi05121792-42:head) e1554) v1
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:41.217+0000 7f05d9a31700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] handle_backoff backoff ack id 1 [3:58cffdd8:::smithi05121792-42:head,3:58cffdd8:::smithi05121792-42:head)
./remote/smithi191/log/ceph-osd.11.log.gz:2021-02-05T05:23:42.913+0000 7f05d5a29700 10 osd.11 pg_epoch: 1554 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] handle_advance_map: 1555(

./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 453'629 (453'628) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4378 2021-02-05T04:46:57.857313+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:10.963+0000 7f79e2281700 10 osd.1 pg_epoch: 466 pg[3.1as1( v 463'631 lc 124'112 (0'0,463'631] local-lis/les=0/0 n=12 ec=248/27 lis/c=0/418 les/c/f=0/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) r=-1 lpr=462 pi=[418,462)/1 luod=0'0 crt=463'631 mlcod 463'631 active m=27 mbc={}] append_log log((0'0,463'631], crt=463'631) [466'632 (453'629) clone    3:58cffdd8:::smithi05121792-42:18c by unknown.0.0:0 2021-02-05T04:46:42.013136+0000 0 snaps [18c,18b,18a,189,188,187,186,185,183] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0,466'633 (453'629) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4564 0.000000 0 ObjectCleanRegions clean_offsets: [9306112~18446744073700245503], clean_omap: 1, new_object: 0]
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:10.963+0000 7f79e2281700 10 osd.1 pg_epoch: 466 pg[3.1as1( v 466'633 lc 124'112 (0'0,466'633] local-lis/les=0/0 n=12 ec=248/27 lis/c=0/418 les/c/f=0/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) r=-1 lpr=462 pi=[418,462)/1 luod=0'0 lua=463'631 crt=466'633 mlcod 463'631 active m=27 mbc={}] add_log_entry 466'633 (453'629) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4564 0.000000 0 ObjectCleanRegions clean_offsets: [9306112~18446744073700245503], clean_omap: 1, new_object: 0
~
```

last operations seen on this object using grep from all osd's:

792-42:head by unknown.0.0:0 2021-02-05T04:46:32.954991+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 431'604 (428'600) modify   3:58cffdd8:::smithi05121792-42:head by unknown.0.0:0 2021-02-05T04:46:35.988425+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 440'610 (431'604) modify   3:58cffdd8:::smithi05121792-42:head by unknown.0.0:0 2021-02-05T04:46:44.963070+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 444'616 (440'610) modify   3:58cffdd8:::smithi05121792-42:head by unknown.0.0:0 2021-02-05T04:46:48.996474+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 449'620 (444'616) modify   3:58cffdd8:::smithi05121792-42:head by unknown.0.0:0 2021-02-05T04:46:53.904712+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 453'627 (449'620) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4376 2021-02-05T04:46:57.855704+0000 0 ObjectCleanRegions clean_offsets: [540672~18446744073709010943], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 453'628 (453'627) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4377 2021-02-05T04:46:57.857280+0000 0 ObjectCleanRegions clean_offsets: [0~540672,720896~18446744073708830719], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:07.935+0000 7f79e2281700 20 update missing, append 453'629 (453'628) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4378 2021-02-05T04:46:57.857313+0000 0 ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:10.963+0000 7f79e2281700 10 osd.1 pg_epoch: 466 pg[3.1as1( v 463'631 lc 124'112 (0'0,463'631] local-lis/les=0/0 n=12 ec=248/27 lis/c=0/418 les/c/f=0/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) r=-1 lpr=462 pi=[418,462)/1 luod=0'0 crt=463'631 mlcod 463'631 active m=27 mbc={}] append_log log((0'0,463'631], crt=463'631) [466'632 (453'629) clone    3:58cffdd8:::smithi05121792-42:18c by unknown.0.0:0 2021-02-05T04:46:42.013136+0000 0 snaps [18c,18b,18a,189,188,187,186,185,183] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0,466'633 (453'629) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4564 0.000000 0 ObjectCleanRegions clean_offsets: [9306112~18446744073700245503], clean_omap: 1, new_object: 0]
./remote/smithi051/log/ceph-osd.1.log.gz:2021-02-05T04:47:10.963+0000 7f79e2281700 10 osd.1 pg_epoch: 466 pg[3.1as1( v 466'633 lc 124'112 (0'0,466'633] local-lis/les=0/0 n=12 ec=248/27 lis/c=0/418 les/c/f=0/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) r=-1 lpr=462 pi=[418,462)/1 luod=0'0 lua=463'631 crt=466'633 mlcod 463'631 active m=27 mbc={}] add_log_entry 466'633 (453'629) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4564 0.000000 0 ObjectCleanRegions clean_offsets: [9306112~18446744073700245503], clean_omap: 1, new_object: 0

2021-02-05T04:47:10.958+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] get_hash_info: not in cache 3:58cffdd8:::smithi05121792-42:head
2021-02-05T04:47:10.958+0000 7f05dd238700 10 bluestore(/var/lib/ceph/osd/ceph-11) stat 3.1as0_head 0#3:58cffdd8:::smithi05121792-42:head#
2021-02-05T04:47:10.958+0000 7f05dd238700 20 _pin0x5590e5ec9000   0#3:58cffdd8:::smithi05121792-42:head# pinned
2021-02-05T04:47:10.958+0000 7f05dd238700 20 _unpin0x5590e5ec9000   0#3:58cffdd8:::smithi05121792-42:head# unpinned
2021-02-05T04:47:10.958+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] get_hash_info: found on disk, size 180224
2021-02-05T04:47:10.958+0000 7f05dd238700 15 bluestore(/var/lib/ceph/osd/ceph-11) getattr 3.1as0_head 0#3:58cffdd8:::smithi05121792-42:head# hinfo_key
2021-02-05T04:47:10.958+0000 7f05dd238700 20 _pin0x5590e5ec9000   0#3:58cffdd8:::smithi05121792-42:head# pinned
2021-02-05T04:47:10.958+0000 7f05dd238700 20 _unpin0x5590e5ec9000   0#3:58cffdd8:::smithi05121792-42:head# unpinned
2021-02-05T04:47:10.958+0000 7f05dd238700 10 bluestore(/var/lib/ceph/osd/ceph-11) getattr 3.1as0_head 0#3:58cffdd8:::smithi05121792-42:head# hinfo_key = 0

verify is this complete write or just getting attrs of async_recovery_targets

min last complete on disk 463'631
calc_trim_to_aggressive limit = 463'631
11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)

2021-02-05T04:47:10.958+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] start_rmw: Op(3:58cffdd8:::smithi05121792-42:head v=466'633 tt=0'0 tid=2534 reqid=client.4548.0:4564 client_op=osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] ondisk+write+known_if_redirected e466) roll_forward_to=463'631 temp_added= temp_cleared= pending_read={} remote_read={} remote_read_result={} pending_apply= pending_commit= plan.to_read={} plan.will_write={3:58cffdd8:::smithi05121792-42:18c=[],3:58cffdd8:::smithi05121792-42:head=[8388608~917504]})
2021-02-05T04:47:10.958+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] try_state_to_reads: Op(3:58cffdd8:::smithi05121792-42:head v=466'633 tt=0'0 tid=2534 reqid=client.4548.0:4564 client_op=osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] ondisk+write+known_if_redirected e466) roll_forward_to=463'631 temp_added= temp_cleared= pending_read={} remote_read={} remote_read_result={} pending_apply= pending_commit= plan.to_read={} plan.will_write={3:58cffdd8:::smithi05121792-42:18c=[],3:58cffdd8:::smithi05121792-42:head=[8388608~917504]})
2021-02-05T04:47:10.962+0000 7f05dd238700 20 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] try_reads_to_commit: written: {3:58cffdd8:::smithi05121792-42:18c={},3:58cffdd8:::smithi05121792-42:head={8388608~917504(917504)}}

object phases plan to write -> written

2021-02-05T04:47:10.962+0000 7f05dd238700 20 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] try_reads_to_commit: 3:58cffdd8:::smithi05121792-42:head,{8388608~917504(917504)}
2021-02-05T04:47:10.962+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] should_send_op issue_repop shipping empty opt to osd.1(1), object 3:58cffdd8:::smithi05121792-42:head which is pending recovery in async_recovery_targets
2021-02-05T04:47:10.962+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 463'631 (0'0,463'631] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] should_send_op issue_repop shipping empty opt to osd.10(2), object 3:58cffdd8:::smithi05121792-42:head which is pending recovery in async_recovery_targets

should_send_op issue_repop shipping empty opt to osd.10(2), object 3:58cffdd8:::smithi05121792-42:head which is pending recovery in async_recovery_targets

2021-02-05T04:47:10.962+0000 7f05dd238700  5 --2- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] >> [v2:172.21.15.51:6802/32585,v1:172.21.15.51:6803/32585] conn(0x55910e7fbc00 0x5590f9ae8d00 crc :-1 s=READY pgs=21 cs=1 l=0 rev1=1 rx=0 tx=0).send_message enqueueing message m=0x5590f9125c00 type=108 MOSDECSubOpWrite(3.1as1 466/462 ECSubWrite(tid=2534, reqid=client.4548.0:4564, at_version=466'633, trim_to=0'0, roll_forward_to=463'631, backfill_or_async_recovery)) v2
2021-02-05T04:47:10.962+0000 7f05dd238700 15 --2- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] >> [v2:172.21.15.51:6802/32585,v1:172.21.15.51:6803/32585] conn(0x55910e7fbc00 0x5590f9ae8d00 crc :-1 s=READY pgs=21 cs=1 l=0 rev1=1 rx=0 tx=0).send_message inline write is denied, reschedule m=0x5590f9125c00

after which all the forward try to write is declined with `inline write is denied`

2021-02-05T04:47:10.962+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 luod=463'631 lua=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] add_log_entry 466'633 (453'629) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4564 0.000000 0 ObjectCleanRegions clean_offsets: [9306112~18446744073700245503], clean_omap: 1, new_object: 0
2021-02-05T04:47:10.962+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 luod=463'631 lua=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] append_log approx pg log length =  633
2021-02-05T04:47:10.962+0000 7f05dd238700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 luod=463'631 lua=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] append_log transaction_applied = 1

2021-02-05T04:47:10.966+0000 7f05d5a29700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 luod=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] get_object_context: 0x5590f5e11b80 3:58cffdd8:::smithi05121792-42:head rwstate(write n=1 w=0) oi: 3:58cffdd8:::smithi05121792-42:head(466'633 client.4548.0:4564 dirty|data_digest s 9306112 uv 342 dd 2c31329d alloc_hint [0 0 0]) exists: 1 ssc: 0x5590f2f7c420 snapset: 18c=[]:{ea=[b8],109=[106,f6],133=[133,12d,116,115,10f,10b],18c=[18c,18b,18a,189,188,187,186,185,183]}
2021-02-05T04:47:10.966+0000 7f05d5a29700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 luod=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] find_object_context 3:58cffdd8:::smithi05121792-42:head @head oi=3:58cffdd8:::smithi05121792-42:head(466'633 client.4548.0:4564 dirty|data_digest s 9306112 uv 342 dd 2c31329d alloc_hint [0 0 0])
2021-02-05T04:47:10.966+0000 7f05d5a29700 10 osd.11 pg_epoch: 466 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=462 pi=[418,462)/1 luod=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+recovery_wait+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1]] readable_with_acting: locs:0(4),5(3),9(5),11(0)

readable_with_acting: locs:0(4),5(3),9(5),11(0)

2021-02-05T04:47:10.994+0000 7f05f9c1a700  5 --2- [v2:172.21.15.191:6816/16961,v1:172.21.15.191:6817/16961] >> [v2:172.21.15.134:3300/0,v1:172.21.15.134:6789/0] conn(0x5590e5106400 0x5590e61d3900 secure :-1 s=READY pgs=40 cs=0 l=1 rev1=1 rx=0x5590e5108810 tx=0x5590e509d500).write_message sending message m=0x559107ec0d80 seq=291 osd_failure(failed immediate osd.0 [v2:172.21.15.51:6816/16914,v1:172.21.15.51:6817/16914] for 21sec e466 v466) v4
2021-02-05T04:47:10.994+0000 7f05f9c1a700 20 --2- [v2:172.21.15.191:6816/16961,v1:172.21.15.191:6817/16961] >> [v2:172.21.15.134:3300/0,v1:172.21.15.134:6789/0] conn(0x5590e5106400 0x5590e61d3900 secure :-1 s=READY pgs=40 cs=0 l=1 rev1=1 rx=0x5590e5108810 tx=0x5590e509d500).write_message sending m=0x559107ec0d80 seq=291 src=osd.11 off=0
2021-02-05T04:47:10.994+0000 7f05f9419700  5 --2- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] >> [v2:172.21.15.51:6818/16914,v1:172.21.15.51:6819/16914] conn(0x5590ee618800 0x5590ee63c800 unknown :-1 s=READY pgs=290 cs=48 l=0 rev1=1 rx=0 tx=0).requeue_sent requeueing message m=0x5590f85e1100 seq=5817 type=108 MOSDECSubOpWrite(3.es4 466/398 ECSubWrite(tid=2532, reqid=osd.11.0:2530, at_version=0'0, trim_to=0'0, roll_forward_to=466'323)) v2

osd 0 goes down

2021-02-05T04:47:13.870+0000 7f05d5a29700 10 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=463'631 lcod 453'629 mlcod 0'0 unknown mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(0+0)=4},4={(0+0)=4},5={(0+0)=4}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.11(0)

after which also we have that object on osd 11, but after add_log_entry crt moves to v 466'633 which ultimately during snapshort trimming trims the pg log... shortly after which we see "is unfound"

for trimming and crt:

  2021-02-05T04:47:13.942+0000 7f05f9419700 20 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] >> [v2:172.21.15.51:6802/32585,v1:172.21.15.51:6803/32585] conn(0x55910e7fbc00 msgr2=0x5590f9ae8d00 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).process
2021-02-05T04:47:13.942+0000 7f05d7a2d700 15 bluestore(/var/lib/ceph/osd/ceph-11) _omap_setkeys 3.16s3_head 3#3:68000000::::head#
2021-02-05T04:47:13.942+0000 7f05d7a2d700 20 bluestore(/var/lib/ceph/osd/ceph-11) _omap_setkeys  0x0000000000000AC5'._info' <- _info
2021-02-05T04:47:13.942+0000 7f05f9419700 20 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] >> [v2:172.21.15.51:6802/32585,v1:172.21.15.51:6803/32585] conn(0x55910e7fbc00 msgr2=0x5590f9ae8d00 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read continue len=32
2021-02-05T04:47:13.942+0000 7f05d7a2d700 20 bluestore(/var/lib/ceph/osd/ceph-11) _omap_setkeys  0x0000000000000AC5'.can_rollback_to' <- can_rollback_to
2021-02-05T04:47:13.942+0000 7f05d7a2d700 20 bluestore(/var/lib/ceph/osd/ceph-11) _omap_setkeys  0x0000000000000AC5'.rollback_info_trimmed_to' <- rollback_info_trimmed_to
2021-02-05T04:47:13.942+0000 7f05d7a2d700 10 bluestore(/var/lib/ceph/osd/ceph-11) _omap_setkeys 3.16s3_head 3#3:68000000::::head# = 0
2021-02-05T04:47:13.942+0000 7f05d7a2d700 15 bluestore(/var/lib/ceph/osd/ceph-11) _omap_rmkeys 3.16s3_head 3#3:68000000::::head#
2021-02-05T04:47:13.942+0000 7f05d7a2d700 20 bluestore(/var/lib/ceph/osd/ceph-11) _omap_rmkeys  rm 0x0000000000000AC5'._fastinfo' <- _fastinfo
2021-02-05T04:47:13.942+0000 7f05d7a2d700 10 bluestore(/var/lib/ceph/osd/ceph-11) _omap_rmkeys 3.16s3_head 3#3:68000000::::head# = 0
2021-02-05T04:47:13.942+0000 7f05d7a2d700 10 bluestore(/var/lib/ceph/osd/ceph-11) _txc_calc_cost 0x5590f99309c0 cost 5534 (1 ios * 4000 + 1534 bytes)

peering starts and we have crt updated:

2021-02-05T04:47:13.942+0000 7f05f9419700 20 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] >> [v2:172.21.15.51:6802/32585,v1:172.21.15.51:6803/32585] conn(0x55910e7fbc00 msgr2=0x5590f9ae8d00 unknown :-1 s=STATE_CONNECTION_ESTABLISHED l=0).read start len=32
2021-02-05T04:47:13.942+0000 7f05d5a29700 10 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized+degraded mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] do_peering_event: epoch_sent: 469 epoch_requested: 469 MInfoRec from 1(1) info: 3.1as1( v 466'633 lc 124'112 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) pg_lease_ack(ruub 498.265228271s)

last updated: crt=452'525 -> crt=466'633 timestamp 2021-02-05T04:47:13.942+0000
2021-02-05T04:47:13.942+0000 7f05d5a29700 20 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized+degraded mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] update_calc_stats actingset 1(1),5(3),9(5),10(2),11(0) upset 1(1),5(3),9(5),10(2),11(0) acting_recovery_backfill 1(1),5(3),9(5),10(2),11(0)

2021-02-05T17:15:00.959+0000 7f05d9a31700  7 osd.11 pg_epoch: 15054 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] object 3:58cffdd8:::smithi05121792-42:head v 466'633, is unfound.

personal ref dir: all grep reside in /home/ideepika/pg[3.1as0.log in teuthology server

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

`rados/thrash-erasure-code-big/{ceph cluster/{12-osds openstack} mon_election/classic msgr-failures/fastclose objectstore/bluestore-comp-zstd rados recovery-overrides/{more-async-partial-recovery} supported-random-distro$/{ubuntu_latest} thrashers/fastread thrashosds-health workloads/ec-rados-plugin=jerasure-k=4-m=2}`

acting set:

two objects that remained unfound even after recovery:

3:58cffdd8:::smithi05121792-42:head v 466'633
3:58cffdd8:::smithi05121792-42:18c v 466'632

looking into object `3:58cffdd8:::smithi05121792-42:head v 466'633`

found on

2021-02-05T04:48:11.005+0000 7f05d5a29700 10 osd.11 pg_epoch: 525 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=524/525 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=524) [11,1,10,7,NONE,9]/[11,1,10,NONE,NONE,9]p11(0) async=[7(3)] r=0 lpr=524 pi=[418,524)/2 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized+degraded+remapped mbc={0={(1+0)=12},1={(0+0)=4,(1+1)=8},2={(0+0)=4,(1+1)=8},3={(0+0)=8,(0+1)=4},4={(0+0)=12},5={(1+0)=12}} trimq=26] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.5(3)
2021-02-05T04:48:10.957+0000 7f05d5a29700 10 osd.11 pg_epoch: 525 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=524/525 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=524) [11,1,10,7,NONE,9]/[11,1,10,NONE,NONE,9]p11(0) async=[7(3)] r=0 lpr=524 pi=[418,524)/2 crt=466'633 lcod 453'629 mlcod 0'0 remapped mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(0+0)=4},4={(0+0)=4},5={(0+0)=4}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.11(0)
2021-02-05T04:48:10.957+0000 7f05d5a29700 10 osd.11 pg_epoch: 525 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=524/525 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=524) [11,1,10,7,NONE,9]/[11,1,10,NONE,NONE,9]p11(0) async=[7(3)] r=0 lpr=524 pi=[418,524)/2 crt=466'633 lcod 453'629 mlcod 0'0 remapped mbc={0={(1+0)=12},1={(0+0)=4,(1+0)=8},2={(0+0)=12},3={(0+0)=12},4={(0+0)=12},5={(0+0)=8,(1+0)=4}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 is on osd.9(5)

osd 0 went down [ @epoch 467 ] while peering and 7 replaced

2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped+peering pruub 492.368682861s@0 mbc={}] check_prior_readable_down_osds prior_readable_down_osds osd.0 is dead as of epoch 467

we requeued osd_op.

these objects being still unfound + peer 0(4) down, we receive `modify&clone` op on these objects

which moves crt forward.

we don't have async recovered obj on [1 ,10] only 3 peers [ 11,5,9] have it,

In Octopus, erasure coded pools can recover as long as there are at least K shards available. (With fewer than K shards, you have actually lost data!) [ object shall never recover. ]

  7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped pruub 492.368682861s@ mbc={}]  canceling repop tid 2534
2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped pruub 492.368682861s@ mbc={}]  requeuing osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] ondisk+write+known_if_redirected e466) v8
2021-02-05T04:47:11.902+0000 7f05d9a31700 10 osd.11 467 dequeue_op 0x5590f620c520 prio 63 cost 54 latency 1.037837 osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] ondisk+write+known_if_redirected e466) v8 pg pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped+peering mbc={}]
2021-02-05T04:47:11.902+0000 7f05d9a31700 10 osd.11 467 dequeue_op 0x5590f2f7db80 prio 63 cost 0 latency 1.037762 osd_op(client.4548.0:4565 3.1as0 3:58cffdd8:::smithi05121792-42:head [stat] snapc 0=[] ondisk+read+rwordered+known_if_redirected e466) v8 pg pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped+peering mbc={}]
2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped pruub 492.368682861s@ mbc={}]  canceling repop tid 2534
2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped pruub 492.368682861s@ mbc={}]  requeuing osd_op(client.4548.0:4564 3.1as0 3:58cffdd8:::smithi05121792-42:head [copy-from ver 342 in=54b] snapc 18c=[18c,18b,18a,189,188,187,186,185,183,182,180,17d,17c,17b,17a,178,174,173,172,171,170,16b,166,165,161,158,157,153,150,147,146,145,13f,13b,133,12d,116,115,10f,10b,106,b8] ondisk+write+known_if_redirected e466) v8

2021-02-05T04:47:13.882+0000 7f05d5a29700 10 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=463'631 lcod 453'629 mlcod 0'0 activating+undersized mbc={0={(1+0)=12},1={(0+0)=12},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] release_backoffs [3:58000000::::0,3:60000000::::head)
2021-02-05T04:47:13.882+0000 7f05d5a29700 20 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized mbc={0={(1+0)=12},1={(0+0)=12},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] rollforward: entry=466'632 (453'629) clone    3:58cffdd8:::smithi05121792-42:18c by unknown.0.0:0 2021-02-05T04:46:42.013136+0000 0 snaps [18c,18b,18a,189,188,187,186,185,183] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0
2021-02-05T04:47:13.882+0000 7f05d5a29700 20 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized mbc={0={(1+0)=12},1={(0+0)=12},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] rollforward: entry=466'633 (453'629) modify   3:58cffdd8:::smithi05121792-42:head by client.4548.0:4564 0.000000 0 ObjectCleanRegions clean_offsets: [9306112~18446744073700245503], clean_omap: 1, new_object: 0

we should check previous transaction applied as well here:

//void PeeringState::append_log
if (!transaction_applied) {
     /* We must be a backfill or async recovery peer, so it's ok if we apply
      * out-of-turn since we won't be considered when
      * determining a min possible last_update.
      *
      * We skip_rollforward() here, which advances the crt, without
      * doing an actual rollforward. This avoids cleaning up entries
      * from the backend and we do not end up in a situation, where the
      * object is deleted before we can _merge_object_divergent_entries().
      */
    pg_log.skip_rollforward();
  }

right after which we declare it unfound, and persistantly `is unfound` state remains for object `3:58cffdd8:::smithi05121792-42:head v 466'633`

2021-02-05T04:47:13.946+0000 7f05d9a31700  7 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=468/418 les/c/f=469/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 active+undersized+degraded mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] object 3:58cffdd8:::smithi05121792-42:head v 466'633, is unfound.

`3:58cffdd8:::smithi05121792-42:head v 466'633` missing on async targets 1(1) and 10(2) osd

2021-02-05T04:48:23.925+0000 7f05d5a29700 10 osd.11 pg_epoch: 538 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=537/538 n=12 ec=248/27 lis/c=524/418 les/c/f=525/419/0 sis=537) [11,1,10,7,0,9]/[11,1,NONE,NONE,0,9]p11(0) async=[7(3),10(2)] r=0 lpr=537 pi=[418,537)/2 crt=466'633 lcod 453'629 mlcod 0'0 remapped mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(0+0)=4},4={(0+0)=4},5={(0+0)=4}}] search_for_missing 3:58cffdd8:::smithi05121792-42:18c 466'632 also missing on osd.0(4)
2021-02-05T04:48:23.925+0000 7f05d5a29700 10 osd.11 pg_epoch: 538 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=537/538 n=12 ec=248/27 lis/c=524/418 les/c/f=525/419/0 sis=537) [11,1,10,7,0,9]/[11,1,NONE,NONE,0,9]p11(0) async=[7(3),10(2)] r=0 lpr=537 pi=[418,537)/2 crt=466'633 lcod 453'629 mlcod 0'0 remapped mbc={0={(1+0)=4},1={(0+0)=4},2={(0+0)=4},3={(0+0)=4},4={(0+0)=4},5={(0+0)=4}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 also missing on osd.0(4)

when osd 0 came back up we still have object missing on it(osd 0 went down when we were doing osd_op on these objects)

//0
2021-02-05T04:48:28.909+0000 7f05d5a29700 10 osd.11 pg_epoch: 543 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=542/543 n=12 ec=248/27 lis/c=537/418 les/c/f=538/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=466'633 lcod 453'629 mlcod 0'0 remapped mbc={0={(1+0)=3},1={(0+0)=3},2={(0+0)=3},3={(0+0)=3},4={(0+0)=3},5={(0+0)=3}}] search_for_missing 3:58cffdd8:::smithi05121792-42:head 466'633 also missing on osd.0(4)

//2 missing on 0,1,10 indefinately
2021-02-05T17:07:09.111+0000 7f05d9a31700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] update_calc_stats missing shard 0(4) missing= 2
2021-02-05T17:07:09.111+0000 7f05d9a31700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] update_calc_stats missing shard 1(1) missing= 2
2021-02-05T17:07:09.111+0000 7f05d9a31700 20 osd.11 pg_epoch: 14973 pg[3.1as0( v 854'670 (0'0,854'670] local-lis/les=542/543 n=22 ec=248/27 lis/c=542/418 les/c/f=543/419/0 sis=542) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) async=[1(1),10(2)] r=0 lpr=542 pi=[418,542)/2 crt=854'670 lcod 854'669 mlcod 463'631 active+recovery_unfound+undersized+degraded+remapped mbc={0={(1+0)=2},1={(0+0)=2},2={(0+0)=2},3={(1+0)=2},4={(0+0)=2},5={(1+0)=2}} trimq=209] update_calc_stats missing shard 10(2) missing= 2

on verifying whether object was actually written in osd 0 or not didn't find any operation on object `3:58cffdd8:::smithi05121792-42:head` (/ceph/teuthology-archive/teuthology-2021-02-03_03:31:04-rados-pacific-distro-basic-smithi/5852263/remote/smithi051/log/ceph-osd.0.log) neither any updates around the time when osd 0 went down: (`2021-02-05T04:47:10`)

This is where we sent the subops

2021-02-05T04:47:10.962+0000 7f05dd238700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] --> [v2:172.21.15.51:6818/16914,v1:172.21.15.51:6819/16914] -- MOSDECSubOpWrite(3.1as4 466/462 ECSubWrite(tid=2534, reqid=client.
4548.0:4564, at_version=466'633, trim_to=0'0, roll_forward_to=463'631)) v2 -- 0x5590f5cc2300 con 0x5590ee618800
2021-02-05T04:47:10.962+0000 7f05dd238700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] --> [v2:172.21.15.51:6802/32585,v1:172.21.15.51:6803/32585] -- MOSDECSubOpWrite(3.1as1 466/462 ECSubWrite(tid=2534, reqid=client.
4548.0:4564, at_version=466'633, trim_to=0'0, roll_forward_to=463'631, backfill_or_async_recovery)) v2 -- 0x5590f9125c00 con 0x55910e7fbc00
2021-02-05T04:47:10.962+0000 7f05dd238700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] --> [v2:172.21.15.134:6802/16716,v1:172.21.15.134:6803/16716] -- MOSDECSubOpWrite(3.1as3 466/462 ECSubWrite(tid=2534, reqid=client.4548.0:4564, at_version=466'633, trim_to=0'0, roll_forward_to=463'631)) v2 -- 0x5590f9125500 con 0x5590ee616400
2021-02-05T04:47:10.962+0000 7f05dd238700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] --> [v2:172.21.15.191:6810/16958,v1:172.21.15.191:6811/16958] -- MOSDECSubOpWrite(3.1as5 466/462 ECSubWrite(tid=2534, reqid=client.4548.0:4564, at_version=466'633, trim_to=0'0, roll_forward_to=463'631)) v2 -- 0x5590f9126300 con 0x5590ee617000
2021-02-05T04:47:10.962+0000 7f05dd238700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] --> [v2:172.21.15.191:6826/16959,v1:172.21.15.191:6827/16959] -- MOSDECSubOpWrite(3.1as2 466/462 ECSubWrite(tid=2534, reqid=client.4548.0:4564, at_version=466'633, trim_to=0'0, roll_forward_to=463'631, backfill_or_async_recovery)) v2 -- 0x5590f9127100 con 0x5590ee619000

we receive replies from all peers except 0 and 1, 11 are async targets.

2021-02-05T04:47:10.966+0000 7f05f9419700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] <== osd.1 v2:172.21.15.51:6802/32585 122 ==== MOSDECSubOpWriteReply(3.1as0 466/462 ECSubWriteReply(tid=2534, last_complete=124'112, committed=1, applied=1)) v2 ==== 95+0+0 (crc 0 0 0) 0x55910bbe9e00 con 0x55910e7fbc00
2021-02-05T04:47:10.966+0000 7f05fa41b700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] <== osd.10 v2:172.21.15.191:6826/16959 1476 ==== MOSDECSubOpWriteReply(3.1as0 466/462 ECSubWriteReply(tid=2534, last_complete=124'112, committed=1, applied=1)) v2 ==== 95+0+0 (unknown 0 0 0) 0x5590f9c40d00 con 0x5590ee619000
2021-02-05T04:47:10.970+0000 7f05f9419700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] <== osd.5 v2:172.21.15.134:6802/16716 5024 ==== MOSDECSubOpWriteReply(3.1as0 466/462 ECSubWriteReply(tid=2534, last_complete=466'633, committed=1, applied=1)) v2 ==== 95+0+0 (unknown 0 0 0) 0x55910bbeba80 con 0x5590ee616400
2021-02-05T04:47:10.998+0000 7f05f9c1a700  1 -- [v2:172.21.15.191:6818/16961,v1:172.21.15.191:6819/16961] <== osd.9 v2:172.21.15.191:6810/16958 3718 ==== MOSDECSubOpWriteReply(3.1as0 466/462 ECSubWriteReply(tid=2534, last_complete=466'633, committed=1, applied=1)) v2 ==== 95+0+0 (crc 0 0 0) 0x55910388e280 con 0x5590ee617000

The crt=466'633 update happened at this point.

2021-02-05T04:47:13.882+0000 7f05d5a29700 20 osd.11 pg_epoch: 469 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=468/469 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=468) [11,1,10,5,NONE,9]p11(0) r=0 lpr=468 pi=[418,468)/1 crt=466'633 lcod 453'629 mlcod 0'0 activating+undersized mbc={0={(1+0)=12},1={(0+0)=12},2={(0+0)=12},3={(1+0)=12},4={(0+0)=12},5={(1+0)=12}} trimq=[f6~1,151~1,171~1]] rollforward: entry=466'632 (453'629) clone    3:58cffdd8:::smithi05121792-42:18c by unknown.0.0:0 2021-02-05T04:46:42.013136+0000 0 snaps [18c,18b,18a,189,188,187,186,185,183] ObjectCleanRegions clean_offsets: [0~18446744073709551615], clean_omap: 1, new_object: 0

This comes from activate()

      // Always call now so update_calc_stats() will be accurate
      discover_all_missing(ctx.msgs);

    }

    // num_objects_degraded if calculated should reflect this too, unless no
    // missing and we are about to go clean.
    if (get_osdmap()->get_pg_size(info.pgid.pgid) > actingset.size()) {
      state_set(PG_STATE_UNDERSIZED);
    }

    state_set(PG_STATE_ACTIVATING);
    pl->on_activate(std::move(to_trim));
  }
  if (acting.size() >= pool.info.min_size) { 
    PGLog::LogEntryHandlerRef rollbacker{pl->get_log_handler(t)};
    pg_log.roll_forward(rollbacker.get());
  }
}

I think the check "if (acting.size() >= pool.info.min_size" is not correct. This does not guarantee that all the acting set osds have no missing objects, which is exactly what happened here. Out of [11,1,10,5,NONE,9] only 11,5 and 9 have no missing. We should only rollforward when we have enough copies to recover, so this check should probably use avail_no_missing.size() to ensure that we can recover.

Also, this seems to be a different root cause for unfound objects than https://tracker.ceph.com/issues/48417

I'm...not sure what that if block is supposed to do. It was introduced as part of the initial overwrites patch sequence in 4a193e828d456a7c301cdac455c33c1b6e57265c. I think the fix is probably just to remove it?

Samuel Just wrote:

I'm...not sure what that if block is supposed to do. It was introduced as part of the initial overwrites patch sequence in 4a193e828d456a7c301cdac455c33c1b6e57265c. I think the fix is probably just to remove it?

I wasn't sure why it was present, but given your explanation, I don't see any issues with removing it (as long as tests are happy).

Looking at this more closely, I think removing that if block is still fine -- it'll be trimmed by the next IO anyway.

However, I don't think that block can actually cause a problem. We went active with last_update=466'633, so we are obligated to never rollback to before 466'
633 anyway -- we've begun serving reads based on that last_update, after all.

I'm pulling the logs to look more closely.

I don't think teuthology-2021-02-03_03:31:04-rados-pacific-distro-basic-smithi/5852263 is related to can_rollback_to at all. The initial write was:

2021-02-05T04:47:08.038+0000 7f9bc31db700 10 osd.5 pg_epoch: 463 pg[3.1as3( v 463'631 (0'0,463'631] local-lis/les=462/463 n=11 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,0,9]/[11,NONE,NONE,5,0,9]p11(0) r=3 lpr=462 pi=[418,462)/1 luod=0'0 lua=453'629 crt=453'629 lcod 453'629 mlcod 0'0 active+remapped mbc={}] add_log_entry 463'631 (452'626) modify   3:5a96ee3e:::smithi05121792-2:head by client.4548.0:4513 0.000000 0 ObjectCleanRegions clean_offsets: [6307840~18446744073703243775], clean_omap: 1, new_object: 0

to acting set [11,NONE,NONE,5,0,9]. Subsequently:

2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped+peering pruub 492.368682861s@ mbc={}] build_prior all_probe 0(4),5(3),7(1),8(2),9(5),10(2),11(0)
2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=467 pruub=12.076786041s) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) r=0 lpr=467 pi=[418,467)/1 crt=463'631 lcod 453'629 mlcod 0'0 remapped+peering pruub 492.368682861s@ mbc={}] build_prior final: probe 1(1),5(3),7(1),8(2),9(5),10(2),11(0) down 0 blocked_by {}

Here, we see build_prior fail to consider any prior intervals (there's debug output that should have been present for each considered). What should have happened is that it should have considered the immediately prior interval where the acting set was [11,NONE,NONE,5,0,9], noticed that osd.0 was down leaving only 3 live osds from that interval, and refused to go active.

Because we went active here, we chose 466'633 as last_update. If we had behaved correctly and waited for osd.0 to be up, we'd have chosen 463'631 instead and avoided the two unfound objects. The rollfoward behaviour in activate() doesn't appear to be significant to this bug.

2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) async=[1(1),10(2)] r=0 lpr=467 pi=[418,467)/1 luod=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}}] start_peering_interval: check_new_interval output: check_new_interval interval(462-466 up [11,1,10,5,0,9](11) acting [11,2147483647,2147483647,5,0,9](11)) : acting set is too small
2021-02-05T04:47:11.894+0000 7f05d9a31700 10 osd.11 pg_epoch: 467 pg[3.1as0( v 466'633 (0'0,466'633] local-lis/les=462/463 n=12 ec=248/27 lis/c=462/418 les/c/f=463/419/0 sis=462) [11,1,10,5,NONE,9]/[11,NONE,NONE,5,NONE,9]p11(0) async=[1(1),10(2)] r=0 lpr=467 pi=[418,467)/1 luod=463'631 crt=463'631 lcod 453'629 mlcod 124'112 active+remapped mbc={0={(1+0)=12},1={(0+0)=4,(0+1)=8},2={(0+0)=4,(0+1)=8},3={(1+0)=12},4={(1+0)=12},5={(1+0)=12}}]  noting past ([418,466] all_participants=0(4),5(3),7(1),8(2),9(5),10(2),11(0) intervals=([456,460] acting 0(4),5(3),7(1),9(5),11(0)))

In particular:

check_new_interval interval(462-466 up [11,1,10,5,0,9](11) acting [11,2147483647,2147483647,5,0,9](11)) : acting set is too small

check_new_interval here is dropping 462-466 as it concluded that it cannot have served writes. This is I think the bug. 462-466 here demonstrably did accept writes, so either this code is wrong and accepting IO was correct, or osd.11's choice to accept IO in epoch 462 was wrong. Note: there were stretch cluster related changes in the past few months near here. Investigating.

Found it.

  /**
   * Returns whether the current acting set is able to go active
   * and serve writes. It needs to satisfy min_size and any
   * applicable stretch cluster constraints.
   */
  bool acting_set_writeable() {
    return (acting.size() >= pool.info.min_size) &&
      (pool.info.stretch_set_can_peer(acting, *get_osdmap(), NULL));
  }

Assumption: min_size is 5 -- does a 4/2 ec code result in a min_size of 5 by default?