Bug #57676
openqa: error during scrub thrashing: rank damage found: {'backtrace'}
Added by Patrick Donnelly over 1 year ago. Updated 4 days ago.
0%
Description
Backtrace scrub failures are back with damage checking in fwd_scrub.py, introduced by
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
Updated by Rishabh Dave about 1 year 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
Updated by Xiubo Li about 1 year ago
Another failure the same with this: https://pulpito.ceph.com/vshankar-2023-05-03_16:19:11-fs-wip-vshankar-testing-20230503.142424-testing-default-smithi/7261300
Updated by Kotresh Hiremath Ravishankar 12 months ago
reef
https://pulpito.ceph.com/yuriw-2023-05-10_18:53:39-fs-wip-yuri3-testing-2023-05-10-0851-reef-distro-default-smithi/7270376
https://pulpito.ceph.com/yuriw-2023-05-15_15:47:06-fs-wip-yuri3-testing-2023-05-10-0851-reef-distro-default-smithi/7274468
https://pulpito.ceph.com/yuriw-2023-05-15_15:47:06-fs-wip-yuri3-testing-2023-05-10-0851-reef-distro-default-smithi/7274461
Updated by Kotresh Hiremath Ravishankar 12 months ago
Updated by Kotresh Hiremath Ravishankar 11 months ago
reef:
https://pulpito.ceph.com/yuriw-2023-05-28_14:46:14-fs-reef-release-distro-default-smithi/7288884
https://pulpito.ceph.com/yuriw-2023-05-28_14:46:14-fs-reef-release-distro-default-smithi/7288901
https://pulpito.ceph.com/yuriw-2023-05-28_14:46:14-fs-reef-release-distro-default-smithi/7288941
https://pulpito.ceph.com/yuriw-2023-05-28_14:46:14-fs-reef-release-distro-default-smithi/7288973
https://pulpito.ceph.com/yuriw-2023-05-28_14:46:14-fs-reef-release-distro-default-smithi/7289012
Updated by Kotresh Hiremath Ravishankar 11 months ago
Updated by Venky Shankar about 1 month ago
- Backport changed from pacific,quincy to quincy,reef,squid
Updated by Venky Shankar about 1 month 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.
Updated by Venky Shankar about 1 month 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.
Updated by Kotresh Hiremath Ravishankar about 1 month 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
Updated by Venky Shankar about 1 month 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
Updated by Venky Shankar about 1 month ago
- Related to Bug #64730: fs/misc/multiple_rsync.sh workunit times out added
Updated by Venky Shankar about 1 month 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?
Updated by Kotresh Hiremath Ravishankar about 1 month 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)
Updated by Kotresh Hiremath Ravishankar about 1 month 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]
Updated by Milind Changire 4 days ago
Updated by Venky Shankar 1 day ago
- Related to Bug #65777: qa: error during scrub thrashing added