Project

General

Profile

Actions
Copy link

Bug #57676

open

qa: error during scrub thrashing: rank damage found: {'backtrace'}

Added by Patrick Donnelly over 1 year ago. Updated 23 days ago.

Status:
Triaged
Priority:
High
Assignee:
Kotresh Hiremath Ravishankar
Category:
Correctness/Safety
Target version:
Ceph - v20.0.0
% Done:

0%

Source:
Q/A
Tags:
Backport:
quincy,reef,squid
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Backtrace scrub failures are back with damage checking in fwd_scrub.py, introduced by

https://github.com/ceph/ceph/pull/46821

See: https://pulpito.ceph.com/pdonnell-2022-09-26_19:11:10-fs-wip-pdonnell-testing-20220923.171109-distro-default-smithi/7044481/

Some past work on this: #48805 and #50976

Related issues 1 (1 open — 0 closed)

Related to CephFS - Bug #64730: fs/misc/multiple_rsync.sh workunit times outTriagedVenky Shankar

Actions
Actions
Copy link
 #1

Updated by Venky Shankar over 1 year ago

  • Category set to Correctness/Safety
  • Status changed from New to Triaged
  • Assignee set to Milind Changire
  • Backport set to pacific,quincy
Actions
Copy link
 #2

Updated by Rishabh Dave 12 months ago

This issue occurred in Pacific run - /ceph/teuthology-archive/yuriw-2023-04-25_19:03:49-fs-wip-yuri5-testing-2023-04-25-0837-pacific-distro-default-smithi/7252936/teuthology.log

2023-04-28T14:59:43.884 ERROR:teuthology.run_tasks:Manager failed: fwd_scrub
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_teuthology_8d156aede5efdae00b53d8d3b8d127082980e7ec/teuthology/run_tasks.py", line 192, in run_tasks
    suppress = manager.__exit__(*exc_info)
  File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
    next(self.gen)
  File "/home/teuthworker/src/github.com_ceph_ceph-c_2cc327ab03de508c4ed32f598c61221f937ffba0/qa/tasks/fwd_scrub.py", line 151, in task
    stop_all_fwd_scrubbers(ctx.ceph[config['cluster']].thrashers)
  File "/home/teuthworker/src/github.com_ceph_ceph-c_2cc327ab03de508c4ed32f598c61221f937ffba0/qa/tasks/fwd_scrub.py", line 86, in stop_all_fwd_scrubbers
    raise RuntimeError(f"error during scrub thrashing: {thrasher.exception}")
RuntimeError: error during scrub thrashing: reached maximum tries (30) after waiting for 900 seconds
Actions
Copy link
 #11

Updated by Patrick Donnelly 7 months ago

  • Target version deleted (v18.0.0)
Actions
Copy link
 #18

Updated by Venky Shankar about 1 month ago

  • Backport changed from pacific,quincy to quincy,reef,squid
Actions
Copy link
 #19

Updated by Venky Shankar 25 days ago

  • Assignee changed from Milind Changire to Kotresh Hiremath Ravishankar
  • Target version set to v20.0.0

Kotersh, please take this one. It would be good to RCA this since this is showing up a lot in our fs suite runs.

Actions
Copy link
 #20

Updated by Venky Shankar 25 days ago

12/54 failures in https://pulpito.ceph.com/teuthology-2024-03-31_21:24:02-fs-squid-distro-default-smithi/ is this issue.

For some reason those numbers have gone up. We need to RCA this asap.

Actions
Copy link
 #21

Updated by Kotresh Hiremath Ravishankar 23 days ago

I looked into the logs from the failure https://pulpito.ceph.com/teuthology-2024-03-31_21:24:02-fs-squid-distro-default-smithi/7633107/

I found that there are lot of files for which the ondisk backtrace version is different from in-memory backtrace version.

e.g., for the file "volumes/qa/sv_0/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b/client.0/tmp/testdir/dir1/dir2/file856"

