Ceph » CephFS

So now it seems like although the order of members was whacky, calls to = {fsicd, rank} were actually assigning the values as expected.

The other possibilities would be that legacy_client_fscid was something invalid (but it is validated in FSMap::sanity), or standby_for_fscid was something non-default (m0zes says it wasn't).

I think this is happening when older MDSs send a beacon to newer mons, because MMDSBeacon isn't initialising POD fields properly in its default constructor, so when there's no ::decode for fields like standby_for_fscid we're getting garbage.

wip-17466-jewel is building with a minimal fix rebased on v10.2.3

https://github.com/ceph/ceph/pull/11281 has the fix for master.

It's tempting to validate standby_for_fscid in FSMap::sanity(), but we don't do that for standby_for_rank because daemons are allowed to have config that references a rank that perhaps doesn't actually exist in the map. It's up to the logic that consumes standby_for_* to avoid trusting what has been put there by the daemon.

I've cherry-picked the mds and mon fixes from your pull-request onto jewel and built a new version. this allowed me to bring the mons back up. unfortunately, the mdsmap is incrementing, but it isn't dumping any of the new epochs. I'm rebuilding with the messages fix, (patching to change MDS_STATE_NULL to CEPH_MDS_STATE_NULL) in with the hope that a new mds map will be generated with the correct states.

# ceph mds dump
dumped fsmap epoch 903388
fs_name    combined
epoch      903384
flags      0
created    2016-08-08 16:42:34.345327
modified           2016-08-08 16:42:34.345327
tableserver        0
root       0
session_timeout    60
session_autoclose          300
max_file_size      17592186044416
last_failure       0
last_failure_osd_epoch     528805
compat     compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object,5=mds uses versioned encoding,6=dirfrag is stored in omap,8=no anchor table}
max_mds    1
in         0
up         {}
failed     0
damaged
stopped
data_pools         100,101,102
metadata_pool      98
inline_data        disabled

That FSMap contains a standby with '"standby_for_fscid": 0', but the existing filesystem is '"id": 2'.
Had him set it to 2 explicitly and that did take (based on updated fsmap) but the MDS remains in standby mode. Requested a monitor log with fresh boot sequence to trace it through.

ceph-post-file: 731781d4-c78c-47f9-9de3-e151b5c1a5f9

Above is the Monitor log with a fresh boot of the mds.

There is some other bug here with standby_for_rank and standby_for_fscid set correctly, I can reproduce it locally. Stand by...

Gah, I thought I saw it (created new FS and set standby_for_fscid, then saw it stuck in standby), but a few deamon restarts later I can't see it any more :-/

No, you're correct. The part you're missing is MDSMonitor::maybe_expand_cluster(), invoked from MDSMonitor::tick(). I'm not seeing why that (and the FSMap::find_replacement_for(), find_standby_for(), find_unused() functions it calls) aren't kicking the MDS over to active.

I think that if you use the repair tools to flush the MDS journal and then do an fs reset you should get everything back working again.

But I'd really like to understand how things got into this state first. Is it the result of something messed up in the point release encoding? Did you do some admin commands to your cluster that we didn't account for? The part where the MDS was insisting it was standby_for_fscid 0 might be the root of the problem.

I've been staring at this code for a while and am at the point where really I think it just will take a bunch of debug statements added to that whole call stack to figure out where it's going wrong.

there was definitely an encoding issue. I went back through the historical mdsmaps and it wasn't always insisting it was standby_for_fscid 0, it was sometimes 10000+ sometimes 0.

I haven't run any admin mds-related (or any others that I know of) commands that we haven't taken into account.

If you want to put together a branch with the debug logging you want, I'd be willing to run it tonight or tomorrow morning. I'd really like to get this bug straightened out, but I cannot wait too much longer. If a journal flush and an fs reset will help get it working I can do that tomorrow (after running the debugging branch if you want).

--
Adam

I built a debug commit and merged in wip-17466-jewel; named the result wip-1746-jewel-debug.

I'm building it now. What logs and levels would you like me to collect?

mon level 20 should do it.

http://people.cs.ksu.edu/~mozes/ceph-mon.hobbit01-debug-branch.log

Unfortunately, it would seem we're bailing out of maybe_expand_cluster before calling any of the other modified functions. Either we're down (CEPH_MDSMAP_DOWN), num_in_mds >= max_mds, or the MDSMAP is degraded. The middle one doesn't seem likely, the mdsmap doesn't indicate (to me) that its "down" or degraded, though.

Anything rank that is in the 'in' set should also be in one of failed,stopped,damaged or up.

I notice that in the earliest logs on this issue we could see rank 0 in the 'failed' set, so something has gone wrong since.

The only way I've seen this before was if someone used rmfailed without knowing what it did?

Well, crap. I don't remember running that, and it wasn't in the bash_history on the monitor I've been using, but:

2016-10-03 11:14:05.777419 7f6d4bbfd700 10 log_client  logged 2016-10-03 11:14:04.758659 mon.0 10.5.38.1:6789/0 6961 : audit [INF] from='client.? 10.5.1.3:0/269354402' entity='client.admin' cmd='[{"prefix": "mds rmfailed", "who": "0", "confirm": "--yes-i-really-mean-it"}]': finished
2016-10-03 11:55:40.410106 7f0f213fd700  0 mon.hobbit01@0(leader) e46 handle_command mon_command({"prefix": "mds rmfailed", "who": "0", "confirm": "--yes-i-really-mean-it"} v 0) v1
2016-10-03 11:55:40.410183 7f0f213fd700  0 log_channel(audit) log [INF] : from='client.1131003972 :/0' entity='client.admin' cmd=[{"prefix": "mds rmfailed", "who": "0", "confirm": "--yes-i-really-mean-it"}]: dispatch
2016-10-03 11:55:41.056921 7f0f25b88700  0 log_channel(audit) log [INF] : from='client.1131003972 :/0' entity='client.admin' cmd='[{"prefix": "mds rmfailed", "who": "0", "confirm": "--yes-i-really-mean-it"}]': finished

Looks like it happened just before comment 9. Given that this portion is now probably our fault, how should I go about flushing the journal and resetting the filesystem?

Digging through that patch, I'm not sure it is setup to work with the mdsmap->fsmap conversion that happened at some point in time.

Do I need to flush a journal before an fs reset?

As for the patch, I think this is what is needed to fix it up, although I'm not intimately familiar with ceph internals. As evidenced by my current issues.

   } else if (prefix == "mds addfailed") {
-    mds_rank_t who;
-    if (!cmd_getval(g_ceph_context, cmdmap, "who", who)) {
-      ss << "error parsing 'who' value '" 
-         << cmd_vartype_stringify(cmdmap["who"]) << "'";
-      return -EINVAL;
+    std::string role_str;
+    cmd_getval(g_ceph_context, cmdmap, "who", role_str);
+    mds_role_t role;
+    int rr = parse_role(role_str, &role, ss);
+    if (r < 0) {
+       ss << "invalid role '" << role_str << "'";
+       return -EINVAL;
     }
-    pending_mdsmap.failed.insert(who);
+    pending_fsmap.modify_filesystem(
+        role.fscid,
+        [role](std::shared_ptr<Filesystem fs)
+    {
+      fs->mds_map.failed.insert(role.rank);
+    });
+

I ended up going with a journal flush and a ceph fs reset. The mds is now up and clients can mount. Thank you both for all your help, even after it became obvious that the latter half of this issue was exacerbated by me.