8 Nov
2019
8 Nov
'19
8:10 p.m.
-----Original message-----
From: Yan, Zheng <ukernel(a)gmail.com>
Sent: Thu 07-11-2019 14:20
Subject: Re: [ceph-users] Re: mds crash loop
To: Karsten Nielsen <karsten(a)foo-bar.dk>dk>;
CC: ceph-users(a)ceph.io;
On Thu, Nov 7, 2019 at 6:40 PM Karsten Nielsen
<karsten(a)foo-bar.dk> wrote:
I got this output from that command.
2019-11-08 14:27:53.110 7f0bda092700 1 mds.k8s-node-01 asok_command: scrub_path
(starting...)
2019-11-08 14:27:53.110 7f0bda092700 1 mds.k8s-node-01 asok_command: scrub_path
(complete)
2019-11-08 14:27:55.794 7f0bd2dfa700 0 log_channel(cluster) log [WRN] : bad backtrace on
inode 0x100013a3156(/missing_obj_dirs/mail), rewriting it
2019-11-08 14:27:55.794 7f0bd2dfa700 0 log_channel(cluster) log [INF] : Scrub repaired
inode 0x100013a3156 (/missing_obj_dirs/mail)
2019-11-08 14:27:55.794 7f0bd2dfa700 -1 mds.0.scrubstack _validate_inode_done scrub error
on inode [inode 0x100013a3156 [...2,head] /missing_obj_dirs/mail/ auth v77565 dirtyparent
f(v0 m2019-11-07 10:10:35.293698 12=3+9) n(v52 rc2019-11-08 14:08:21.585140 b21180195
2561=1820+741) (inest lock dirty) (ifile excl) (iversion lock)
caps={1793815=pAsXsFs/-@5},l=1793815 | dirtyscattered=1 request=0 lock=0 dirfrag=1 caps=1
dirtyrstat=0 dirtyparent=1 scrubqueue=0 dirty=1 waiter=0 authpin=0 0x55d4dc882300]:
{"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":-61,"ondisk_value":"(-1)0x0:[]//","memoryvalue":"(6)0x100013a3156:[<0x100026d3cff/mail
v77565>,<0x1/missing_obj_dirs
v3025317>]//","error_str":"failed to read off disk; see
retval"},"raw_stats":{"checked":true,"passed":true,"read_ret_val":0,"ondisk_value.dirstat":"f(v0
m2019-11-07 10:10:35.293698 12=3+9)","ondisk_value.rstat":"n(v0
rc2019-11-07 1
0:10:38.061742 b21180195
2561=1820+741)","memory_value.dirrstat":"f(v0 m2019-11-07
10:10:35.293698 12=3+9)","memory_value.rstat":"n(v52 rc2019-11-08
14:08:21.585140 b21180195
2561=1820+741)","error_str":""},"return_code":-61}
2019-11-08 14:27:55.794 7f0bd2dfa700 0 log_channel(cluster) log [WRN] : bad backtrace on
inode 0x100013950d6(/missing_obj_dirs/empty_templates), rewriting it
2019-11-08 14:27:55.794 7f0bd2dfa700 0 log_channel(cluster) log [INF] : Scrub repaired
inode 0x100013950d6 (/missing_obj_dirs/empty_templates)
2019-11-08 14:27:55.794 7f0bd2dfa700 -1 mds.0.scrubstack _validate_inode_done scrub error
on inode [inode 0x100013950d6 [...2,head] /missing_obj_dirs/empty_templates/ auth v77569
ap=2+0 dirtyparent f(v0 m2019-09-17 19:13:12.226251 3=3+0) n(v0 rc2019-11-08
14:09:01.450030 b29712 4=3+1) (inest lock) (ifile sync->lock) (iversion lock)
caps={1793815=pAsXs/pAsXsFs/-@4,1804200=pAsLsXs/pAsLsXsFs/AsLsXsFsx@31} | request=1 lock=0
dirfrag=0 caps=1 dirtyparent=1 scrubqueue=0 dirty=1 waiter=1 authpin=1 0x55d4ee870000]:
{"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":-2,"ondisk_value":"(-1)0x0:[]//","memoryvalue":"(6)0x100013950d6:[<0x100026d3cff/empty_templates
v77569>,<0x1/missing_obj_dirs
v3025317>]//","error_str":"failed to decode on-disk backtrace (0
bytes)!"},"raw_stats":{"checked":true,"passed":false,"read_ret_val":0,"ondisk_value.dirstat":"f()","ondisk_value.rstat":"n(v0
1=0+1)","memory_value.
dirrstat":"f(v0 m2019-09-17 19:13:12.226251
3=3+0)","memory_value.rstat":"n(v0 rc2019-11-08 14:09:01.450030 b29712
4=3+1)","error_str":"freshly-calculated rstats don't match
existing ones (will be fixed)"},"return_code":-2}
2019-11-08 14:27:56.114 7f0bd2dfa700 0 log_channel(cluster) log [WRN] : bad backtrace on
inode 0x100013abb3c(/missing_obj_dirs/passwords), rewriting it
2019-11-08 14:27:56.114 7f0bd2dfa700 0 log_channel(cluster) log [INF] : Scrub repaired
inode 0x100013abb3c (/missing_obj_dirs/passwords)
2019-11-08 14:27:56.114 7f0bd2dfa700 -1 mds.0.scrubstack _validate_inode_done scrub error
on inode [inode 0x100013abb3c [...2,head] /missing_obj_dirs/passwords/ auth v77567
dirtyparent f(v0 m2019-11-07 10:03:19.194734 8=1+7) n(v20 rc2019-11-08 14:08:30.565341
b5715351 413=349+64) (inest lock) (ifile excl) (iversion lock)
caps={1793815=pAsXsFs/-@6},l=1793815 | dirtyscattered=0 request=0 lock=0 dirfrag=1 caps=1
dirtyrstat=0 dirtyparent=1 scrubqueue=0 dirty=1 waiter=0 authpin=0 0x55d4dc880000]:
{"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":-61,"ondisk_value":"(-1)0x0:[]//","memoryvalue":"(6)0x100013abb3c:[<0x100026d3cff/passwords
v77567>,<0x1/missing_obj_dirs
v3025512>]//","error_str":"failed to read off disk; see
retval"},"raw_stats":{"checked":true,"passed":true,"read_ret_val":0,"ondisk_value.dirstat":"f(v0
m2019-11-07 10:03:19.194734 8=1+7)","ondisk_value.rstat":"n(v0
rc2019-11-07 10:
03:24.178813 b5715351 413=349+64)","memory_value.dirrstat":"f(v0
m2019-11-07 10:03:19.194734 8=1+7)","memory_value.rstat":"n(v20
rc2019-11-08 14:08:30.565341 b5715351
413=349+64)","error_str":""},"return_code":-61}
2019-11-08 14:27:56.254 7f0bd2dfa700 0 log_channel(cluster) log [WRN] : bad backtrace on
inode 0x100013a2659(/missing_obj_dirs/richdocuments), rewriting it
2019-11-08 14:27:56.254 7f0bd2dfa700 0 log_channel(cluster) log [INF] : Scrub repaired
inode 0x100013a2659 (/missing_obj_dirs/richdocuments)
2019-11-08 14:27:56.254 7f0bd2dfa700 -1 mds.0.scrubstack _validate_inode_done scrub error
on inode [inode 0x100013a2659 [...2,head] /missing_obj_dirs/richdocuments/ auth v77561
dirtyparent f(v0 m2019-11-07 14:54:47.223440 19=9+10) n(v30 rc2019-11-08 14:08:03.876745
b3205323 261=241+20) (inest lock) (ifile excl) (iversion lock)
caps={1793815=pAsXsFs/-@3},l=1793815 | dirtyscattered=0 request=0 lock=0 dirfrag=1 caps=1
dirtyrstat=0 dirtyparent=1 scrubqueue=0 dirty=1 waiter=0 authpin=0 0x55d4dc87e300]:
{"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":-61,"ondisk_value":"(-1)0x0:[]//","memoryvalue":"(6)0x100013a2659:[<0x100026d3cff/richdocuments
v77561>,<0x1/missing_obj_dirs
v3025512>]//","error_str":"failed to read off disk; see
retval"},"raw_stats":{"checked":true,"passed":true,"read_ret_val":0,"ondisk_value.dirstat":"f(v0
m2019-11-07 14:54:47.223440 19=9+10)","ondisk_value.rstat":"n(v0 rc20
19-11-07 14:54:47.223440 b3205323
261=241+20)","memory_value.dirrstat":"f(v0 m2019-11-07 14:54:47.223440
19=9+10)","memory_value.rstat":"n(v30 rc2019-11-08 14:08:03.876745
b3205323
261=241+20)","error_str":""},"return_code":-61}
2019-11-08 14:27:56.254 7f0bd2dfa700 0 log_channel(cluster) log [WRN] : bad backtrace on
inode 0x100013acfcb(/missing_obj_dirs/carnet), rewriting it
2019-11-08 14:27:56.254 7f0bd2dfa700 0 log_channel(cluster) log [INF] : Scrub repaired
inode 0x100013acfcb (/missing_obj_dirs/carnet)
2019-11-08 14:27:56.254 7f0bd2dfa700 -1 mds.0.scrubstack _validate_inode_done scrub error
on inode [inode 0x100013acfcb [...2,head] /missing_obj_dirs/carnet/ auth v77563 ap=2+0
dirtyparent f(v0 m2019-10-21 11:03:29.113564 20=11+9) n(v31 rc2019-11-08 14:08:09.480870
b12005493 1999=1656+343) (inest lock) (ifile sync->lock) (iversion lock)
caps={1793815=pAsXs/pAsXsFs/-@4,1794668=pAsXs/pAsXsFs/-@108394} | request=1 lock=0
dirfrag=0 caps=1 dirtyparent=1 scrubqueue=0 dirty=1 waiter=1 authpin=1 0x55d4dc889800]:
{"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":-2,"ondisk_value":"(-1)0x0:[]//","memoryvalue":"(6)0x100013acfcb:[<0x100026d3cff/carnet
v77563>,<0x1/missing_obj_dirs
v3025512>]//","error_str":"failed to decode on-disk backtrace (0
bytes)!"},"raw_stats":{"checked":true,"passed":false,"read_ret_val":0,"ondisk_value.dirstat":"f()","ondisk_value.rstat":"n(v0
1=0+1)","memory_value.dirrstat":"f
(v0 m2019-10-21 11:03:29.113564 20=11+9)","memory_value.rstat":"n(v31
rc2019-11-08 14:08:09.480870 b12005493
1999=1656+343)","error_str":"freshly-calculated rstats don't match
existing ones (will be fixed)"},"return_code":-2}
2019-11-08 14:27:56.258 7f0bd2dfa700 0 log_channel(cluster) log [WRN] : bad backtrace on
inode 0x100026d3cff(/missing_obj_dirs), rewriting it
2019-11-08 14:27:56.258 7f0bd2dfa700 0 log_channel(cluster) log [INF] : Scrub repaired
inode 0x100026d3cff (/missing_obj_dirs)
2019-11-08 14:27:56.258 7f0bd2dfa700 -1 mds.0.scrubstack _validate_inode_done scrub error
on inode [inode 0x100026d3cff [...2,head] /missing_obj_dirs/ auth v3025512 pv3025514
ap=1+1 dirtyparent f(v0 m2019-11-08 14:09:01.450030 5=0+5) n(v0 rc2019-11-08
14:09:01.450030 b42106362 5236=4066+1170) (inest lock w=1) (ifile excl) (iversion lock
w=1) caps={1793815=pAsLsXsFsx/AsLsXsFsx@7},l=1793815 | request=0 lock=2 dirfrag=1 caps=1
dirtyparent=1 scrubqueue=1 dirty=1 authpin=1 0x55d4ede56700]:
{"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":-2,"ondisk_value":"(-1)0x0:[]//","memoryvalue":"(6)0x100026d3cff:[<0x1/missing_obj_dirs
v3025512>]//","error_str":"failed to decode on-disk backtrace (0
bytes)!"},"raw_stats":{"checked":true,"passed":true,"read_ret_val":0,"ondisk_value.dirstat":"f(v0
m2019-11-08 14:09:01.450030 5=0+5)","ondisk_value.rstat":"n(v0
rc2019-11-08 14:09:01.450030 b42106362 5236=4
066+1170)","memory_value.dirrstat":"f(v0 m2019-11-08 14:09:01.450030
5=0+5)","memory_value.rstat":"n(v0 rc2019-11-08 14:09:01.450030
b42106362
5236=4066+1170)","error_str":""},"return_code":-2}
2019-11-08 14:27:56.258 7f0bd2dfa700 0 log_channel(cluster) log [INF] : scrub complete
I am not sure what to read out of that. Other than data seems to be missing.
>
> > Any tool that is able to do that ?
> >
> > Thanks
> > - Karsten
> >
> > -----Original message-----
> > From: Yan, Zheng <ukernel(a)gmail.com>
> > Sent: Thu 07-11-2019 09:22
> > Subject: Re: [ceph-users] Re: mds crash loop
> > To: Karsten Nielsen <karsten(a)foo-bar.dk>dk>;
> > CC: ceph-users(a)ceph.io;
> > > I have tracked down the root cause. See
> https://tracker.ceph.com/issues/42675
> > >
> > > Regards
> > > Yan, Zheng
> > >
> > > On Thu, Nov 7, 2019 at 4:01 PM Karsten Nielsen <karsten(a)foo-bar.dk>
wrote:
> > > >
> > > > -----Original message-----
> > > > From: Yan, Zheng <ukernel(a)gmail.com>
> > > > Sent: Thu 07-11-2019 07:21
> > > > Subject: Re: [ceph-users] Re: mds crash loop
> > > > To: Karsten Nielsen <karsten(a)foo-bar.dk>dk>;
> > > > CC: ceph-users(a)ceph.io;
> > > > > On Thu, Nov 7, 2019 at 5:50 AM Karsten Nielsen
<karsten(a)foo-bar.dk>
> wrote:
> > > > > >
> > > > > > -----Original message-----
> > > > > > From: Yan, Zheng <ukernel(a)gmail.com>
> > > > > > Sent: Wed 06-11-2019 14:16
> > > > > > Subject: Re: [ceph-users] mds crash loop
> > > > > > To: Karsten Nielsen <karsten(a)foo-bar.dk>dk>;
> > > > > > CC: ceph-users(a)ceph.io;
> > > > > > > On Wed, Nov 6, 2019 at 4:42 PM Karsten Nielsen
<karsten(a)foo-bar.dk>
> > > wrote:
> > > > > > > >
> > > > > > > > -----Original message-----
> > > > > > > > From: Yan, Zheng <ukernel(a)gmail.com>
> > > > > > > > Sent: Wed 06-11-2019 08:15
> > > > > > > > Subject: Re: [ceph-users] mds crash loop
> > > > > > > > To: Karsten Nielsen
<karsten(a)foo-bar.dk>dk>;
> > > > > > > > CC: ceph-users(a)ceph.io;
> > > > > > > > > On Tue, Nov 5, 2019 at 5:29 PM Karsten
Nielsen
> <karsten(a)foo-bar.dk>
> > > > > wrote:
> > > > > > > > > >
> > > > > > > > > > Hi,
> > > > > > > > > >
> > > > > > > > > > Last week I upgraded my ceph cluster
from luminus to mimic
> 13.2.6
> > > > > > > > > > It was running fine for a while but
yesterday my mds went
> into a
> > > crash
> > > > > > > loop.
> > > > > > > > > >
> > > > > > > > > > I have 1 active and 1 standby mds for my
cephfs both of which
> is
> > > > > running
> > > > > > > the
> > > > > > > > > same crash loop.
> > > > > > > > > > I am running ceph based on
> https://hub.docker.com/r/ceph/daemon
> > > > > version
> > > > > > > > > v3.2.7-stable-3.2-minic-centos-7-x86_64 with
a etcd kv store.
> > > > > > > > > >
> > > > > > > > > > Log details are:
https://paste.debian.net/1113943/
> > > > > > > > > >
> > > > > > > > >
> > > > > > > > > please try again with debug_mds=20. Thanks
> > > > > > > > >
> > > > > > > > > Yan, Zheng
> > > > > > > >
> > > > > > > > Yes I have set that and had to move to
pastebin.com as debian
> > > apperently
> > > > > only
> > > > > > > supports 150k
> > > > > > > >
> > > > > > > >
> > > > > > > > https://pastebin.com/Gv7c5h54
> > > > > > > >
> > > > > > >
> > > > > > > Looks like on-disk root inode is corrupted. have you
encountered any
> > > > > > > unusually things during the upgrade?
> > > > > > >
> > > > > > > please run 'rados -p <cephfs metadata pool>
stat 1.00000000.inode' ,
> > > > > > > check if the object is modified before or after the
'luminous ->
> > > > > > > 13.2.6' upgrade.
> > > > > > > To fix the corrupted object. Run
'cephfs-data-scan init
> > > > > > > --force-init'. Then restart mds. After mds become
active, run 'ceph
> > > > > > > daemon mds.x scrub_path / force repair'
> > > > > > >
> > > > > >
> > > > > > I followed the steps I got the mds started but now a lot of
files are
> in
> > > > > lost+found 24283 and I have these errors in the mds log
> > > > > >
> > > > > 'cephfs-data-scan init --force-init' does not move files
into
> > > > > lost+found. have you ever run other 'cephfs-data-scan
foo' command or
> > > > > 'cephfs-journal-tool foo' command?
> > > >
> > > > I have had a similar problem with the cluster before where I went
through
> the
> > > cycle of:
> > > > https://docs.ceph.com/docs/mimic/cephfs/disaster-recovery/ -> Using
an
> > > alternate metadata pool for recovery
> > > >
> > > > I did run the cephfs-journal-tool journal reset command, mostly
because
> > > cephfs is not that utilized so I thought it was safe to do as after the
> upgrade
> > > the cluster has not been used much, so data lose would be minimal -
> apparently
> > > I was wrong.
> > > >
> > > > >
> > > > > > 2019-11-06 20:20:18.215 7f0bd9090700 1 mds.0.32011 cluster
recovered.
> > > > > > 2019-11-06 20:20:19.019 7f0bd2dfa700 0
mds.0.cache.dir(0x100013acfcb)
> > > > > _fetched missing object for [dir 0x100013acfcb
> > > /nextcloud/custom_apps/carnet/
> > > > > [2,head] auth v=0 cv=0/0 ap=1+0+0 state=1073741888|fetching f()
n()
> > > > > hs=0+0,ss=0+0 | waiter=1 authpin=1 0x55d4dc4f5100]
> > > > > > 2019-11-06 20:20:19.019 7f0bd2dfa700 -1 log_channel(cluster)
log
> [ERR] :
> > > dir
> > > > > 0x100013acfcb object missing on disk; some files may be lost
> > > > > (/nextcloud/custom_apps/carnet)
> > > > > > 2019-11-06 20:20:19.275 7f0bd2dfa700 0
mds.0.cache.dir(0x100013a3156)
> > > > > _fetched missing object for [dir 0x100013a3156
> /nextcloud/custom_apps/mail/
> > > > > [2,head] auth v=0 cv=0/0 ap=1+0+0 state=1073741888|fetching f()
n()
> > > > > hs=0+0,ss=0+0 | waiter=1 authpin=1 0x55d4dcc40000]
> > > > > > 2019-11-06 20:20:19.275 7f0bd2dfa700 -1 log_channel(cluster)
log
> [ERR] :
> > > dir
> > > > > 0x100013a3156 object missing on disk; some files may be lost
> > > > > (/nextcloud/custom_apps/mail)
> > > > > > 2019-11-06 20:20:19.371 7f0bd2dfa700 0
mds.0.cache.dir(0x100013abb3c)
> > > > > _fetched missing object for [dir 0x100013abb3c
> > > > > /nextcloud/custom_apps/passwords/ [2,head] auth v=0 cv=0/0
ap=1+0+0
> > > > > state=1073741888|fetching f() n() hs=0+0,ss=0+0 | waiter=1
authpin=1
> > > > > 0x55d4dcc40700]
> > > > > > 2019-11-06 20:20:19.371 7f0bd2dfa700 -1 log_channel(cluster)
log
> [ERR] :
> > > dir
> > > > > 0x100013abb3c object missing on disk; some files may be lost
> > > > > (/nextcloud/custom_apps/passwords)
> > > > > > 2019-11-06 20:20:19.383 7f0bd2dfa700 0
mds.0.cache.dir(0x100013a9b9b)
> > > > > _fetched missing object for [dir 0x100013a9b9b
> > > > > /nextcloud/custom_apps/phonetrack/ [2,head] auth v=0 cv=0/0
ap=1+0+0
> > > > > state=1073741888|fetching f() n() hs=0+0,ss=0+0 | waiter=1
authpin=1
> > > > > 0x55d4dcc40e00]
> > > > > > 2019-11-06 20:20:19.383 7f0bd2dfa700 -1 log_channel(cluster)
log
> [ERR] :
> > > dir
> > > > > 0x100013a9b9b object missing on disk; some files may be lost
> > > > > (/nextcloud/custom_apps/phonetrack)
> > > > > > 2019-11-06 20:20:19.431 7f0bd2dfa700 0
mds.0.cache.dir(0x100013a2659)
> > > > > _fetched missing object for [dir 0x100013a2659
> > > > > /nextcloud/custom_apps/richdocuments/ [2,head] auth v=0 cv=0/0
ap=1+0+0
> > > > > state=1073741888|fetching f() n() hs=0+0,ss=0+0 | waiter=1
authpin=1
> > > > > 0x55d4dcc41500]
> > > > > > 2019-11-06 20:20:19.431 7f0bd2dfa700 -1 log_channel(cluster)
log
> [ERR] :
> > > dir
> > > > > 0x100013a2659 object missing on disk; some files may be lost
> > > > > (/nextcloud/custom_apps/richdocuments)
> > > > > > 2019-11-06 20:20:22.360 7f0bd9090700 1 mds.k8s-node-01
Updating MDS
> map
> > > to
> > > > > version 32015 from mon.1
> > > > > >
> > > > > >
> > > > > > >
> > > > > > > > - Karsten
> > > > > > > >
> > > > > > > > >
> > > > > > > > > > Thanks for any hints
> > > > > > > > > > - Karsten
> > > > > > > > > >
_______________________________________________
> > > > > > > > > > ceph-users mailing list --
ceph-users(a)ceph.io
> > > > > > > > > > To unsubscribe send an email to
ceph-users-leave(a)ceph.io
> > > > > > > > >
> > > > > > > > >
> > > > > > >
> > > > > > >
> > > > > > _______________________________________________
> > > > > > ceph-users mailing list -- ceph-users(a)ceph.io
> > > > > > To unsubscribe send an email to ceph-users-leave(a)ceph.io
> > > > >
> > > > >
> > > > _______________________________________________
> > > > ceph-users mailing list -- ceph-users(a)ceph.io
> > > > To unsubscribe send an email to ceph-users-leave(a)ceph.io
> > >
> > >
> > _______________________________________________
> > ceph-users mailing list -- ceph-users(a)ceph.io
> > To unsubscribe send an email to ceph-users-leave(a)ceph.io
>
>
That is awesome.
Now I just need to figure out where the lost+found files needs to go.
And what happened to the missing objects for the dirs.
lost+found files are likely files that were deleted. you can keep the
lost+found dir for a while, then delete the 'lost+found' directory.
for 'missing object' dirs, mv all of them to a temp directory, such as
/mnt/cephfs/missing_obj_dirs.
Then run command 'ceph daemon mds.x scrub_patch /missing_obj_dirs
force recursive repair'. wait a minute, the rm -rf
/mnt/cephfs/missing_obj_dirs