2024-03-31T22:59:48.806+0000 7fee8508a700 10 MDSContext::complete: 19MDSIOContextWrapper
2024-03-31T22:59:48.806+0000 7fee8508a700 20 mds.3.cache.ino(0x100000012bf) ondisk_read_retval: 0
2024-03-31T22:59:48.806+0000 7fee8508a700 10 mds.3.cache.ino(0x100000012bf) decoded 380 bytes of backtrace successfully
2024-03-31T22:59:48.806+0000 7fee8b897700  1 -- [v2:172.21.15.169:6832/3950852269,v1:172.21.15.169:6833/3950852269] <== client.15501 192.168.0.1:0/2893928180 89 ==== client_caps(update ino 0x10000001929 1554 seq 1 tid 5935 caps=pAsxLsXsxFsxcrwb dirty=AxFx wanted=- follows 2 mseq 1 size 0/4194304 ts 1/18446744073709551615 mtime 2024-03-31T22:59:43.322260+0000 ctime 2024-03-31T22:59:43.323167+0000 change_attr 1 tws 2) ==== 260+0+0 (crc 0 0 0) 0x559a2a474e00 con 0x559a2a24cc00
2024-03-31T22:59:48.806+0000 7fee8508a700 10 mds.3.cache.ino(0x100000012bf) scrub: inotable ino = 0x100000012bf
2024-03-31T22:59:48.806+0000 7fee8508a700 10 mds.3.cache.ino(0x100000012bf) scrub: inotable free says 0
2024-03-31T22:59:48.806+0000 7fee8508a700 10 MDSContext::complete: 16C_InodeValidated
2024-03-31T22:59:48.806+0000 7fee8508a700  0 log_channel(cluster) log [WRN] : Scrub error on inode 0x100000012bf (/volumes/qa/sv_0/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b/client.0/tmp/testdir/dir1/dir2/file856) see mds.l log and `damage ls` output for details
2024-03-31T22:59:48.806+0000 7fee8508a700 -1 mds.3.scrubstack _validate_inode_done scrub error on inode [inode 0x100000012bf [3,head] /volumes/qa/sv_0/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b/client.0/tmp/testdir/dir1/dir2/file856 auth v4429 ap=1 s=0 n(v0 rc2024-03-31T22:59:35.501633+0000 1=1+0) caps={15501=pAsLsXsFs/-@1} | importingcaps=0 caps=1 replicated=0 authpin=1 scrubqueue=0 0x559a2a681b80]: {"performed_validation":true,"passed_validation":false,"backtrace":{"checked":true,"passed":false,"read_ret_val":0,"ondisk_value":"(4)0x100000012bf:[<0x1000000020c/file856 v3073>,<0x1000000020b/dir2 v3871>,<0x1000000020a/dir1 v3255>,<0x10000000209/testdir v29>,<0x10000000005/tmp v79>,<0x10000000003/client.0 v45>,<0x10000000002/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b v42>,<0x10000000001/sv_0 v63>,<0x10000000000/qa v49>,<0x1/volumes v47>]//[3]","memoryvalue":"(4)0x100000012bf:[<0x1000000020c/file856 v4429>,<0x1000000020b/dir2 v6612>,<0x1000000020a/dir1 v6634>,<0x10000000209/testdir v60>,<0x10000000005/tmp v105>,<0x10000000003/client.0 v69>,<0x10000000002/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b v64>,<0x10000000001/sv_0 v85>,<0x10000000000/qa v69>,<0x1/volumes v23>]//[3]","error_str":"On-disk backtrace is divergent or newer"},"raw_stats":{"checked":false,"passed":false,"read_ret_val":0,"ondisk_value.dirstat":"f()","ondisk_value.rstat":"n()","memory_value.dirstat":"f()","memory_value.rstat":"n()","error_str":""},"return_code":0}
2024-03-31T22:59:48.806+0000 7fee8508a700 20 mds.3.cache.ino(0x100000012bf) scrub_finished

So the in-memory version of <0x1/volumes v23> is less than on-disk version of <0x1/volumes v47> Hence it's marked as damaged.
Since the version mismatch happened at the first level directory i.e. /volumes, all the files under that has the same failures

On mds.l alone, there are 2617 files marked as damaged.

khiremat@teuthology:/a/teuthology-2024-03-31_21:24:02-fs-squid-distro-default-smithi/7633107/remote/smithi169$ zgrep "mds.3.scrubstack _validate_inode_done scrub error on inode" log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz | wc -l
2617

Actions
Copy link
 #22

Updated by Venky Shankar 23 days ago

Kotresh Hiremath Ravishankar wrote:

I looked into the logs from the failure https://pulpito.ceph.com/teuthology-2024-03-31_21:24:02-fs-squid-distro-default-smithi/7633107/

I found that there are lot of files for which the ondisk backtrace version is different from in-memory backtrace version.

e.g., for the file "volumes/qa/sv_0/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b/client.0/tmp/testdir/dir1/dir2/file856"

