Ceph

and i am able to dump the osd map using

ceph-monstore-tool /var/lib/ceph/mon/ceph-Mon get osdmap -- --out /tmp/osdmap.85
osdmaptool /tmp/osdmap.85 --print --tree --dump-json

the output is attached:

epoch 85
fsid 283bbd8b-9205-4cfc-83fa-80546ba2fe36
created 2015-05-06 15:39:42.874568
modified 2015-05-18 06:20:07.885802
flags

pool 0 'rbd' replicated size 2 min_size 1 crush_ruleset 0 object_hash rjenkins pg_num 64 pgp_num 64 last_change 1 flags hashpspool stripe_width 0

max_osd 4
osd.0 down in  weight 1 up_from 78 up_thru 78 down_at 85 last_clean_interval [46,72) 10.8.128.40:6800/25974 10.8.128.40:6804/25974 10.8.128.40:6808/25974 10.8.128.40:6809/25974 exists 4d27fc96-3a2f-478f-bca5-a4e55ec7e53c
osd.1 up   in  weight 1 up_from 69 up_thru 80 down_at 63 last_clean_interval [8,62) 10.8.128.86:6800/19549 10.8.128.86:6801/19549 10.8.128.86:6802/19549 10.8.128.86:6803/19549 exists,up 61f9fbec-687e-4d89-8900-fc7d9ff5f88a
osd.2 up   in  weight 1 up_from 84 up_thru 80 down_at 83 last_clean_interval [80,83) 10.8.128.40:6810/26274 10.8.128.40:6801/1026274 10.8.128.40:6802/1026274 10.8.128.40:6803/1026274 exists,up 7823abe2-208c-4381-9020-54b6bbf11b07
osd.3 down in  weight 1 up_from 71 up_thru 80 down_at 85 last_clean_interval [17,65) 10.8.128.86:6804/19849 10.8.128.86:6805/19849 10.8.128.86:6808/19849 10.8.128.86:6809/19849 exists 8551c2bb-82ed-4b15-ad6e-305e6d560b59

