Bug #11110
Updated by Samuel Just about 9 years ago
Reported on list:
2015-03-13 16:15:48.128081 7f3c2cc53700 5 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 inactive] enter Started/Primary/Peering
2015-03-13 16:15:48.128094 7f3c2cc53700 5 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] enter Started/Primary/Peering/GetInfo
2015-03-13 16:15:48.128108 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] _calc_past_interval_range: already have past intervals back to 66791
2015-03-13 16:15:48.128122 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67050-67050 up [6689,1919,2329](6689) acting [6689](6689))
2015-03-13 16:15:48.128134 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67048-67049 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.128148 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67047-67047 up [6689,1919,2329](6689) acting [6689](6689))
2015-03-13 16:15:48.128161 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67045-67046 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.128175 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67044-67044 up [6689,1919,2329](6689) acting [6689](6689))
2015-03-13 16:15:48.128188 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67037-67043 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.128202 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67034-67036 up [1919,2329](1919) acting [1919,2329](1919) maybe_went_rw)
2015-03-13 16:15:48.128216 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67031-67033 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.128229 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67028-67030 up [1919,2329](1919) acting [1919,2329](1919) maybe_went_rw)
2015-03-13 16:15:48.128243 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67025-67027 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.128258 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(67022-67024 up [1919,2329](1919) acting [1919,2329](1919) maybe_went_rw)
2015-03-13 16:15:48.128271 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(66796-67021 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.128293 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(66792-66795 up [6689,1919](6689) acting [6689,1919](6689))
2015-03-13 16:15:48.128305 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior interval(66787-66791 up [6689](6689) acting [6689](6689) maybe_went_rw)
2015-03-13 16:15:48.128317 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] PriorSet: build_prior final: probe 1919,2329,6689 down blocked_by {}
2015-03-13 16:15:48.128329 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] up_thru 67050 < same_since 67051, must notify monitor
2015-03-13 16:15:48.128343 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: querying info from osd.1919
2015-03-13 16:15:48.128361 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: querying info from osd.2329
2015-03-13 16:15:48.128376 7f3c2cc53700 15 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] publish_stats_to_osd 67051:20493
2015-03-13 16:15:48.128391 7f3c2cc53700 20 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] handle_activate_map: Not dirtying info: last_persisted is 67050 while current is 67051
2015-03-13 16:15:48.128399 7f3c2cc53700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] handle_peering_event: epoch_sent: 67051 epoch_requested: 67051 NullEvt
2015-03-13 16:15:48.129402 7f3c37664700 20 osd.6689 67051 _dispatch 0x43a4ec0 pg_notify(75.45(30) epoch 67051) v5
2015-03-13 16:15:48.130427 7f3c37664700 20 osd.6689 67051 _dispatch 0x43a0b40 pg_notify(75.45(30) epoch 67051) v5
2015-03-13 16:15:48.142378 7f3c2e055700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] handle_peering_event: epoch_sent: 67051 epoch_requested: 67051 MNotifyRec from 2329 notify: (query_epoch:67051, epoch_sent:67051, info:75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)) features: 0x3ffffffffffff
2015-03-13 16:15:48.142398 7f3c2e055700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] got osd.2329 75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)
2015-03-13 16:15:48.142429 7f3c2e055700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] update_heartbeat_peers 1919,2329,6689 unchanged
2015-03-13 16:15:48.142441 7f3c2e055700 20 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: Adding osd: 2329 features: 3ffffffffffff
2015-03-13 16:15:48.142460 7f3c2e055700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] handle_peering_event: epoch_sent: 67051 epoch_requested: 67051 MNotifyRec from 2329 notify: (query_epoch:67051, epoch_sent:67051, info:75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)) features: 0x3ffffffffffff
2015-03-13 16:15:48.142472 7f3c2e055700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] got dup osd.2329 info 75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037), identical to ours
2015-03-13 16:15:48.219295 7f3c37664700 20 osd.6689 67051 _dispatch 0xe5efbc0 pg_notify(75.45(23) epoch 67051) v5
2015-03-13 16:15:48.219397 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] handle_peering_event: epoch_sent: 67051 epoch_requested: 67051 MNotifyRec from 1919 notify: (query_epoch:67051, epoch_sent:67051, info:75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)) features: 0x3ffffffffffff
2015-03-13 16:15:48.219436 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] got osd.1919 75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)
2015-03-13 16:15:48.219465 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] update_heartbeat_peers 1919,2329,6689 unchanged
2015-03-13 16:15:48.219478 7f3c2c252700 20 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: Adding osd: 1919 features: 3ffffffffffff
2015-03-13 16:15:48.219492 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: last maybe_went_rw interval was interval(67048-67049 up [6689,1919,2329](6689) acting [6689,1919,2329](6689) maybe_went_rw)
2015-03-13 16:15:48.219506 7f3c2c252700 20 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] state<Started/Primary/Peering/GetInfo>: Common features: 3ffffffffffff
2015-03-13 16:15:48.219522 7f3c2c252700 5 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] exit Started/Primary/Peering/GetInfo 0.091427 4 0.000490
2015-03-13 16:15:48.219539 7f3c2c252700 5 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] enter Started/Primary/Peering/GetLog
2015-03-13 16:15:48.219564 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] calc_acting osd.1919 75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)
2015-03-13 16:15:48.219582 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] calc_acting osd.2329 75.45( v 66245'4028 (48932'1001,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)
2015-03-13 16:15:48.219595 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] calc_acting osd.6689 75.45( v 66245'4028 (49044'1025,66245'4028] local-les=61515 n=3994 ec=48759 les/c 66791/66791 67037/67051/67037)
2015-03-13 16:15:48.219609 7f3c2c252700 10 osd.6689 =67051 pi=66787-67050/14 crt=66226'4026 lcod 0'0 mlcod 0'0 peering] choose_acting failed
This can cause a pg an osd to become incorrectly unavailable.