[...]

So the in-memory version of <0x1/volumes v23> is less than on-disk version of <0x1/volumes v47> Hence it's marked as damaged.
Since the version mismatch happened at the first level directory i.e. /volumes, all the files under that has the same failures

That's the case of divergent backtrace (in-memory version > on-disk version in-memory version < on-disk version for any given ancestor. See: inode_backtrace_t::compare).

Actually, I am currently looking into https://tracker.ceph.com/issues/64730 which is another case of divergent backtrace.

On mds.l alone, there are 2617 files marked as damaged.

khiremat@teuthology:/a/teuthology-2024-03-31_21:24:02-fs-squid-distro-default-smithi/7633107/remote/smithi169$ zgrep "mds.3.scrubstack _validate_inode_done scrub error on inode" log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz | wc -l
2617

EDIT: in-memory version < on-disk version

Actions
Copy link
 #23

Updated by Venky Shankar 23 days ago

  • Related to Bug #64730: fs/misc/multiple_rsync.sh workunit times out added
Actions
Copy link
 #24

Updated by Venky Shankar 23 days ago

In tracker #64730, I am doubting the in-memory versions mismatches to be related to subtree exporting b/w active MDSs. Could you check if there are subtree exports (esp. for the problematic inode), Kotresh?

Actions
Copy link
 #25

Updated by Kotresh Hiremath Ravishankar 23 days ago

In tracker #64730, I am doubting the in-memory versions mismatches to be related to subtree exporting b/w active MDSs. Could you check if there are subtree exports (esp. for the problematic inode), Kotresh?

Yes, there are subtree exports b/w MDSs for the problematic inode. The migration completed at "2024-03-31T22:59:48.289" and the scrub for this inode errored out at "2024-03-31T22:59:48.806"

./smithi169/log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz:2024-03-31T22:59:48.134+0000 7fee8b897700 10 mds.3.mig decode_import_inode added [inode 0x100000012bf [3,head] #100000012bf auth v4429 s=0 n(v0 rc2024-03-31T22:59:35.501633+0000 1=1+0) | importingcaps=1 0x559a2a681b80]
./smithi169/log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz:2024-03-31T22:59:48.134+0000 7fee8b897700 12 mds.3.cache.dir(0x1000000020c.111111*) link_primary_inode [dentry #0x1/volumes/qa/sv_0/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b/client.0/tmp/testdir/dir1/dir2/file856 [3,head] auth{0=1} NULL (dversion lock) v=4429 ino=(nil) state=1073741824 | replicated=1 0x559a2a972c80] [inode 0x100000012bf [3,head] #100000012bf auth v4429 s=0 n(v0 rc2024-03-31T22:59:35.501633+0000 1=1+0) | importingcaps=1 0x559a2a681b80]
./smithi169/log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz:2024-03-31T22:59:48.289+0000 7fee8508a700 10 mds.3.mig finish_import_inode_caps for client.15501 on [inode 0x100000012bf [3,head] /volumes/qa/sv_0/6d1b54ec-aa66-45d6-8d87-0b3b88c77f5b/client.0/tmp/testdir/dir1/dir2/file856 auth{0=1} v4429 s=0 n(v0 rc2024-03-31T22:59:35.501633+0000 1=1+0) | importingcaps=1 replicated=1 0x559a2a681b80]
./smithi169/log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz:2024-03-31T22:59:48.289+0000 7fee8508a700 10 mds.3.cache.ino(0x100000012bf) add_client_cap first cap, joining realm snaprealm(0x10000000002 seq 1 lc 0 cr 1 cps 2 snaps={} last_modified 0.000000 change_attr 0 0x559a2a2678c0)
Actions
Copy link
 #26

Updated by Kotresh Hiremath Ravishankar 23 days ago

Venky,

Yes, the /volumes inode 0x10000000000 is a replica on the mds where the scrub error is reported.

./smithi169/log/884bb054-efb0-11ee-b647-cb9ed24678a4/ceph-mds.l.log.gz:2024-03-31T22:57:57.073+0000 7fee8b897700 10 mds.3.cache decode_replica_inode added [inode 0x10000000000 [...2,head] #10000000000/ rep@-2.1 v23 f(v0 m2024-03-31T22:56:01.726609+0000 3=2+1) n(v2 rc2024-03-31T22:56:01.726609+0000 b234 10=4+6) (inest mix) 0x559a2a23f180]
Actions
Copy link

Also available in: Atom PDF