Ceph » CephFS

We have seen 3 identical crashes so far. (Logs of the crashed MDSs are at ceph-post-file: a74beec8-0a68-44c1-bfc5-56da4872414f)

The crash is always triggered by an export of /volumes/ to an mds, who then crashes in MDSRank::get_session for the client at 188.184.94.182. This IP is our OpenStack Manila controller (who is creating/deleting a test share once per hour, but otherwise pretty idle).

Here's an example export which triggered a crash today:

2019-06-09 20:34:08.382444 7fa3f1b2c700  0 mds.0.migrator nicely exporting 
to mds.2 [dir 0x1000023defd /volumes/ [2,head] auth{1=3,2=3,3=1,4=2} pv=124817319 v=124817316 
cv=124814979/124814979 REP ap=2+1+1 state=1610612738|complete f(v8364 m2019-06-09 20:34:02.721217 
201=199+2) n(v7712004 rc2029-07-04 21:56:43.000000 b84032403688154 74034480=65652517+8381963) 
hs=201+4,ss=0+0 dirty=6 | dnwaiter=0 child=1 frozen=0 subtree=0 importing=0 replicated=1 
dirty=1 waiter=0 authpin=1 tempexporting=0 0x55d4540d9800]

and the crash this time on mds.2:

    -5> 2019-06-09 20:34:09.111916 7f664e49d700  0 -- 137.138.149.200:6800/331189051 >> 188.184.94.182:0/3076084349 conn(0x55dd38659000 :6800 
s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=0).handle_connect_msg accept we reset (peer sent cseq 116), sending RESETSESSION
    -4> 2019-06-09 20:34:10.438319 7f6648516700 10 monclient: _send_mon_message to mon.cephflax-mon-9b406e0261 at 137.138.121.135:6789/0
    -3> 2019-06-09 20:34:10.646909 7f6648d17700  2 mds.2.cache Memory usage:  total 17978216, rss 17503916, heap 307232, baseline 307232, buffers 0, 84434 / 
5372784 inodes have caps, 85166 caps, 0.0158514 caps per inode
    -2> 2019-06-09 20:34:13.916519 7f664b51c700  1 mds.cephflax-mds-4b5d89fe52 Updating MDS map to version 198555 from mon.0
    -1> 2019-06-09 20:34:14.001817 7f664e49d700  0 -- 137.138.149.200:6800/331189051 >> 188.184.94.182:0/3076084349 conn(0x55dd38659000 :6800 
s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=419012 cs=1 l=0).process missed message?  skipped from seq 0 to 2131513044
     0> 2019-06-09 20:34:14.005921 7f664b51c700 -1 /builddir/build/BUILD/ceph-12.2.12/src/mds/MDSRank.cc: In function 'Session* MDSRank::get_session(Message*)' 
thread 7f664b51c700 time 2019-06-09 20:34:14.001930
/builddir/build/BUILD/ceph-12.2.12/src/mds/MDSRank.cc: 1304: FAILED assert(session->get_nref() == 1)

With gdb I found that session->get_nref() = 2:

(gdb) p session->nref
value has been optimized out
(gdb) p ((Session *)(*(Connection *)(m->connection)).priv).nref
$67 = {<std::__atomic_base<unsigned long>> = {_M_i = 2}, <No data fields>}

Here's more of that session in case it helps:

(gdb) p *((Session *)(*(Connection *)(m->connection)).priv)
$69 = {<RefCountedObject> = {_vptr.RefCountedObject = 0x55b1afb21c50 <vtable for Session+16>, 
    nref = {<std::__atomic_base<unsigned long>> = {_M_i = 2}, <No data fields>}, cct = 0x0}, 
  state = 0, state_seq = 0, importing_count = 0, human_name = "", 
  projected = std::deque with 0 elements, load_avg = {val = 0, delta = 0, vel = 0, last_decay = {
      tv = {tv_sec = 0, tv_nsec = 0}}, rate = {k = 0}}, load_avg_rate = {k = 0}, recall_caps = {
    val = 0, delta = 0, vel = 0, last_decay = {tv = {tv_sec = 1559757242, tv_nsec = 260002304}}, 
    rate = {k = -0.011552453009332421}}, release_caps = {val = 0, delta = 0, vel = 0, last_decay = {
      tv = {tv_sec = 1559757242, tv_nsec = 260003346}}, rate = {k = -0.011552453009332421}}, 
  recall_caps_throttle = {val = 0, delta = 0, vel = 0, last_decay = {tv = {tv_sec = 1559757242, 
        tv_nsec = 260004647}}, rate = {k = -0.2772588722239781}}, recall_limit = 0, birth_time = {
    __d = {__r = 1762031282356192}}, info = {inst = {name = {_type = 8 '\b', _num = 76672649, 
...

Looking at `MDSRank::get_session`, I wonder if it's possible that this is the only client which is triggering the `if (session->is_closed())` codepath ?
If so, this would be the only time that we ever check that that nref 1 on the sessions (so maybe it is never 1 for any session ??)

I was looking at commit 5dd000eb44e39567657a346451eec6adba3efb63 and I'm wondering if that backport is missing `session->put()` in MDSRankDispatcher::ms_dispatch ?? (Every other get_priv of a Session in luminous mds code doesn't carry the ref.)
So maybe the correct (luminous only) fix would be:

diff --git a/src/mds/MDSRank.cc b/src/mds/MDSRank.cc
index 89b6e97b06..36a3e9367e 100644
--- a/src/mds/MDSRank.cc
+++ b/src/mds/MDSRank.cc
@@ -952,8 +952,10 @@ bool MDSRankDispatcher::ms_dispatch(Message *m)
 {
   if (m->get_source().is_client()) {
     Session *session = static_cast<Session*>(m->get_connection()->get_priv());
-    if (session)
+    if (session) {
+      session->put(); // do not carry ref
       session->last_seen = Session::clock::now();
+    }
   }

   inc_dispatch_depth();

For now, we're running with mds_bal_interval = 0 to disable the balancer. But of course it would be good to hear if the above should fix, then we'll compile and try it out. (But I want to be cautious, as this is happening on our prod cluster).