Ceph » CephFS

Here is a log with debug_mds=10. ceph-post-file: f4f87969-d492-4e1d-8e8e-5c9e81e45d2f

From what I can gather, (and I might be wrong), this happens when a client does getattr with a Stale fh:

   -42> 2020-10-12 16:22:54.848 7faf9f4df700  7 mds.1.server reply_client_request -116 ((116) Stale file handle) client_request(client.1247869482:6492 getattr As #0x10041167375 2020-10-06 17:09:53.325431 RETRY=229 caller_uid=0, caller_gid=0{}) v4
   -41> 2020-10-12 16:22:54.848 7faf9f4df700 10 mds.1.server apply_allocated_inos 0x0 / [] / 0x0
    -2> 2020-10-12 16:22:54.851 7faf9f4df700 -1 /builddir/build/BUILD/ceph-14.2.11/src/mds/SessionMap.cc: In function 'void SessionMap::hit_session(Session*)' thread 7faf9f4df700 time 2020-10-12 16:22:54.849676
     0> 2020-10-12 16:22:54.854 7faf9f4df700 -1 *** Caught signal (Aborted) **
 in thread 7faf9f4df700 thread_name:ms_dispatch

I am going to evict those clients with Stale file handles then try again.

Indeed, I evicted the weird clients spinning on Stale file handles, and then the mds stopping procedure finished without crashing.

For completeness, here is one such client that can trigger this:

    {
        "id": 1223433359,
        "entity": {
            "name": {
                "type": "client",
                "num": 1223433359
            },
            "addr": {
                "type": "any",
                "addr": "redacted:0",
                "nonce": 1813269304
            }
        },
        "state": "open",
        "num_leases": 0,
        "num_caps": 1,
        "request_load_avg": 14545,
        "uptime": 16737.925794727998,
        "requests_in_flight": 0,
        "completed_requests": 0,
        "reconnecting": false,
        "recall_caps": {
            "value": 0,
            "halflife": 60
        },
        "release_caps": {
            "value": 0,
            "halflife": 60
        },
        "recall_caps_throttle": {
            "value": 0,
            "halflife": 2.5
        },
        "recall_caps_throttle2o": {
            "value": 0,
            "halflife": 0.5
        },
        "session_cache_liveness": {
            "value": 0,
            "halflife": 300
        },
        "inst": "client.1223433359 redacted:0/1813269304",
        "completed_requests": [],
        "prealloc_inos": [],
        "used_inos": [],
        "client_metadata": {
            "features": "0x0000000000001fff",
            "ceph_sha1": "75f4de193b3ea58512f204623e6c5a16e6c1e1ba",
            "ceph_version": "ceph version 14.2.4 (75f4de193b3ea58512f204623e6c5a16e6c1e1ba) nautilus (stable)",
            "entity_id": "pvc-990e69c2-518d-4974-8867-4d6ad8ddf387",
            "hostname": "kubeflow-ml-001-redacted-node-1.cern.ch.ch",
            "mount_point": "/var/lib/kubelet/plugins/kubernetes.io/csi/pv/pvc-990e69c2-518d-4974-8867-4d6ad8ddf387/globalmount",
            "pid": "891",
            "root": "/volumes/_nogroup/af09d1d5-6854-4156-8d47-3fd0d3aed30b" 
        }
    },

Dan van der Ster wrote:

Indeed, I evicted the weird clients spinning on Stale file handles, and then the mds stopping procedure finished without crashing.

For completeness, here is one such client that can trigger this:
[...]

Hi Dan, is that session dump from rank 0? It must be rank 1 did not have a session with that client to trip that assertion.

Patrick Donnelly wrote:

Dan van der Ster wrote:

Indeed, I evicted the weird clients spinning on Stale file handles, and then the mds stopping procedure finished without crashing.

For completeness, here is one such client that can trigger this:
[...]

Hi Dan, is that session dump from rank 0? It must be rank 1 did not have a session with that client to trip that assertion.

Hi Patrick, I'm not sure, because this was an output of tell mds.*. But I'll check next time I trigger this. (I can reproduce the stuck clients by failing over to a standby mds).

I have the coredump so we can debug further. In the hit_session frame, we see the session clearly:

(gdb) up
#8  0x000055f33658dbfa in SessionMap::hit_session (this=0x55f338b5f150, session=session@entry=0x55f338c3b000)
(gdb) p session->state
$3 = 3
(gdb) p Session::STATE_CLOSING+0
$4 = 3
(gdb) p session->info
$5 = {inst = {name = {_type = 8 '\b', _num = 1247869482, static TYPE_MON = 1, static TYPE_MDS = 2,
      static TYPE_OSD = 4, static TYPE_CLIENT = 8, static TYPE_MGR = 16, static NEW = -1}, addr = {
      static TYPE_DEFAULT = entity_addr_t::TYPE_MSGR2, type = 3, nonce = 1807280899, u = {sa = {sa_family = 2,
          sa_data = "\000\000\211\212\067'\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 0,
          sin_addr = {s_addr = 657951369}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2,
          sin6_port = 0, sin6_flowinfo = 657951369, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>,
              __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}}},
  completed_requests = std::map with 0 elements, prealloc_inos = {_size = 0, m = std::map with 0 elements},
  used_inos = {_size = 0, Python Exception <class 'gdb.error'> There is no member or method named _M_value_field.:
m = std::map with 0 elements}, client_metadata = {kv_map = std::map with 7 elements,
    features = {static bits_per_block = 64, _vec = std::vector of length 1, capacity 1 = {8191}}},
  completed_flushes = std::set with 0 elements, auth_name = {static STR_TO_ENTITY_TYPE = {_M_elems = {{type = 32,
          str = 0x7fafa8fff606 "auth"}, {type = 1, str = 0x7fafa8fde9a7 "mon"}, {type = 4,
          str = 0x7fafa9021bf8 "osd"}, {type = 2, str = 0x7fafa90344ff "mds"}, {type = 16,
          str = 0x7fafa901bf7e "mgr"}, {type = 8, str = 0x7fafa901bfcb "client"}}}, type = 8,
    id = "pvc-fb998d31-d9c4-462d-a7a4-6f768458cd56", type_id = "client.pvc-fb998d31-d9c4-462d-a7a4-6f768458cd56"}}

So looks like we are in hit_session when state is Session::STATE_CLOSING.

Does this fix, or would it be better to check the session state before calling hit_session?

diff --git a/src/mds/SessionMap.cc b/src/mds/SessionMap.cc
index ae80cef..18bfc5c 100644
--- a/src/mds/SessionMap.cc
+++ b/src/mds/SessionMap.cc
@@ -1015,7 +1015,8 @@ int Session::check_access(CInode *in, unsigned mask,
 // track total and per session load
 void SessionMap::hit_session(Session *session) {
   uint64_t sessions = get_session_count_in_state(Session::STATE_OPEN) +
-                      get_session_count_in_state(Session::STATE_STALE);
+                      get_session_count_in_state(Session::STATE_STALE) +;
+                      get_session_count_in_state(Session::STATE_CLOSING);
   ceph_assert(sessions != 0);

   double total_load = total_load_avg.hit();

That patch looks correct. Would you like to post the PR Dan?

I tested the fix in the same env, with the stale fh clients, and now the mds does not crash while stopping.