Project

General

Profile

Actions
Copy link

Bug #69898

open

Test failure: test_fetch_for_mds_max_snaps_per_dir (tasks.cephfs.test_snap_schedules.TestSnapSchedulesFetchForeignConfig)

Added by Kumar Hemanth about 1 year ago. Updated about 2 months ago.

Status:
New
Priority:
Normal
Assignee:
Mahesh Mohan
Category:
-
Target version:
-
% Done:

0%

Source:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Labels (FS):
Pull request ID:
Tags (freeform):
temp-assign
Merge Commit:
Fixed In:
Released In:
Upkeep Timestamp:

Description

https://pulpito.ceph.com/hyelloji-2025-01-15_07:12:26-fs-wip-hemanth1-testing-2025-01-13-1558-reef-distro-default-smithi/8078219/

2025-01-16T19:28:13.169 INFO:tasks.cephfs_test_runner:Test the correctness of snap directory name ... FAIL
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:======================================================================
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:FAIL: test_fetch_for_mds_max_snaps_per_dir (tasks.cephfs.test_snap_schedules.TestSnapSchedulesFetchForeignConfig)
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:Test the correctness of snap directory name
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/github.com_ceph_ceph-c_35aa12e8113161a135a96fd9b5a767dd61a532c4/qa/tasks/cephfs/test_snap_schedules.py", line 1135, in test_fetch_for_mds_max_snaps_per_dir
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:    self.assertTrue(fs_count == 9)
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:AssertionError: False is not true
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:Ran 12 tests in 6579.661s
2025-01-16T19:28:13.170 INFO:tasks.cephfs_test_runner:
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:FAILED (failures=1)
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:======================================================================
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:FAIL: test_fetch_for_mds_max_snaps_per_dir (tasks.cephfs.test_snap_schedules.TestSnapSchedulesFetchForeignConfig)
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:Test the correctness of snap directory name
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/github.com_ceph_ceph-c_35aa12e8113161a135a96fd9b5a767dd61a532c4/qa/tasks/cephfs/test_snap_schedules.py", line 1135, in test_fetch_for_mds_max_snaps_per_dir
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:    self.assertTrue(fs_count == 9)
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:AssertionError: False is not true
2025-01-16T19:28:13.171 INFO:tasks.cephfs_test_runner:
2025-01-16T19:28:13.171 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_teuthology_42294faf23294f557d349df1bd69657772519729/teuthology/run_tasks.py", line 112, in run_tasks
    manager.__enter__()
  File "/usr/lib/python3.10/contextlib.py", line 135, in __enter__
    return next(self.gen)
  File "/home/teuthworker/src/github.com_ceph_ceph-c_35aa12e8113161a135a96fd9b5a767dd61a532c4/qa/tasks/cephfs_test_runner.py", line 211, in task
    raise RuntimeError("Test failure: {0}".format(", ".join(bad_tests)))
RuntimeError: Test failure: test_fetch_for_mds_max_snaps_per_dir (tasks.cephfs.test_snap_schedules.TestSnapSchedulesFetchForeignConfig)
2025-01-16T19:28:13.342 ERROR:teuthology.util.sentry: Sentry event: https://sentry.ceph.com/organizations/ceph/?query=2365ce9bed2742fd8d870da450e05067
Traceback (most recent call last):
  File "/home/teuthworker/src/git.ceph.com_teuthology_42294faf23294f557d349df1bd69657772519729/teuthology/run_tasks.py", line 112, in run_tasks
    manager.__enter__()
  File "/usr/lib/python3.10/contextlib.py", line 135, in __enter__
    return next(self.gen)
  File "/home/teuthworker/src/github.com_ceph_ceph-c_35aa12e8113161a135a96fd9b5a767dd61a532c4/qa/tasks/cephfs_test_runner.py", line 211, in task
    raise RuntimeError("Test failure: {0}".format(", ".join(bad_tests)))
RuntimeError: Test failure: test_fetch_for_mds_max_snaps_per_dir (tasks.cephfs.test_snap_schedules.TestSnapSchedulesFetchForeignConfig)
Actions
Copy link
 #1

Updated by Milind Changire about 1 year ago

tl;dr; its a simple race between readdir and rmdir

Here's the timestamps:
Dir is created

2025-01-16T19:28:00.680+0000 7fd97119d640 10 client.11985 mkdirat: snap_test_dir1/.snap/scheduled-2025-01-16-19_28_00_UTC

Dir is read by teuthology

2025-01-16T19:28:00.745 DEBUG:teuthology.orchestra.run.smithi005:> (cd /home/ubuntu/cephtest/mnt.0 && exec ls snap_test_dir1/.snap)
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_18_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_19_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_20_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_21_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_22_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_23_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_24_00_UTC
2025-01-16T19:28:00.760 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_26_00_UTC
2025-01-16T19:28:00.761 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_27_00_UTC
2025-01-16T19:28:00.761 INFO:teuthology.orchestra.run.smithi005.stdout:scheduled-2025-01-16-19_28_00_UTC

Dir is pruned

2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule INFO snap_schedule.fs.schedule_client] no retention set, assuming n: 9
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_28_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_27_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_26_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_24_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_23_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_22_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_21_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_20_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] keeping b'scheduled-2025-01-16-19_19_00_UTC' due to 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] found enough snapshots for 9n
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period m
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period h
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period d
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period w
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period M
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] compiling keep set for period y
2025-01-16T19:28:00.824+0000 7fd97119d640  0 [snap_schedule DEBUG snap_schedule.fs.schedule_client] rmdir on scheduled-2025-01-16-19_18_00_UTC

The solution is simple:
  • calculate time until next top of the minute
  • add 10 seconds to the above window
  • sleep for above duration
Actions
Copy link
 #2

Updated by Milind Changire about 1 year ago

  • Assignee set to Milind Changire
Actions
Copy link
 #3

Updated by Patrick Donnelly about 1 year ago

  • Description updated (diff)
Actions
Copy link
 #4

Updated by Venky Shankar about 2 months ago

  • Assignee changed from Milind Changire to Mahesh Mohan
  • Tags (freeform) set to temp-assign
Actions
Copy link

Also available in: Atom PDF