{
    "epoch": 85,
    "fsid": "283bbd8b-9205-4cfc-83fa-80546ba2fe36",
    "created": "2015-05-06 15:39:42.874568",
    "modified": "2015-05-18 06:20:07.885802",
    "flags": "",
    "cluster_snapshot": "",
    "pool_max": 0,
    "max_osd": 4,
    "pools": [
        {
            "pool": 0,
            "pool_name": "rbd",
            "flags": 1,
            "flags_names": "hashpspool",
            "type": 1,
            "size": 2,
            "min_size": 1,
            "crush_ruleset": 0,
            "object_hash": 2,
            "pg_num": 64,
            "pg_placement_num": 64,
            "crash_replay_interval": 0,
            "last_change": "1",
            "last_force_op_resend": "0",
            "auid": 0,
            "snap_mode": "selfmanaged",
            "snap_seq": 0,
            "snap_epoch": 0,
            "pool_snaps": [],
            "removed_snaps": "[]",
            "quota_max_bytes": 0,
            "quota_max_objects": 0,
            "tiers": [],
            "tier_of": -1,
            "read_tier": -1,
            "write_tier": -1,
            "cache_mode": "none",
            "target_max_bytes": 0,
            "target_max_objects": 0,
            "cache_target_dirty_ratio_micro": 0,
            "cache_target_full_ratio_micro": 0,
            "cache_min_flush_age": 0,
            "cache_min_evict_age": 0,
            "erasure_code_profile": "",
            "hit_set_params": {
                "type": "none" 
            },
            "hit_set_period": 0,
            "hit_set_count": 0,
            "min_read_recency_for_promote": 0,
            "stripe_width": 0,
            "expected_num_objects": 0
        }
    ],
    "osds": [
        {
            "osd": 0,
            "uuid": "4d27fc96-3a2f-478f-bca5-a4e55ec7e53c",
            "up": 0,
            "in": 1,
            "weight": 1.000000,
            "primary_affinity": 1.000000,
            "last_clean_begin": 46,
            "last_clean_end": 72,
            "up_from": 78,
            "up_thru": 78,
            "down_at": 85,
            "lost_at": 0,
            "public_addr": "10.8.128.40:6800\/25974",
            "cluster_addr": "10.8.128.40:6804\/25974",
            "heartbeat_back_addr": "10.8.128.40:6808\/25974",
            "heartbeat_front_addr": "10.8.128.40:6809\/25974",
            "state": [
                "exists" 
            ]
        },
        {
            "osd": 1,
            "uuid": "61f9fbec-687e-4d89-8900-fc7d9ff5f88a",
            "up": 1,
            "in": 1,
            "weight": 1.000000,
            "primary_affinity": 1.000000,
            "last_clean_begin": 8,
            "last_clean_end": 62,
            "up_from": 69,
            "up_thru": 80,
            "down_at": 63,
            "lost_at": 0,
            "public_addr": "10.8.128.86:6800\/19549",
            "cluster_addr": "10.8.128.86:6801\/19549",
            "heartbeat_back_addr": "10.8.128.86:6802\/19549",
            "heartbeat_front_addr": "10.8.128.86:6803\/19549",
            "state": [
                "exists",
                "up" 
            ]
        },
        {
            "osd": 2,
            "uuid": "7823abe2-208c-4381-9020-54b6bbf11b07",
            "up": 1,
            "in": 1,
            "weight": 1.000000,
            "primary_affinity": 1.000000,
            "last_clean_begin": 80,
            "last_clean_end": 83,
            "up_from": 84,
            "up_thru": 80,
            "down_at": 83,
            "lost_at": 0,
            "public_addr": "10.8.128.40:6810\/26274",
            "cluster_addr": "10.8.128.40:6801\/1026274",
            "heartbeat_back_addr": "10.8.128.40:6802\/1026274",
            "heartbeat_front_addr": "10.8.128.40:6803\/1026274",
            "state": [
                "exists",
                "up" 
            ]
        },
        {
            "osd": 3,
            "uuid": "8551c2bb-82ed-4b15-ad6e-305e6d560b59",
            "up": 0,
            "in": 1,
            "weight": 1.000000,
            "primary_affinity": 1.000000,
            "last_clean_begin": 17,
            "last_clean_end": 65,
            "up_from": 71,
            "up_thru": 80,
            "down_at": 85,
            "lost_at": 0,
            "public_addr": "10.8.128.86:6804\/19849",
            "cluster_addr": "10.8.128.86:6805\/19849",
            "heartbeat_back_addr": "10.8.128.86:6808\/19849",
            "heartbeat_front_addr": "10.8.128.86:6809\/19849",
            "state": [
                "exists" 
            ]
        }
    ],
    "osd_xinfo": [
        {
            "osd": 0,
            "down_stamp": "2015-05-18 06:20:07.885802",
            "laggy_probability": 0.249900,
            "laggy_interval": 47,
            "features": 1125899906842623,
            "old_weight": 65536
        },
        {
            "osd": 1,
            "down_stamp": "2015-05-14 04:58:18.937390",
            "laggy_probability": 0.357000,
            "laggy_interval": 933,
            "features": 1125899906842623,
            "old_weight": 65536
        },
        {
            "osd": 2,
            "down_stamp": "2015-05-18 05:32:05.357656",
            "laggy_probability": 0.474930,
            "laggy_interval": 8,
            "features": 1125899906842623,
            "old_weight": 0
        },
        {
            "osd": 3,
            "down_stamp": "2015-05-18 06:20:07.885802",
            "laggy_probability": 0.357000,
            "laggy_interval": 928,
            "features": 1125899906842623,
            "old_weight": 65536
        }
    ],
    "pg_temp": [],
    "primary_temp": [],
    "blacklist": [],
    "erasure_code_profiles": {
        "default": {
            "directory": "\/usr\/lib64\/ceph\/erasure-code",
            "k": "2",
            "m": "1",
            "plugin": "jerasure",
            "technique": "reed_sol_van" 
        }
    }
}
ID WEIGHT TYPE NAME UP/DOWN REWEIGHT PRIMARY-AFFINITY
 0      0 osd.0        down  1.00000          1.00000
 1      0 osd.1          up  1.00000          1.00000
 2      0 osd.2          up  1.00000          1.00000
 3      0 osd.3        down  1.00000          1.00000

kefu, we need logs from osdmap epoch 81 to 82. Last working crushmap is from epoch 81, all subsequent maps are broken.

Right now, the only way I can easily reproduce this is by setting an empty crushmap with 'ceph osd setcrushmap -i some-empty.crushmap'.

I have no idea whether this was deliberately performed or if this is was an unfortunate side effect of some operation.

diff --git a/src/tools/osdmaptool.cc b/src/tools/osdmaptool.cc
index 14331c3..a628454 100644
--- a/src/tools/osdmaptool.cc
+++ b/src/tools/osdmaptool.cc
@@ -465,9 +465,14 @@ int main(int argc, const char **argv)
     osdmap.print(cout);
   if (print_json)
     osdmap.dump_json(cout);
