Ceph » CephFS

Jul 27 09:29:38 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:29:38.505+0000 7f76e1941700  1 mds.0.288 handle_mds_map i am now mds.0.288
Jul 27 09:29:38 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:29:38.505+0000 7f76e1941700  1 mds.0.288 handle_mds_map state change up:boot --> up:replay
Jul 27 09:29:38 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:29:38.505+0000 7f76e1941700  1 mds.0.288 replay_start
Jul 27 09:29:38 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:29:38.505+0000 7f76e1941700  1 mds.0.288  waiting for osdmap 87650 (which blacklists prior instance)
Jul 27 09:30:08 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:30:08.590+0000 7f76db134700 -1 mds.0.inotable: load_2 could not read table: -110
Jul 27 09:30:08 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:30:08.590+0000 7f76db134700 -1 log_channel(cluster) log [ERR] : error reading table object 'mds0_inotable' -110 ((110) Connection timed out)
Jul 27 09:30:10 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]: 2021-07-27T09:30:10.858+0000 7f76db134700  1 mds.newbrunswick2 respawn!
...
Jul 27 09:30:11 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]:   -13> 2021-07-27T09:30:08.590+0000 7f76db134700 -1 mds.0.inotable: load_2 could not read table: -110
Jul 27 09:30:11 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]:   -12> 2021-07-27T09:30:08.590+0000 7f76db134700 -1 log_channel(cluster) log [ERR] : error reading table object 'mds0_inotable' -110 ((110) Connection timed out)
Jul 27 09:30:11 newbrunswick2 container_name/ceph-mds-newbrunswick2[861]:   -11> 2021-07-27T09:30:08.590+0000 7f76db134700  5 mds.beacon.newbrunswick2 set_want_state: up:replay -> down:damaged

Do you have the cluster or mon or osd logs from this same time -- maybe the relevant PGs are inactive so the read of mds0_inotable times out.

Since this is reproduceable, you could try delaying the MDS restart until after all PGs are active and see if it "fixes" this.

The PGs are not active until 09:30:14, so that's evidence for my theory.
This looks like a bootstrapping issue arising when MDS's are co-located with OSDs.

Jul 27 09:30:00 newbrunswick0 docker[1244]: debug 2021-07-27T09:29:59.999+0000 7fb5dd9ee700  0 log_channel(cluster) log [WRN] : [WRN] PG_AVAILABILITY: Reduced data availability: 39 pgs inactive, 84 pgs peering
Jul 27 09:30:14 newbrunswick0 docker[1244]: debug 2021-07-27T09:30:14.111+0000 7fb5dd9ee700  0 log_channel(cluster) log [INF] : Health check cleared: PG_AVAILABILITY (was: Reduced data availability: 3 pgs inactive, 49 pgs peering)
Jul 27 09:30:14 newbrunswick0 docker[1244]: debug 2021-07-27T09:30:14.111+0000 7fb5dd9ee700  0 log_channel(cluster) log [INF] : Health check cleared: PG_DEGRADED (was: Degraded data redundancy: 30/129252 objects degraded (0.023%), 2 pgs degraded)

You can also try `ceph mds repaired 0` when the fs is in damaged state, after all PGs are active+clean.

Thanks Dan, that's a convincing diagnosis. We've diverted our attention to other projects but I'll look into implementing something smarter restart logic to delay the MDS restart.

Should ceph be smart enough to handle this natively? i.e. MDS will start in a holding state until PGs are all active, or recover automatically when the PGs return to active?

We've been using `ceph mds repaired 0` to return to a healthy state, thanks.

David Piper wrote:

Do the pgs need to be `active+clean` or are there other pg states that it would be safe to start MDS during? e.g. combinations of undersized / degraded / peered etc.

All PGs being `active` is sufficient. If you start the MDS while metadata PGs are active+degraded/undersized, then the IOs causing this issue should succeed, but I suppose there is a chance that an IO may take longer than the timeout causing this issue. If you want to be 100% sure of success, wait for `active+clean` before starting the MDS.

BTW, I was looking for, but didn't yet find, the rados client io timeout which seems to be at the root of this issue. Finding that, I suppose that an alternative solution would be to set it to something large, e.g. 300s. But I'm unfamiliar in this area -- normally rados IOs are not supposed to timeout ever. The MDS must be using some intentionally time-limited IO when bootstrapping. Someone more familiar could perhaps clarify how this works.

I should mention, I've only had this reproduce once after we added the fix, when previously it was 100% reproducible, so it certainly seems to be improved after adding the delay.

Hi again - another update on this one.

We deploy on both OpenStack and VMware hosted VMs, with the intention that they resulting VM is functionally identical. However I can't reproduce this on a VMware hosted cluster of VMs, so I'm investigating why that may be - i.e. what the difference is on our deployment types.

I still think that the RADOS client timeouts are the culprit, with the MDS damage being a symptom of that problem - as I mentioned earlier the RGW restarts I experienced also log that they hit RADOS client timeouts.

I'm expecting I eventually uncover something amiss with our OpenStack VM bootstrapping that is causing this, but I think this may still be an underlying Ceph MDS bug that this RADOS client timeout leaves the cluster in a state where the filesystem is offline and can't auto-recover. ​

Meanwhile any advice on how to debug the RADOS client timeouts is greatly appreciated. I'll report back if I find the cause. Thanks.

...and I've just found that we're globally setting:

```
rados_osd_op_timeout: 30
rados_mon_op_timeout: 30
```

As per: https://tracker.ceph.com/issues/7386 seems like this is off-piste. I removed the config and can't reproduce the original issue.

So I guess that this isn't a bug after all, just bad config from us - I'm not sure why we have got away with this till now, and also not sure why it only happens on OpenStack deployments, but probably not interesting to anyone else at this point!