Bug #20958
closedmissing set lost during upgrade
0%
Description
pg 4.3
2017-08-09 10:12:13.523990 7fc6295c2700 10 osd.3 pg_epoch: 331 pg[4.3( empty local-les=0 n=0 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=0'0 mlcod 0'0 remapped+peering] handle_peering_event: epoch_sent: 331 epoch_requested: 331 MLogRec from 0 2017-08-09 10:12:13.524011 7fc6295c2700 10 osd.3 pg_epoch: 331 pg[4.3( empty local-les=0 n=0 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=0'0 mlcod 0'0 remapped+peering] state<Started/Primary/Peering/GetLog>: GetLog: received master log from osd0 2017-08-09 10:12:13.524024 7fc6295c2700 10 osd.3 pg_epoch: 331 pg[4.3( empty local-les=0 n=0 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=0'0 mlcod 0'0 remapped+peering] state<Started/Primary/Peering/GetLog>: leaving GetLog 2017-08-09 10:12:13.524036 7fc6295c2700 10 osd.3 pg_epoch: 331 pg[4.3( empty local-les=0 n=0 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=0'0 mlcod 0'0 remapped+peering] state<Started/Primary/Peering/GetLog>: processing master log 2017-08-09 10:12:13.524047 7fc6295c2700 10 osd.3 pg_epoch: 331 pg[4.3( empty local-les=0 n=0 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=0'0 mlcod 0'0 remapped+peering] proc_master_log for osd.0: log((0'0,323'1426], crt=323'1426) missing(0) 2017-08-09 10:12:13.524059 7fc6295c2700 10 merge_log log((0'0,323'1426], crt=323'1426) from osd.0 into log((0'0,0'0], crt=0'0) 2017-08-09 10:12:13.524065 7fc6295c2700 10 merge_log extending head to 323'1426 ... 2017-08-09 10:12:13.527918 7fc6295c2700 20 ? 214'1013 (213'1003) modify 4:ccaac2a2:::smithi199163903-493 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head by unknown.0.0:0 2017-08-09 10:09:41.198667 ... 2017-08-09 10:12:13.527928 7fc6295c2700 20 ? 214'1012 (206'957) delete 4:ccaac2a2:::smithi199163903-493 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:88 by unknown.0.0:0 2017-08-09 10:09:41.198667 ... 2017-08-09 10:12:13.556729 7fc6295c2700 10 osd.3 pg_epoch: 331 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-les=0 n=49 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=323'1426 mlcod 0'0 remapped+peering m=49] peer osd.0 now 4.3( v 323'1426 (0'0,323'1426] local-les=29 n=49 ec=28 les/c/f 29/29/0 329/331/329) missing(0)
i.e., empty pg, every object is missing. last thing before restart:
2017-08-09 10:12:13.753417 7fc6295c2700 10 osd.3 pg_epoch: 332 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-les=29 n=49 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=323'1426 mlcod 0'0 remapped+peering m=49] state<Started/Primary>: pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-les=29 n=49 ec=28 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=331 pi=28-330/3 crt=323'1426 mlcod 0'0 remapped+peering m=49] got dup osd.0 info 4.3( v 323'1426 (0'0,323'1426] local-les=29 n=49 ec=28 les/c/f 29/29/0 329/331/329), i dentical to ours
then
2017-08-09 10:12:14.944433 7f8968ad9e00 0 ceph version 12.1.2-475-g1045d0d (1045d0d11a93b48747a796c5c055a0e353366261) luminous (rc), process (unknown), pid 443489
and
2017-08-09 10:12:15.158950 7f8968ad9e00 10 osd.3 332 _open_lock_pg 4.3 2017-08-09 10:12:15.158960 7f8968ad9e00 10 osd.3 332 _get_pool 4 2017-08-09 10:12:15.158986 7f8968ad9e00 5 osd.3 pg_epoch: 331 pg[4.3(unlocked)] enter Initial 2017-08-09 10:12:15.158991 7f8968ad9e00 20 osd.3 pg_epoch: 331 pg[4.3(unlocked)] enter NotTrimming 2017-08-09 10:12:15.158996 7f8968ad9e00 15 filestore(/var/lib/ceph/osd/ceph-3) omap_get_values(5126): 4.3_head/#4:c0000000::::head# 2017-08-09 10:12:15.159022 7f8968ad9e00 15 filestore(/var/lib/ceph/osd/ceph-3) omap_get_values(5152): 4.3_head/#4:c0000000::::head# = 0() 2017-08-09 10:12:15.159033 7f8968ad9e00 20 read_log_and_missing coll 4.3_head log_oid #4:c0000000::::head# 2017-08-09 10:12:15.159053 7f8968ad9e00 10 filestore(/var/lib/ceph/osd/ceph-3) stat(3201): 4.3_head/#4:c0000000::::head# = 0 (size 0) 2017-08-09 10:12:15.159057 7f8968ad9e00 15 filestore(/var/lib/ceph/osd/ceph-3) get_omap_iterator(5190): 4.3_head/#4:c0000000::::head# ... 2017-08-09 10:12:15.169859 7f8968ad9e00 20 read_log_and_missing 323'1426 (0'0) promote 4:df323761:::smithi199163903-495 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head by osd.0.0:4658 2017-08-09 10:12:05.332391 0 2017-08-09 10:12:15.171375 7f8968ad9e00 10 read_log_and_missing done 2017-08-09 10:12:15.171476 7f8968ad9e00 10 osd.3 332 PG 4.3 must upgrade... 2017-08-09 10:12:15.171495 7f8968ad9e00 5 write_log_and_missing with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, writeout_from: 4294967295'18446744073709551615, trimmed: , trimmed_dups: , clear_divergent_priors: 0 ... 2017-08-09 10:12:15.172054 7f8968ad9e00 10 osd.3 pg_epoch: 331 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 329/331/329) [3]/[3,0] r=0 lpr=0 pi=[28,331)/3 crt=323'1426 mlcod 0'0 unknown] handle_loaded
then a bit later we become a replica, and eventually peer
2017-08-09 10:12:23.658065 7f894c3cd700 10 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] handle_peering_event: epoch_sent: 346 epoch_requested: 346 MInfoRec from 2 info: 4.3( v 323'1426 (0'0,323'1426] local-lis/les=345/346 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) 2017-08-09 10:12:23.658081 7f894c3cd700 10 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] state<Started/Stray>: got info from osd.2 4.3( v 323'1426 (0'0,323'1426] local-lis/les=345/346 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) 2017-08-09 10:12:23.658091 7f894c3cd700 5 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] exit Started/Stray 0.249551 8 0.001554 2017-08-09 10:12:23.658101 7f894c3cd700 5 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] enter Started/ReplicaActive 2017-08-09 10:12:23.658108 7f894c3cd700 5 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] enter Started/ReplicaActive/RepNotRecovering 2017-08-09 10:12:23.658115 7f894c3cd700 10 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] state<Started/ReplicaActive>: In ReplicaActive, about to call activate 2017-08-09 10:12:23.658121 7f894c3cd700 10 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=345/346 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown] activate - no missing, moving last_complete 0'0 -> 323'1426 2017-08-09 10:12:23.658126 7f894c3cd700 20 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=345/346 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 unknown] rollforward: entry=38'1 (0'0) promote 4:c1631978:::smithi199163903-2:head by osd.0.0:5 2017-08-09 10:05:36.815738 0 ... 2017-08-09 10:12:23.671812 7f894c3cd700 10 osd.3 pg_epoch: 346 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=345/346 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 unknown] state<Started/ReplicaActive>: Activate Finished 2017-08-09 10:12:23.671851 7f894c3cd700 10 log is not dirty 2017-08-09 10:12:23.671863 7f894c3cd700 5 filestore(/var/lib/ceph/osd/ceph-3) queue_transactions(2161): existing 0x556f63675c20 osr(4.3 0x556f632a2200) ...
on the primary (osd.2, which is 2017-08-09 10:12:13.509070 7f03de0a3e00 0 ceph version 12.1.2-475-g1045d0d),
2017-08-09 10:12:23.473771 7f03c1d0c700 10 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetMissing>: requesting log+missing since 29'0 from osd.3 ... 2017-08-09 10:12:23.486103 7f03c951b700 1 -- 172.21.15.93:6815/1443414 <== osd.3 172.21.15.93:6808/1443489 42 ==== pg_log(4.3 epoch 345 log log((0'0,323'1426], crt=323'1426) pi (empty) query_epoch 345) v5 ==== 537419+0+0 (535632555 0 0) 0x56366b7b4000 con 0x56366a5d9000 2017-08-09 10:12:23.486128 7f03c951b700 20 osd.2 345 OSD::ms_dispatch: pg_log(4.3 epoch 345 log log((0'0,323'1426], crt=323'1426) pi (empty) query_epoch 345) v5 2017-08-09 10:12:23.486134 7f03c951b700 10 osd.2 345 do_waiters -- start 2017-08-09 10:12:23.486136 7f03c951b700 10 osd.2 345 do_waiters -- finish 2017-08-09 10:12:23.486138 7f03c951b700 20 osd.2 345 _dispatch 0x56366b7b4000 pg_log(4.3 epoch 345 log log((0'0,323'1426], crt=323'1426) pi (empty) query_epoch 345) v5 2017-08-09 10:12:23.486145 7f03c951b700 7 osd.2 345 handle_pg_log pg_log(4.3 epoch 345 log log((0'0,323'1426], crt=323'1426) pi (empty) query_epoch 345) v5 from osd.3 2017-08-09 10:12:23.486150 7f03c951b700 15 osd.2 345 require_same_or_newer_map 345 (i am 345) 0x56366b7b4000 2017-08-09 10:12:23.486894 7f03c1d0c700 10 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] handle_peering_event: epoch_sent: 345 epoch_requested: 345 MLogRec from 3 2017-08-09 10:12:23.486924 7f03c1d0c700 10 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] proc_replica_log for osd.3: 4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) log((0'0,323'1426], crt=323'1426) missing(0 may_include_deletes = 0) 2017-08-09 10:12:23.486947 7f03c1d0c700 10 proc_replica_log for osd.3: 4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) log((0'0,323'1426], crt=323'1426) missing(0 may_include_deletes = 0) 2017-08-09 10:12:23.486956 7f03c1d0c700 10 proc_replica_log: osd.3 same log head, not looking for divergent objects 2017-08-09 10:12:23.486962 7f03c1d0c700 10 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] peer osd.3 now 4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) missing(0 may_include_deletes = 0) 2017-08-09 10:12:23.486981 7f03c1d0c700 10 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetMissing>: still need up_thru update before going active 2017-08-09 10:12:23.486999 7f03c1d0c700 5 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] exit Started/Primary/Peering/GetMissing 0.013235 3 0.000229 2017-08-09 10:12:23.487021 7f03c1d0c700 15 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] publish_stats_to_osd 345:1856 2017-08-09 10:12:23.487037 7f03c1d0c700 5 osd.2 pg_epoch: 345 pg[4.3( v 323'1426 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=0 lpr=345 pi=[28,345)/11 crt=323'1426 lcod 0'0 mlcod 0'0 peering] enter Started/Primary/Peering/WaitUpThru
notably, "missing(0 may_include_deletes = 0)".
/a/sage-2017-08-09_05:36:03-upgrade:jewel-x-luminous-distro-basic-smithi/1501304
upgrade:jewel-x/parallel/{0-cluster/{openstack.yaml start.yaml} 1-jewel-install/jewel.yaml 1.5-final-scrub.yaml 2-workload/cache-pool-snaps.yaml 3-upgrade-sequence/upgrade-all.yaml 4-luminous.yaml 5-final-workload/{blogbench.yaml rados-snaps-few-objects.yaml rados_loadgenmix.yaml rados_mon_thrash.yaml rbd_cls.yaml rbd_import_export.yaml rgw_swift.yaml} distros/ubuntu_latest.yaml}
Updated by Sage Weil over 6 years ago
osd.3 send empty msising to primary at
2017-08-09 10:12:23.476536 7f894cbce700 10 osd.3 pg_epoch: 345 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] log request from 2 2017-08-09 10:12:23.476557 7f894cbce700 10 osd.3 pg_epoch: 345 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] sending info+missing+log since 29'0 2017-08-09 10:12:23.477820 7f894cbce700 10 osd.3 pg_epoch: 345 pg[4.3( v 323'1426 lc 0'0 (0'0,323'1426] local-lis/les=29/29 n=49 ec=28/28 lis/c 29/29 les/c/f 29/29/0 343/345/342) [2,3] r=1 lpr=345 pi=[28,345)/11 crt=323'1426 unknown NOTIFY] sending log((0'0,323'1426], crt=323'1426) missing(0 may_include_deletes = 0)
Updated by Sage Weil over 6 years ago
It looks like a bug in the jewel->luminous conversion:
- jewel doesn't save the missing set
- luminous detects that case by the presence of the divergent_priors omap key. if it's there, we rebuild missing manually.
- jewel only writes the divergent_priors key if dirty_divergent_priors == true.
- jewel only sets it to true if you call PGLog::add_divergent_prior()
So it looks to me like if you have a jewel cluster that never had a divergent prior, then upgrade, then the missing set is not rebuilt. The bug is that the presence of that omap key is not a reliable indicator that we are upgrading from jewel (and may need to rebuild missing).
Updated by Greg Farnum over 6 years ago
- Project changed from Ceph to RADOS
- Category set to Correctness/Safety
- Status changed from 12 to 7
- Backport set to luminous
- Component(RADOS) OSD added
Updated by Sage Weil over 6 years ago
- Project changed from RADOS to Ceph
- Description updated (diff)
- Category deleted (
Correctness/Safety) - Status changed from 7 to 12
- Backport deleted (
luminous)
Updated by Sage Weil over 6 years ago
- Project changed from Ceph to RADOS
- Category set to Correctness/Safety