-  if (tree)
-    osdmap.print_tree(&cout, NULL);
-
+  if (tree) {
+    boost::scoped_ptr<Formatter> f(Formatter::create("json"));
+    f->open_object_section("tree");
+    osdmap.print_tree(NULL, f.get());
+    f->close_section();
+    f->flush(cout);
+    // osdmap.print_tree(&cout, NULL);
+  }
   if (modified) {
     bl.clear();
     osdmap.encode(bl, CEPH_FEATURES_SUPPORTED_DEFAULT | CEPH_FEATURE_RESERVED);

and with the patch above. we are able to reproduce the crash using

./osdmaptool /tmp/osdmap.85 --tree # in which, /tmp/osdmap.85 is the osdmap extracted using ceph-monstore-tool

yes, "osd setcrushmap" was issued before we ran into this issue.

$ zgrep setcrushmap *
ceph.audit.log-20150519.gz:2015-05-18 05:14:12.613798 mon.0 10.8.128.33:6789/0 224816 : audit [INF] from='client.? 10.8.128.33:0/1023292' entity='client.admin' cmd=[{"prefix": "osd setcrushmap"}]: dispatch
ceph.audit.log-20150519.gz:2015-05-18 05:14:12.613798 mon.0 10.8.128.33:6789/0 224816 : audit [INF] from='client.? 10.8.128.33:0/1023292' entity='client.admin' cmd=[{"prefix": "osd setcrushmap"}]: dispatch

Yeah, I noticed that a while ago. The annoying thing is that I can't find logs for the period when the osdmap moves from epoch 81 (the last correctly formed crushmap) to epoch 82 (first wrong map). The 'ceph osd setcrushmap' commands do fall in this gap, so I'm assuming this was indeed an incorrectly formed crushmap that was pushed to the cluster -- and by 'incorrectly formed', in this case, I mean an empty map.

I think the real bug here is that we are allowing setting an empty map without requiring the user to be really sure about that.

echoing joao

(gdb) p *this->crush
$9 = {mapper_lock = {name = 0xb298b8 "CrushWrapper::mapper_lock", id = -1, recursive = false, lockdep = true,
    backtrace = false, _m = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 2,
        __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
      __size = '\000' <repeats 16 times>, "\002", '\000' <repeats 22 times>, __align = 0}, nlock = 0,
    locked_by = 0, cct = 0x0, logger = 0x0}, type_map = std::map with 0 elements,
  name_map = std::map with 0 elements, rule_name_map = std::map with 0 elements, crush = 0x2cfeff0,
  have_rmaps = false, type_rmap = std::map with 0 elements, name_rmap = std::map with 0 elements,
  rule_name_rmap = std::map with 0 elements}

so in osdmap#85, we have 4 OSDs. but since the crushmap is empty, crush->get_typename(0) returns NULL, hence the crash.

I think the real bug here is that we are allowing setting an empty map without requiring the user to be really sure about that.

we perform some sanity tests when handling "osd setcrushmap" or "osd crush set". but they failed to detect a crush map which not able to cover all OSDs in the osdmap.

will add a test for it.

in http://tracker.ceph.com/attachments/download/1716/1029402.log.gz, we have

    -1> 2015-05-25 05:33:57.741951 7ffe076b2700  5 mon.Mon@0(leader).paxos(paxos active c 1..531) is_readable = 1 - now=2015-05-25 05:33:57.741956 lease_expire=0.000000 has v0 lc 531
     0> 2015-05-25 05:33:57.748845 7ffe076b2700 -1 osd/OSDMap.h: In function 'unsigned int OSDMap::get_weight(int) const' thread 7ffe076b2700 time 2015-05-25 05:33:57.742429
osd/OSDMap.h: 374: FAILED assert(o < max_osd)

 ceph version 0.94.1 (e4bfad3a3c51054df7e537a724c8d0bf9be972ff)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x85) [0x7b3a95]
 2: /usr/bin/ceph-mon() [0x773223]
 3: (OSDMap::print_tree(std::ostream*, ceph::Formatter*) const+0x192a) [0x78835a]
 4: (OSDMonitor::preprocess_command(MMonCommand*)+0xe55) [0x60a105]
 5: (OSDMonitor::preprocess_query(PaxosServiceMessage*)+0x20b) [0x60f7ab]
 6: (PaxosService::dispatch(PaxosServiceMessage*)+0x833) [0x5cad23]
 7: (Monitor::handle_command(MMonCommand*)+0x147c) [0x591a9c]
 8: (Monitor::dispatch(MonSession*, Message*, bool)+0xf9) [0x594cd9]
 9: (Monitor::_ms_dispatch(Message*)+0x1a6) [0x595986]

where the crush map possesses some OSD which is missing in osdmap.

BTW, per http://ceph.com/docs/master/rados/operations/add-or-rm-osds/ and http://ceph.com/docs/master/install/manual-deployment/. the suggested practice of adding an OSD manually is:

1. add the bucket hosting the osd to crush map
2. add the OSD to the host
3. start the OSD instance

sent mail to Eino for more information.

quote of Kefu's inquiry

Eino, i was looking at your issue at http://tracker.ceph.com/issues/12876.
seems it is due to a fault crush rule, see http://tracker.ceph.com/issues/12876#note-5.
may i know how you managed to inject it into the monitor? i tried using

$ ceph osd setcrushmap -i new-crush-map
Error EINVAL: Failed to parse crushmap: ** Caught signal (Segmentation fault) *

but no luck.

quote from Eino's reply

I'm pretty sure I did it just like you were trying to do. The cluster has since been upgraded a couple of times. Unfortunately I can't remember when I created that particular faulty rule.