Project

General

Profile

Bug #20958

missing set lost during upgrade

Added by Sage Weil almost 2 years ago. Updated almost 2 years ago.

Status:
Resolved
Priority:
Immediate
Assignee:
-
Category:
Correctness/Safety
Target version:
-
Start date:
08/09/2017
Due date:
% Done:

0%

Source:
Tags:
Backport:
luminous
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
Pull request ID:

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}

History

#1 Updated by Sage Weil almost 2 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)

#2 Updated by Sage Weil almost 2 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).

#3 Updated by Greg Farnum almost 2 years ago

  • Project changed from Ceph to RADOS
  • Category set to Correctness/Safety
  • Status changed from Verified to Testing
  • Backport set to luminous
  • Component(RADOS) OSD added

#4 Updated by Sage Weil almost 2 years ago

  • Project changed from RADOS to Ceph
  • Description updated (diff)
  • Category deleted (Correctness/Safety)
  • Status changed from Testing to Verified
  • Backport deleted (luminous)

#5 Updated by Sage Weil almost 2 years ago

  • Project changed from Ceph to RADOS
  • Category set to Correctness/Safety

#6 Updated by Sage Weil almost 2 years ago

  • Backport set to luminous

#7 Updated by Sage Weil almost 2 years ago

  • Status changed from Verified to Testing

#8 Updated by Sage Weil almost 2 years ago

  • Status changed from Testing to Resolved

also backported

Also available in: Atom PDF