CAUTION: This email originated from outside of the LMB:
*.-dparmar@xxxxxxxxxx-.*
Do not click links or open attachments unless you recognize the
sender and know the content is safe.
If you think this is a phishing email, please forward it to
phishing@xxxxxxxxxxxxxxxxx
--
Ugh, something went horribly wrong. I've downloaded the MDS logs
that contain assertion failure and it looks relevant to this [0].
Do you have client logs for this?
The other log that you shared is being downloaded right now, once
that's done and I'm done going through it, I'll update you.
[0] https://tracker.ceph.com/issues/54546
On Mon, Jul 8, 2024 at 4:49 PM Ivan Clayson
<ivan@xxxxxxxxxxxxxxxxx> wrote:
Hi Dhairya,
Sorry to resurrect this thread again, but we still
unfortunately have an issue with our filesystem after we
attempted to write new backups to it.
We finished the scrub of the filesystem on Friday and ran a
repair scrub on the 1 directory which had metadata damage.
After doing so and rebooting, the cluster reported no issues
and data was accessible again.
We re-started the backups to run over the weekend and
unfortunately the filesystem crashed again where the log of
the failure is here:
https://www.mrc-lmb.cam.ac.uk/scicomp/data/uploads/ceph/ceph-mds.pebbles-s2.log-20240708.gz.
We ran the backups on kernel mounts of the filesystem without
the nowsync option this time to avoid the out-of-sync write
problems..
I've tried resetting the journal again after recovering the
dentries but unfortunately the filesystem is still in a
failed state despite setting joinable to true. The log of
this crash is here:
https://www.mrc-lmb.cam.ac.uk/scicomp/data/uploads/ceph/ceph-mds.pebbles-s4.log-20240708.
I'm not sure how to proceed as I can't seem to get any MDS to
take over the first rank. I would like to do a scrub of the
filesystem and preferably overwrite the troublesome files
with the originals on the live filesystem. Do you have any
advice on how to make the filesystem leave its failed state?
I have a backup of the journal before I reset it so I can
roll back if necessary.
Here are some details about the filesystem at present:
root@pebbles-s2 11:49 [~]: ceph -s; ceph fs status
cluster:
id: e3f7535e-d35f-4a5d-88f0-a1e97abcd631
health: HEALTH_ERR
1 filesystem is degraded
1 large omap objects
1 filesystem is offline
1 mds daemon damaged
nobackfill,norebalance,norecover,noscrub,nodeep-scrub,nosnaptrim
flag(s) set
1750 pgs not deep-scrubbed in time
1612 pgs not scrubbed in time
services:
mon: 4 daemons, quorum
pebbles-s1,pebbles-s2,pebbles-s3,pebbles-s4 (age 50m)
mgr: pebbles-s2(active, since 77m), standbys:
pebbles-s1, pebbles-s3, pebbles-s4
mds: 1/2 daemons up, 3 standby
osd: 1380 osds: 1380 up (since 76m), 1379 in (since
10d); 10 remapped pgs
flags
nobackfill,norebalance,norecover,noscrub,nodeep-scrub,nosnaptrim
data:
volumes: 1/2 healthy, 1 recovering; 1 damaged
pools: 7 pools, 2177 pgs
objects: 3.24G objects, 6.7 PiB
usage: 8.6 PiB used, 14 PiB / 23 PiB avail
pgs: 11785954/27384310061 objects misplaced (0.043%)
2167 active+clean
6 active+remapped+backfilling
4 active+remapped+backfill_wait
ceph_backup - 0 clients
===========
RANK STATE MDS ACTIVITY DNS INOS DIRS CAPS
0 failed
POOL TYPE USED AVAIL
mds_backup_fs metadata 1174G 3071G
ec82_primary_fs_data data 0 3071G
ec82pool data 8085T 4738T
ceph_archive - 2 clients
============
RANK STATE MDS ACTIVITY DNS INOS
DIRS CAPS
0 active pebbles-s4 Reqs: 0 /s 13.4k 7105
118 2
POOL TYPE USED AVAIL
mds_archive_fs metadata 5184M 3071G
ec83_primary_fs_data data 0 3071G
ec83pool data 138T 4307T
STANDBY MDS
pebbles-s2
pebbles-s3
pebbles-s1
MDS version: ceph version 17.2.7
(b12291d110049b2f35e32e0de30d70e9a4c060d2) quincy (stable)
root@pebbles-s2 11:55 [~]: ceph fs dump
e2643889
enable_multiple, ever_enabled_multiple: 1,1
default 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,9=file layout v2,10=snaprealm v2}
legacy client fscid: 1
Filesystem 'ceph_backup' (1)
fs_name ceph_backup
epoch 2643888
flags 12 joinable allow_snaps allow_multimds_snaps
created 2023-05-19T12:52:36.302135+0100
modified 2024-07-08T11:17:55.437861+0100
tableserver 0
root 0
session_timeout 60
session_autoclose 300
max_file_size 109934182400000
required_client_features {}
last_failure 0
last_failure_osd_epoch 494515
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,7=mds uses inline
data,8=no anchor table,9=file layout v2,10=snaprealm v2}
max_mds 1
in 0
up {}
failed
damaged 0
stopped
data_pools [6,3]
metadata_pool 2
inline_data disabled
balancer
standby_count_wanted 1
Kindest regards,
Ivan
On 28/06/2024 15:17, Dhairya Parmar wrote:
CAUTION: This email originated from outside of the LMB:
*.-dparmar@xxxxxxxxxx-.*
Do not click links or open attachments unless you recognize
the sender and know the content is safe.
If you think this is a phishing email, please forward it to
phishing@xxxxxxxxxxxxxxxxx
--
On Fri, Jun 28, 2024 at 6:02 PM Ivan Clayson
<ivan@xxxxxxxxxxxxxxxxx> wrote:
Hi Dhairya,
I would be more than happy to share our corrupted
journal. Has the host key changed for drop.ceph.com
<http://drop.ceph.com>? The fingerprint I'm being sent
is 7T6dSMcUUa5refV147WEZR99UgW8Y1qYEXZr8ppvog4 which is
different to the one in our
/usr/share/ceph/known_hosts_drop.ceph.com
<http://known_hosts_drop.ceph.com>.
Ah, strange. Let me get in touch with folks who might know
about this, will revert back to you ASAP
Thank you for your advice as well. We've reset our MDS'
journal and are currently in the process of a full
filesystem scrub which understandably is taking quite a
bit of time but seems to be progressing through the
objects fine.
YAY!
Thank you ever so much for all your help and please do
feel free to follow up with us if you would like any
further details about our crash!
Glad to hear it went well, this bug is being worked on with
high priority and once the patch is ready, it will be
backported.
The root cause of this issue is the `nowsync` (async dirops)
being enabled by default with kclient [0]. This feature
allows asynchronous creation and deletion of files,
optimizing performance by avoiding round-trip latency for
these system calls. However, in very rare cases (like yours
:D), it can affect the system's consistency and stability
hence if this kind of optimization is not a priority for
your workload, I recommend turning it off by switching
the mount points to `wsync` and also set the MDS config
`mds_client_delegate_inos_pct` to `0` so that you don't end
up in this situation again (until the bug fix arrives :)).
[0]
https://github.com/ceph/ceph-client/commit/f7a67b463fb83a4b9b11ceaa8ec4950b8fb7f902
Kindest regards,
Ivan
On 27/06/2024 12:39, Dhairya Parmar wrote:
CAUTION: This email originated from outside of the LMB:
*.-dparmar@xxxxxxxxxx-.*
Do not click links or open attachments unless you
recognize the sender and know the content is safe.
If you think this is a phishing email, please forward
it to phishing@xxxxxxxxxxxxxxxxx
--
Hi Ivan,
The solution (which has been successful for us in the
past) is to reset the journal. This would bring the fs
back online and return the MDSes to a stable state, but
some data would be lost—the data in the journal that
hasn't been flushed to the backing store would be gone.
Therefore, you should try to flush out as much journal
data as possible before resetting the journal.
Here are the steps for this entire process:
1) Bring the FS offline
$ ceph fs fail <fs_name>
2) Recover dentries from journal (run it with every MDS
Rank)
$ cephfs-journal-tool --rank=<fs_name>:<mds-rank> event
recover_dentries summary
3) Reset the journal (again with every MDS Rank)
$ cephfs-journal-tool --rank=<fs_name>:<mds-rank>
journal reset
4) Bring the FS online
$ cephfs fs set <fs_name> joinable true
5) Restart the MDSes
6) Perform scrub to ensure consistency of fs
$ ceph tell mds.<fs_name>:0 scrub start <path>
[scrubopts] [tag]
# you could try a recursive scrub maybe `ceph tell
mds.<fs_name>:0 scrub start / recursive`
Some important notes to keep in mind:
* Recovering dentries will take time (generally, rank 0
is the most time-consuming, but the rest should be quick).
* cephfs-journal-tool and metadata OSDs are bound to
use a significant CPU percentage. This is because
cephfs-journal-tool has to swig the journal data and
flush it out to the backing store, which also makes the
metadata operations go rampant, resulting in OSDs
taking a significant percentage of CPU.
Do let me know how this goes.
On Thu, Jun 27, 2024 at 3:44 PM Ivan Clayson
<ivan@xxxxxxxxxxxxxxxxx> wrote:
Hi Dhairya,
We can induce the crash by simply restarting the
MDS and the crash seems to happen when an MDS goes
from up:standby to up:replay. The MDS works through
a few files in the log before eventually crashing
where I've included the logs for this here (this is
after I imported the backed up journal which I hope
was successful but please let me know if you
suspect it wasn't!):
https://www.mrc-lmb.cam.ac.uk/scicomp/data/uploads/ceph/ceph-mds.pebbles-s3.mds_restart_crash.log
With respect to the client logs, are you referring
to the clients who are writing to the filesystem?
We don't typically run them in any sort of debug
mode and we have quite a few machines running our
backup system but we can look an hour or so before
the first MDS crash (though I don't know if this is
when the de-sync occurred). Here are some MDS logs
with regards to the initial crash on Saturday
morning though which may be helpful:
-59> 2024-06-22T05:41:43.090+0100
7f184ce82700 10 monclient: tick
-58> 2024-06-22T05:41:43.090+0100
7f184ce82700 10 monclient: _check_auth_rotating
have uptodate secrets (they expire after
2024-06-22T05:41:13.091556+0100)
-57> 2024-06-22T05:41:43.208+0100
7f184de84700 1 mds.pebbles-s2 Updating MDS map
to version 2529650 from mon.3
-56> 2024-06-22T05:41:43.208+0100
7f184de84700 4 mds.0.purge_queue operator():
data pool 6 not found in OSDMap
-55> 2024-06-22T05:41:43.208+0100
7f184de84700 4 mds.0.purge_queue operator():
data pool 3 not found in OSDMap
-54> 2024-06-22T05:41:43.209+0100
7f184de84700 5 asok(0x5592e7968000)
register_command objecter_requests hook
0x5592e78f8800
-53> 2024-06-22T05:41:43.209+0100
7f184de84700 10 monclient: _renew_subs
-52> 2024-06-22T05:41:43.209+0100
7f184de84700 10 monclient: _send_mon_message to
mon.pebbles-s4 at v2:10.1.5.134:3300/0
<http://10.1.5.134:3300/0>
-51> 2024-06-22T05:41:43.209+0100
7f184de84700 10 log_channel(cluster)
update_config to_monitors: true to_syslog:
false syslog_facility: prio: info to_graylog:
false graylog_host: 127.0.0.1 graylog_port: 12201)
-50> 2024-06-22T05:41:43.209+0100
7f184de84700 4 mds.0.purge_queue operator():
data pool 6 not found in OSDMap
-49> 2024-06-22T05:41:43.209+0100
7f184de84700 4 mds.0.purge_queue operator():
data pool 3 not found in OSDMap
-48> 2024-06-22T05:41:43.209+0100
7f184de84700 4 mds.0.0 apply_blocklist: killed
0, blocklisted sessions (0 blocklist entries, 0)
-47> 2024-06-22T05:41:43.209+0100
7f184de84700 1 mds.0.2529650 handle_mds_map i
am now mds.0.2529650
-46> 2024-06-22T05:41:43.209+0100
7f184de84700 1 mds.0.2529650 handle_mds_map
state change up:standby --> up:replay
-45> 2024-06-22T05:41:43.209+0100
7f184de84700 5 mds.beacon.pebbles-s2
set_want_state: up:standby -> up:replay
-44> 2024-06-22T05:41:43.209+0100
7f184de84700 1 mds.0.2529650 replay_start
-43> 2024-06-22T05:41:43.209+0100
7f184de84700 1 mds.0.2529650 waiting for
osdmap 473739 (which blocklists prior instance)
-42> 2024-06-22T05:41:43.209+0100
7f184de84700 10 monclient: _send_mon_message to
mon.pebbles-s4 at v2:10.1.5.134:3300/0
<http://10.1.5.134:3300/0>
-41> 2024-06-22T05:41:43.209+0100
7f1849e7c700 2 mds.0.cache Memory usage:
total 299012, rss 37624, heap 182556, baseline
182556, 0 / 0 inodes have caps, 0 caps, 0 caps
per inode
-40> 2024-06-22T05:41:43.224+0100
7f184de84700 10 monclient: _renew_subs
-39> 2024-06-22T05:41:43.224+0100
7f184de84700 10 monclient: _send_mon_message to
mon.pebbles-s4 at v2:10.1.5.134:3300/0
<http://10.1.5.134:3300/0>
-38> 2024-06-22T05:41:43.224+0100
7f184de84700 10 monclient:
handle_get_version_reply finishing 1 version 473739
-37> 2024-06-22T05:41:43.224+0100
7f1847e78700 2 mds.0.2529650 Booting: 0:
opening inotable
-36> 2024-06-22T05:41:43.224+0100
7f1847e78700 2 mds.0.2529650 Booting: 0:
opening sessionmap
-35> 2024-06-22T05:41:43.224+0100
7f1847e78700 2 mds.0.2529650 Booting: 0:
opening mds log
-34> 2024-06-22T05:41:43.224+0100
7f1847e78700 5 mds.0.log open discovering log
bounds
-33> 2024-06-22T05:41:43.224+0100
7f1847e78700 2 mds.0.2529650 Booting: 0:
opening purge queue (async)
-32> 2024-06-22T05:41:43.224+0100
7f1847e78700 4 mds.0.purge_queue open: opening
-31> 2024-06-22T05:41:43.224+0100
7f1847e78700 1 mds.0.journaler.pq(ro) recover
start
-30> 2024-06-22T05:41:43.224+0100
7f1847e78700 1 mds.0.journaler.pq(ro) read_head
-29> 2024-06-22T05:41:43.224+0100
7f1847e78700 2 mds.0.2529650 Booting: 0:
loading open file table (async)
-28> 2024-06-22T05:41:43.224+0100
7f1847e78700 2 mds.0.2529650 Booting: 0:
opening snap table
-27> 2024-06-22T05:41:43.224+0100
7f1847677700 4 mds.0.journalpointer Reading
journal pointer '400.00000000'
-26> 2024-06-22T05:41:43.224+0100
7f1850689700 10 monclient: get_auth_request con
0x5592e8987000 auth_method 0
-25> 2024-06-22T05:41:43.225+0100
7f1850e8a700 10 monclient: get_auth_request con
0x5592e8987c00 auth_method 0
-24> 2024-06-22T05:41:43.252+0100
7f1848e7a700 1 mds.0.journaler.pq(ro)
_finish_read_head loghead(trim 231160676352,
expire 231163662875, write 231163662875,
stream_format 1). probing for end of log (from
231163662875)...
-23> 2024-06-22T05:41:43.252+0100
7f1848e7a700 1 mds.0.journaler.pq(ro) probing
for end of the log
-22> 2024-06-22T05:41:43.252+0100
7f1847677700 1 mds.0.journaler.mdlog(ro)
recover start
-21> 2024-06-22T05:41:43.252+0100
7f1847677700 1 mds.0.journaler.mdlog(ro) read_head
-20> 2024-06-22T05:41:43.252+0100
7f1847677700 4 mds.0.log Waiting for journal
0x200 to recover...
-19> 2024-06-22T05:41:43.252+0100
7f1850689700 10 monclient: get_auth_request con
0x5592e8bc6000 auth_method 0
-18> 2024-06-22T05:41:43.253+0100
7f185168b700 10 monclient: get_auth_request con
0x5592e8bc6800 auth_method 0
-17> 2024-06-22T05:41:43.257+0100
7f1847e78700 1 mds.0.journaler.mdlog(ro)
_finish_read_head loghead(trim 90131453181952,
expire 90131465778558, write 90132009715463,
stream_format 1). probing for end of log (from
90132009715463)...
-16> 2024-06-22T05:41:43.257+0100
7f1847e78700 1 mds.0.journaler.mdlog(ro)
probing for end of the log
-15> 2024-06-22T05:41:43.257+0100
7f1847e78700 1 mds.0.journaler.mdlog(ro)
_finish_probe_end write_pos = 90132019384791
(header had 90132009715463). recovered.
-14> 2024-06-22T05:41:43.257+0100
7f1847677700 4 mds.0.log Journal 0x200 recovered.
-13> 2024-06-22T05:41:43.257+0100
7f1847677700 4 mds.0.log Recovered journal
0x200 in format 1
-12> 2024-06-22T05:41:43.273+0100
7f1848e7a700 1 mds.0.journaler.pq(ro)
_finish_probe_end write_pos = 231163662875
(header had 231163662875). recovered.
-11> 2024-06-22T05:41:43.273+0100
7f1848e7a700 4 mds.0.purge_queue operator():
open complete
-10> 2024-06-22T05:41:43.273+0100
7f1848e7a700 1 mds.0.journaler.pq(ro)
set_writeable
-9> 2024-06-22T05:41:43.441+0100
7f1847e78700 2 mds.0.2529650 Booting: 1:
loading/discovering base inodes
-8> 2024-06-22T05:41:43.441+0100
7f1847e78700 0 mds.0.cache creating system
inode with ino:0x100
-7> 2024-06-22T05:41:43.442+0100
7f1847e78700 0 mds.0.cache creating system
inode with ino:0x1
-6> 2024-06-22T05:41:43.442+0100
7f1847e78700 2 mds.0.2529650 Booting: 2:
replaying mds log
-5> 2024-06-22T05:41:43.442+0100
7f1847e78700 2 mds.0.2529650 Booting: 2:
waiting for purge queue recovered
-4> 2024-06-22T05:41:44.090+0100
7f184ce82700 10 monclient: tick
-3> 2024-06-22T05:41:44.090+0100
7f184ce82700 10 monclient: _check_auth_rotating
have uptodate secrets (they expire after
2024-06-22T05:41:14.091638+0100)
-2> 2024-06-22T05:41:44.210+0100
7f1849e7c700 2 mds.0.cache Memory usage:
total 588368, rss 308304, heap 207132, baseline
182556, 0 / 15149 inodes have caps, 0 caps, 0
caps per inode
-1> 2024-06-22T05:41:44.642+0100
7f1846675700 -1
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.2.7/rpm/el8/BUILD/ceph-17.2.7/src/include/interval_set.h:
In function 'void interval_set<T, C>::erase(T,
T, std::function<bool(T, T)>) [with T =
inodeno_t; C = std::map]' thread 7f1846675700
time 2024-06-22T05:41:44.643146+0100
ceph version 17.2.7
(b12291d110049b2f35e32e0de30d70e9a4c060d2)
quincy (stable)
1: (ceph::__ceph_assert_fail(char const*, char
const*, int, char const*)+0x135) [0x7f18568b64a3]
2:
/usr/lib64/ceph/libceph-common.so.2(+0x269669)
[0x7f18568b6669]
3: (interval_set<inodeno_t,
std::map>::erase(inodeno_t, inodeno_t,
std::function<bool (inodeno_t,
inodeno_t)>)+0x2e5) [0x5592e5027885]
4: (EMetaBlob::replay(MDSRank*, LogSegment*,
int, MDPeerUpdate*)+0x4377) [0x5592e532c7b7]
5: (EUpdate::replay(MDSRank*)+0x61)
[0x5592e5330bd1]
6: (MDLog::_replay_thread()+0x7bb)
[0x5592e52b754b]
7: (MDLog::ReplayThread::entry()+0x11)
[0x5592e4f6a041]
8: /lib64/libpthread.so.0(+0x81ca)
[0x7f18558a41ca]
9: clone()
0> 2024-06-22T05:41:44.643+0100
7f1846675700 -1 *** Caught signal (Aborted) **
in thread 7f1846675700 thread_name:md_log_replay
ceph version 17.2.7
(b12291d110049b2f35e32e0de30d70e9a4c060d2)
quincy (stable)
1: /lib64/libpthread.so.0(+0x12cf0)
[0x7f18558aecf0]
2: gsignal()
3: abort()
4: (ceph::__ceph_assert_fail(char const*, char
const*, int, char const*)+0x18f) [0x7f18568b64fd]
5:
/usr/lib64/ceph/libceph-common.so.2(+0x269669)
[0x7f18568b6669]
6: (interval_set<inodeno_t,
std::map>::erase(inodeno_t, inodeno_t,
std::function<bool (inodeno_t,
inodeno_t)>)+0x2e5) [0x5592e5027885]
7: (EMetaBlob::replay(MDSRank*, LogSegment*,
int, MDPeerUpdate*)+0x4377) [0x5592e532c7b7]
8: (EUpdate::replay(MDSRank*)+0x61)
[0x5592e5330bd1]
9: (MDLog::_replay_thread()+0x7bb)
[0x5592e52b754b]
10: (MDLog::ReplayThread::entry()+0x11)
[0x5592e4f6a041]
11: /lib64/libpthread.so.0(+0x81ca)
[0x7f18558a41ca]
12: clone()
We have a relatively low debug setting normally so
I don't think many details of the initial crash
were captured unfortunately and the MDS logs before
the above (i.e. "-60" and older) are just beacon
messages and _check_auth_rotating checks.
I was wondering whether you have any
recommendations in terms of what actions we could
take to bring our filesystem back into a working
state short of rebuilding the entire metadata pool?
We are quite keen to bring our backup back into
service urgently as we currently do not have any
accessible backups for our Ceph clusters.
Kindest regards,
Ivan
On 25/06/2024 19:18, Dhairya Parmar wrote:
CAUTION: This email originated from outside of the
LMB:
*.-dparmar@xxxxxxxxxx-.*
Do not click links or open attachments unless you
recognize the sender and know the content is safe.
If you think this is a phishing email, please
forward it to phishing@xxxxxxxxxxxxxxxxx
--
On Tue, Jun 25, 2024 at 6:38 PM Ivan Clayson
<ivan@xxxxxxxxxxxxxxxxx> wrote:
Hi Dhairya,
Thank you for your rapid reply. I tried
recovering the dentries for the file just
before the crash I mentioned before and then
splicing the transactions from the journal
which seemed to remove that issue for that
inode but resulted in the MDS crashing on the
next inode in the journal when performing replay.
The MDS delegates a range of preallocated inodes
(in form of a set - interval_set<inodeno_t>
preallocated_inos) to the clients, so it can be
one inode that is untracked or some inodes from
the range or in worst case scenario - ALL, and
this is something that even the
`cephfs-journal-tool` would not be able to tell
(since we're talking about MDS internals which
aren't exposed to such tools). That is the reason
why you see "MDS crashing on the next inode in the
journal when performing replay".
An option could be to expose the inode set to some
tool or asok cmd to identify such inodes ranges,
which needs to be discussed. For now, we're trying
to address this in [0], you can follow the
discussion there.
[0] https://tracker.ceph.com/issues/66251
Removing all the transactions involving the
directory housing the files that seemed to
cause these crashes from the journal only
caused the MDS to fail to even start replay.
I've rolled back our journal to our original
version when the crash first happened and the
entire MDS log for the crash can be found
here:
https://www.mrc-lmb.cam.ac.uk/scicomp/data/uploads/ceph/ceph-mds.pebbles-s3.flush_journal.log-25-06-24
Awesome, this would help us a ton. Apart from
this, would it be possible to send us client logs?
Please let us know if you would like any other
logs file as we can easily induce this crash.
Since you can easily induce the crash, can you
share the reproducer please i.e. what all action
you take in order to hit this?
Kindest regards,
Ivan
On 25/06/2024 09:58, Dhairya Parmar wrote:
CAUTION: This email originated from outside
of the LMB:
*.-dparmar@xxxxxxxxxx-.*
Do not click links or open attachments unless
you recognize the sender and know the content
is safe.
If you think this is a phishing email, please
forward it to phishing@xxxxxxxxxxxxxxxxx
--
Hi Ivan,
This looks to be similar to the issue [0]
that we're already addressing at [1]. So
basically there is some out-of-sync event
that led the client to make use of the inodes
that MDS wasn't aware of/isn't tracking and
hence the crash. It'd be really helpful if
you can provide us more logs.
CC @Rishabh Dave <mailto:ridave@xxxxxxxxxx>
@Venky Shankar <mailto:vshankar@xxxxxxxxxx>
@Patrick Donnelly
<mailto:pdonnell@xxxxxxxxxx> @Xiubo Li
<mailto:xiubli@xxxxxxxxxx>
[0] https://tracker.ceph.com/issues/61009
[1] https://tracker.ceph.com/issues/66251
--
***Dhairya Parmar*
Associate Software Engineer, CephFS
<https://www.redhat.com/>IBM, Inc.
On Mon, Jun 24, 2024 at 8:54 PM Ivan Clayson
<ivan@xxxxxxxxxxxxxxxxx> wrote:
Hello,
We have been experiencing a serious issue
with our CephFS backup cluster
running quincy (version 17.2.7) on a
RHEL8-derivative Linux kernel
(Alma8.9, 4.18.0-513.9.1 kernel) where
our MDSes for our filesystem are
constantly in a "replay" or
"replay(laggy)" state and keep crashing.
We have a single MDS filesystem called
"ceph_backup" with 2 standby
MDSes along with a 2nd unused filesystem
"ceph_archive" (this holds
little to no data) where we are using our
"ceph_backup" filesystem to
backup our data and this is the one which
is currently broken. The Ceph
health outputs currently are:
root@pebbles-s1 14:05 [~]: ceph -s
cluster:
id:
e3f7535e-d35f-4a5d-88f0-a1e97abcd631
health: HEALTH_WARN
1 filesystem is degraded
insufficient standby MDS daemons available
1319 pgs not deep-scrubbed in time
1054 pgs not scrubbed in time
services:
mon: 4 daemons, quorum
pebbles-s1,pebbles-s2,pebbles-s3,pebbles-s4
(age 36m)
mgr: pebbles-s2(active, since
36m), standbys: pebbles-s4,
pebbles-s3, pebbles-s1
mds: 2/2 daemons up
osd: 1380 osds: 1380 up (since
29m), 1379 in (since 3d); 37
remapped pgs
data:
volumes: 1/2 healthy, 1 recovering
pools: 7 pools, 2177 pgs
objects: 3.55G objects, 7.0 PiB
usage: 8.9 PiB used, 14 PiB / 23
PiB avail
pgs: 83133528/30006841533
objects misplaced (0.277%)
2090 active+clean
47 active+clean+scrubbing+deep
29 active+remapped+backfilling
8 active+remapped+backfill_wait
2 active+clean+scrubbing
1 active+clean+snaptrim
io:
recovery: 1.9 GiB/s, 719 objects/s
root@pebbles-s1 14:09 [~]: ceph fs status
ceph_backup - 0 clients
===========
RANK STATE MDS ACTIVITY DNS INOS
DIRS CAPS
0 replay(laggy) pebbles-s3 0 0
0 0
POOL TYPE USED AVAIL
mds_backup_fs metadata 1255G 2780G
ec82_primary_fs_data data 0 2780G
ec82pool data 8442T 3044T
ceph_archive - 2 clients
============
RANK STATE MDS ACTIVITY DNS INOS
DIRS CAPS
0 active pebbles-s2 Reqs: 0
/s 13.4k 7105 118 2
POOL TYPE USED AVAIL
mds_archive_fs metadata 5184M 2780G
ec83_primary_fs_data data 0 2780G
ec83pool data 138T 2767T
MDS version: ceph version 17.2.7
(b12291d110049b2f35e32e0de30d70e9a4c060d2)
quincy (stable)
root@pebbles-s1 14:09 [~]: ceph health
detail | head
HEALTH_WARN 1 filesystem is degraded;
insufficient standby MDS
daemons available; 1319 pgs not
deep-scrubbed in time; 1054 pgs not
scrubbed in time
[WRN] FS_DEGRADED: 1 filesystem is
degraded
fs ceph_backup is degraded
[WRN] MDS_INSUFFICIENT_STANDBY:
insufficient standby MDS daemons
available
have 0; want 1 more
When our cluster first ran after a
reboot, Ceph ran through the 2
standby MDSes, crashing them all, until
it reached the final MDS and is
now stuck in this "replay(laggy)" state.
Putting our MDSes into
debugging mode, we can see that this MDS
crashed when replaying the
journal for a particular inode (this is
the same for all the MDSes and
they all crash on the same object):
...
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay for [521,head] had
[inode 0x1005ba89481
[...539,head]
/cephfs-users/afellows/Ferdos/20210625_real_DDFHFKLMT_KriosIII_K3/cryolo/test_micrographs/
auth fragtree_t(*^2 00*^3 00000*^
4 00001*^3 00010*^4 00011*^4 00100*^4
00101*^4 00110*^4 00111*^4
01*^3 01000*^4 01001*^3 01010*^4
01011*^3 01100*^4 01101*^4 01110*^4
01111*^4 10*^3 10000*^4 10001*^4
10010*^4 10011*^4 10100*^4 10101*^3
10110*^4 10111*^4 11*^6) v10880645
f(v0 m2024-06-22
T05:41:10.213700+0100 1281276=1281276+0)
n(v12
rc2024-06-22T05:41:10.213700+0100
b1348251683896 1281277=1281276+1)
old_inodes=8 (iversion lock) |
dirfrag=416 dirty=1 0x55770a2bdb80]
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay dir 0x1005ba89481.011011000*
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay updated dir [dir
0x1005ba89481.011011000*
/cephfs-users/afellows/Ferdos/20210625_real_DDFHFKLMT_KriosIII_K3/cryolo/test_micrographs/
[2,head] auth v=436385 cv=0/0
state=107374182
4 f(v0
m2024-06-22T05:41:10.213700+0100
2502=2502+0) n(v12
rc2024-06-22T05:41:10.213700+0100
b2120744220 2502=2502+0)
hs=32+33,ss=0+0 dirty=65 | child=1
0x55770ebcda80]
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay added (full) [dentry
#0x1/cephfs-users/afellows/Ferdos/20210625_real_DDFHFKLMT_KriosIII_K3/cryolo/test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_005006_fracti
ons_ave_Z124.mrc.teberet7.partial
[539,head] auth NULL (dversion
lock) v=436384 ino=(nil)
state=1610612800|bottomlru | dirty=1
0x557710444500]
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay added [inode
0x1005cd4fe35 [539,head]
/cephfs-users/afellows/Ferdos/20210625_real_DDFHFKLMT_KriosIII_K3/cryolo/test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_
005006_fractions_ave_Z124.mrc.teberet7.partial
auth v436384 s=0 n(v0
1=1+0) (iversion lock)
cr={99995144=0-4194304@538} 0x557710438680]
2024-06-24T13:44:55.563+0100 7f8811c40700 10
mds.0.cache.ino(0x1005cd4fe35)
mark_dirty_parent
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay noting opened inode
[inode 0x1005cd4fe35 [539,head]
/cephfs-users/afellows/Ferdos/20210625_real_DDFHFKLMT_KriosIII_K3/cryolo/test_micrographs/FoilHole_27649821_Data_27626128_2762
6130_20210628_005006_fractions_ave_Z124.mrc.teberet7.partial
auth
v436384 DIRTYPARENT s=0 n(v0 1=1+0)
(iversion lock)
cr={99995144=0-4194304@538} |
dirtyparent=1 dirty=1 0x557710438680]
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay inotable tablev 3112837
<= table 3112837
2024-06-24T13:44:55.563+0100 7f8811c40700
10 mds.0.journal
EMetaBlob.replay sessionmap v 1560540883,
table 1560540882 prealloc
[] used 0x1005cd4fe35
2024-06-24T13:44:55.563+0100 7f8811c40700 -1
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.2.7/rpm/el8/BUILD/ceph-17.2.7/src/include/interval_set.h:
I
n function 'void interval_set<T,
C>::erase(T, T,
std::function<bool(T, T)>) [with T =
inodeno_t; C = std::map]'
thread 7f8811c40700 time
2024-06-24T13:44:55.564315+0100
/home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/17.2.7/rpm/el8/BUILD/ceph-17.2.7/src/include/interval_set.h:
568: FAILED ceph_assert(p->first <=
start)
ceph version 17.2.7
(b12291d110049b2f35e32e0de30d70e9a4c060d2)
quincy (stable)
1: (ceph::__ceph_assert_fail(char
const*, char const*, int, char
const*)+0x135) [0x7f8821e814a3]
2:
/usr/lib64/ceph/libceph-common.so.2(+0x269669)
[0x7f8821e81669]
3: (interval_set<inodeno_t,
std::map>::erase(inodeno_t, inodeno_t,
std::function<bool (inodeno_t,
inodeno_t)>)+0x2e5) [0x5576f9bb2885]
4: (EMetaBlob::replay(MDSRank*,
LogSegment*, int,
MDPeerUpdate*)+0x4377) [0x5576f9eb77b7]
5: (EUpdate::replay(MDSRank*)+0x61)
[0x5576f9ebbbd1]
6: (MDLog::_replay_thread()+0x7bb)
[0x5576f9e4254b]
7:
(MDLog::ReplayThread::entry()+0x11)
[0x5576f9af5041]
8: /lib64/libpthread.so.0(+0x81ca)
[0x7f8820e6f1ca]
9: clone()
I've only included a short section of the
crash (this is the first trace
in the log with regards to the crash with
a 10/20 debug_mds option). We
tried deleting the 0x1005cd4fe35 object
from the object store using the
"rados" command but this did not allow
our MDS to successfully replay.
From my understanding the journal seems
okay as we didn't run out of
space for example on our metadata pool
and "cephfs-journal-tool journal
inspect" doesn't seem to think there is
any damage:
root@pebbles-s1 13:58 [~]:
cephfs-journal-tool --rank=ceph_backup:0
journal inspect
Overall journal integrity: OK
root@pebbles-s1 14:04 [~]:
cephfs-journal-tool --rank=ceph_backup:0
event get --inode 1101069090357 summary
Events by type:
OPEN: 1
UPDATE: 3
Errors: 0
root@pebbles-s1 14:05 [~]:
cephfs-journal-tool --rank=ceph_backup:0
event get --inode 1101069090357 list
2024-06-22T05:41:10.214635+0100
0x51f97d4cfe35 UPDATE: (openc)
test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_005006_fractions_ave_Z124.mrc.teberet7.partial
2024-06-22T05:41:11.203312+0100
0x51f97d59c848 UPDATE:
(check_inode_max_size)
test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_005006_fractions_ave_Z124.mrc.teberet7.partial
test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_005006_fractions_ave_Z124.mrc.teberet7.partial
2024-06-22T05:41:15.484871+0100
0x51f97e7344cc OPEN: ()
FoilHole_27649821_Data_27626128_27626130_20210628_005006_fractions_ave_Z124.mrc.teberet7.partial
2024-06-22T05:41:15.484921+0100
0x51f97e73493b UPDATE: (rename)
test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_005006_fractions_ave_Z124.mrc.teberet7.partial
test_micrographs/FoilHole_27649821_Data_27626128_27626130_20210628_005006_fractions_ave_Z124.mrc
I was wondering whether anyone had any
advice for us on how we should
proceed forward? We were thinking about
manually applying these events
(via "event apply") where failing that we
could erase this problematic
event with "cephfs-journal-tool
--rank=ceph_backup:0 event splice
--inode 1101069090357". Is this a good
idea? We would rather not rebuild
the entire metadata pool if we could
avoid it (once was enough for us)
as this cluster has ~9 PB of data on it.
Kindest regards,
Ivan Clayson
--
Ivan Clayson
-----------------
Scientific Computing Officer
Room 2N249
Structural Studies
MRC Laboratory of Molecular Biology
Francis Crick Ave, Cambridge
CB2 0QH
_______________________________________________
ceph-users mailing list -- ceph-users@xxxxxxx
To unsubscribe send an email to
ceph-users-leave@xxxxxxx
--
Ivan Clayson
-----------------
Scientific Computing Officer
Room 2N249
Structural Studies
MRC Laboratory of Molecular Biology
Francis Crick Ave, Cambridge
CB2 0QH
--
Ivan Clayson
-----------------
Scientific Computing Officer
Room 2N249
Structural Studies
MRC Laboratory of Molecular Biology
Francis Crick Ave, Cambridge
CB2 0QH
--
Ivan Clayson
-----------------
Scientific Computing Officer
Room 2N249
Structural Studies
MRC Laboratory of Molecular Biology
Francis Crick Ave, Cambridge
CB2 0QH
--
Ivan Clayson
-----------------
Scientific Computing Officer
Room 2N249
Structural Studies
MRC Laboratory of Molecular Biology
Francis Crick Ave, Cambridge
CB2 0QH
