Ceph

We have multiple NVMe-based clusters running the latest Pacific release
(16.2.11) that are experiencing a problem where their filesystems randomly go
read-only.

This problem first affected us in October of 2022 while the clusters were
running either 16.2.7, 16.2.9, or 16.2.10. Digging into the logs it seemed
that we were experiencing the problem reported in issue 54701 since concurrent
lookup and unlink operations were seen before the filesystem went read-only.

After patiently waiting for 16.2.11 to be released (which had a fix for 54701)
we proceeded to gradually roll it out to all the clusters. This was finished
last Wednesday (February 8th, 2023), but this weekend the problem re-appeared.

The log entries do look a little different now. It seems to start with some
slow requests for a file called wpo_logo_small.png*:

2023-02-11T15:05:43.135-0700 7fede94a8700 0 log_channel(cluster) log [WRN] : slow request 511.708058 seconds old, received at 2023-02-11T14:57:11.427532-0700: client_request(client.168395754:122198341 lookup #0x1000a03a2ba/wpo_logo_small.png.webp.lossless.webp 2023-02-11T14:57:11.426323-0700 caller_uid=[redacted], caller_gid=[redacted]{}) currently dispatched
2023-02-11T15:05:43.135-0700 7fede94a8700 0 log_channel(cluster) log [WRN] : slow request 514.370971 seconds old, received at 2023-02-11T14:57:08.764619-0700: client_request(client.168335863:181891244 lookup #0x1000a03a2ba/wpo_logo_small.png.webp.lossless.webp 2023-02-11T14:57:08.761738-0700 caller_uid=[redacted], caller_gid=[redacted]{}) currently dispatched
2023-02-11T15:05:43.135-0700 7fede94a8700 0 log_channel(cluster) log [WRN] : slow request 514.370960 seconds old, received at 2023-02-11T14:57:08.764630-0700: client_request(client.168335863:181891245 lookup #0x1000a03a2ba/wpo_logo_small.png.webp.lossless.webp 2023-02-11T14:57:08.761738-0700 caller_uid=[redacted], caller_gid=[redacted]{}) currently dispatched
2023-02-11T15:05:43.135-0700 7fede94a8700 0 log_channel(cluster) log [WRN] : slow request 514.370821 seconds old, received at 2023-02-11T14:57:08.764769-0700: client_request(client.168335863:181891247 create #0x1000a03a2ba/wpo_logo_small.png.webp.lossy.webp 2023-02-11T14:57:08.762738-0700 caller_uid=[redacted], caller_gid=[redacted]{}) currently failed to wrlock, waiting

followed by an MDS map being updated:

2023-02-11T15:05:51.283-0700 7fedeacab700 1 mds.[redacted] Updating MDS map to version 315291 from mon.2

then the file system going read-only:

2023-02-11T15:05:55.971-0700 7fede4c9f700 -1 mds.0.277011 unhandled write error (90) Message too long, force readonly...
2023-02-11T15:05:55.971-0700 7fede4c9f700 1 mds.0.cache force file system read-only
2023-02-11T15:05:55.971-0700 7fede4c9f700 0 log_channel(cluster) log [WRN] : force file system read-only

we added some auto-remediation that then restarts the MDS that is read-only:

2023-02-11T15:07:25.510-0700 7fedec4ae700 -1 received signal: Terminated from /usr/lib/systemd/systemd --system --deserialize 25 (PID: 1) UID: 0
2023-02-11T15:07:25.510-0700 7fedec4ae700 -1 mds.[redacted] * got signal Terminated *
2023-02-11T15:07:25.510-0700 7fedec4ae700 1 mds.[redacted] suicide! Wanted state up:active
2023-02-11T15:07:29.510-0700 7fedec4ae700 1 mds.0.277011 shutdown: shutting down rank 0

this causes the standby-replay to take over which then goes read-only shortly
afterwards:

2023-02-11T15:09:13.238-0700 7fd104c9d700 1 mds.[redacted] Updating MDS map to version 315305 from mon.0
2023-02-11T15:09:13.238-0700 7fd104c9d700 1 mds.0.315301 handle_mds_map i am now mds.0.315301
2023-02-11T15:09:13.238-0700 7fd104c9d700 1 mds.0.315301 handle_mds_map state change up:rejoin --> up:active
2023-02-11T15:09:13.238-0700 7fd104c9d700 1 mds.0.315301 recovery_done -- successful recovery!
2023-02-11T15:09:18.236-0700 7fd104c9d700 1 mds.0.315301 active_start
2023-02-11T15:09:25.221-0700 7fd104c9d700 1 mds.0.315301 cluster recovered.
2023-02-11T15:09:30.020-0700 7fd104c9d700 1 mds.[redacted] Updating MDS map to version 315306 from mon.0
2023-02-11T15:09:30.049-0700 7fd0fec91700 -1 mds.0.315301 unhandled write error (90) Message too long, force readonly...
2023-02-11T15:09:30.049-0700 7fd0fec91700 1 mds.0.cache force file system read-only
2023-02-11T15:09:30.049-0700 7fd0fec91700 0 log_channel(cluster) log [WRN] : force file system read-only

our auto-remediation then restarts that mds and the file system is then able to
become healthy again.

Unfortunately I haven't been able to reproduce the problem in an isolated
environment, but this code change to the wp-optimize plugin appears to be
related:

https://plugins.trac.wordpress.org/changeset/2794595/wp-optimize/trunk/cache/file-based-page-cache-functions.php?old=2737167&old_path=wp-optimize%2Ftrunk%2Fcache%2Ffile-based-page-cache-functions.php

A version with that change was released around the time this read-only problem
started affecting us.