Project

General

Profile

Actions

Bug #62229

open

log_channel(cluster) log [WRN] : client.7719 does not advance its oldest_client_tid (1), 1004 completed requests recorded in session

Added by Xiubo Li 9 months ago. Updated 9 months ago.

Status:
Fix Under Review
Priority:
Normal
Assignee:
Category:
-
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

https://pulpito.ceph.com/vshankar-2023-07-25_11:29:34-fs-wip-vshankar-testing-20230725.043804-testing-default-smithi/7350686/

Test failure: test_client_release_bug (tasks.cephfs.test_client_limits.TestClientLimits)

2023-07-25T15:26:25.043 INFO:teuthology.orchestra.run.smithi038.stderr:2023-07-25T15:26:25.031+0000 7ff4275ff700  1 -- 172.21.15.38:0/2708588022 shutdown_connections
2023-07-25T15:26:25.043 INFO:teuthology.orchestra.run.smithi038.stderr:2023-07-25T15:26:25.032+0000 7ff4275ff700  1 -- 172.21.15.38:0/2708588022 wait complete.
2023-07-25T15:26:25.063 INFO:tasks.cephfs_test_runner:test_client_release_bug (tasks.cephfs.test_client_limits.TestClientLimits) ... ERROR
2023-07-25T15:26:25.063 INFO:tasks.cephfs_test_runner:
2023-07-25T15:26:25.064 INFO:tasks.cephfs_test_runner:======================================================================
2023-07-25T15:26:25.064 INFO:tasks.cephfs_test_runner:ERROR: test_client_release_bug (tasks.cephfs.test_client_limits.TestClientLimits)
2023-07-25T15:26:25.064 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2023-07-25T15:26:25.064 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2023-07-25T15:26:25.065 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_a5d48e8c688c2543997a98b8acbae2ce9635578c/qa/tasks/cephfs/test_client_limits.py", line 208, in test_client_release_bug
2023-07-25T15:26:25.065 INFO:tasks.cephfs_test_runner:    self.wait_for_health("MDS_CLIENT_LATE_RELEASE", session_timeout + 10)
2023-07-25T15:26:25.065 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_a5d48e8c688c2543997a98b8acbae2ce9635578c/qa/tasks/ceph_test_case.py", line 184, in wait_for_health
2023-07-25T15:26:25.065 INFO:tasks.cephfs_test_runner:    self.wait_until_true(seen_health_warning, timeout)
2023-07-25T15:26:25.065 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_a5d48e8c688c2543997a98b8acbae2ce9635578c/qa/tasks/ceph_test_case.py", line 231, in wait_until_true
2023-07-25T15:26:25.065 INFO:tasks.cephfs_test_runner:    raise TestTimeoutError("Timed out after {0}s and {1} retries".format(elapsed, retry_count))
2023-07-25T15:26:25.066 INFO:tasks.cephfs_test_runner:tasks.ceph_test_case.TestTimeoutError: Timed out after 70s and 0 retries
2023-07-25T15:26:25.066 INFO:tasks.cephfs_test_runner:
2023-07-25T15:26:25.066 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2023-07-25T15:26:25.066 INFO:tasks.cephfs_test_runner:Ran 9 tests in 748.706s
2023-07-25T15:26:25.066 INFO:tasks.cephfs_test_runner:
2023-07-25T15:26:25.067 INFO:tasks.cephfs_test_runner:FAILED (errors=1)
2023-07-25T15:26:25.067 INFO:tasks.cephfs_test_runner:
2023-07-25T15:26:25.067 INFO:tasks.cephfs_test_runner:======================================================================
2023-07-25T15:26:25.067 INFO:tasks.cephfs_test_runner:ERROR: test_client_release_bug (tasks.cephfs.test_client_limits.TestClientLimits)
2023-07-25T15:26:25.067 INFO:tasks.cephfs_test_runner:----------------------------------------------------------------------
2023-07-25T15:26:25.068 INFO:tasks.cephfs_test_runner:Traceback (most recent call last):
2023-07-25T15:26:25.068 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_a5d48e8c688c2543997a98b8acbae2ce9635578c/qa/tasks/cephfs/test_client_limits.py", line 208, in test_client_release_bug
2023-07-25T15:26:25.068 INFO:tasks.cephfs_test_runner:    self.wait_for_health("MDS_CLIENT_LATE_RELEASE", session_timeout + 10)
2023-07-25T15:26:25.068 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_a5d48e8c688c2543997a98b8acbae2ce9635578c/qa/tasks/ceph_test_case.py", line 184, in wait_for_health
2023-07-25T15:26:25.068 INFO:tasks.cephfs_test_runner:    self.wait_until_true(seen_health_warning, timeout)
2023-07-25T15:26:25.069 INFO:tasks.cephfs_test_runner:  File "/home/teuthworker/src/git.ceph.com_ceph-c_a5d48e8c688c2543997a98b8acbae2ce9635578c/qa/tasks/ceph_test_case.py", line 231, in wait_until_true
2023-07-25T15:26:25.069 INFO:tasks.cephfs_test_runner:    raise TestTimeoutError("Timed out after {0}s and {1} retries".format(elapsed, retry_count))
2023-07-25T15:26:25.069 INFO:tasks.cephfs_test_runner:tasks.ceph_test_case.TestTimeoutError: Timed out after 70s and 0 retries
2023-07-25T15:26:25.069 INFO:tasks.cephfs_test_runner:

Actions #1

Updated by Xiubo Li 9 months ago

  • Status changed from New to Fix Under Review
  • Pull request ID set to 52692

The test_client_oldest_tid test case was triggered first:

2023-07-25T15:20:29.281 INFO:tasks.cephfs_test_runner:Starting test: test_client_oldest_tid (tasks.cephfs.test_client_limits.TestClientLimits)
2023-07-25T15:20:29.281 DEBUG:teuthology.orchestra.run.smithi038:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 120 ceph --cluster ceph log 'Starting test tasks.cephfs.test_client_limits.TestClientLimits.test_client_oldest_tid'
...
2023-07-25T15:20:29.787 INFO:teuthology.orchestra.run.smithi038.stderr:2023-07-25T15:20:29.772+0000 7f205cfff700  1 -- 172.21.15.38:0/278982153 --> [v2:172.21.15.38:3300/0,v1:172.21.15.38:6789/0] -- mon_command({"prefix": "log", "logtext": ["Starting test tasks.cephfs.test_client_limits.TestClientLimits.test_client_oldest_tid"]} v 0) v1 -- 0x7f20580cf890 con 0x7f205813d950
2023-07-25T15:20:30.263 INFO:teuthology.orchestra.run.smithi038.stderr:2023-07-25T15:20:30.247+0000 7f2046ffd700  1 -- 172.21.15.38:0/278982153 <== mon.0 v2:172.21.15.38:3300/0 7 ==== mon_command_ack([{"prefix": "log", "logtext": ["Starting test tasks.cephfs.test_client_limits.TestClientLimits.test_client_oldest_tid"]}]=0  v375) v1 ==== 153+0+0 (secure 0 0 0) 0x7f2050057b70 con 0x7f205813d950
...
2023-07-25T15:21:33.423 DEBUG:teuthology.orchestra.run.smithi038:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 120 ceph --cluster ceph log 'Ended test tasks.cephfs.test_client_limits.TestClientLimits.test_client_oldest_tid'
...
2023-07-25T15:21:33.933 INFO:teuthology.orchestra.run.smithi038.stderr:2023-07-25T15:21:33.917+0000 7f79ee39d700  1 -- 172.21.15.38:0/1069934743 --> [v2:172.21.15.38:3300/0,v1:172.21.15.38:6789/0] -- mon_command({"prefix": "log", "logtext": ["Ended test tasks.cephfs.test_client_limits.TestClientLimits.test_client_oldest_tid"]} v 0) v1 -- 0x7f79e815f5f0 con 0x7f79e80b1fc0
2023-07-25T15:21:34.773 INFO:teuthology.orchestra.run.smithi038.stderr:2023-07-25T15:21:34.757+0000 7f79ddffb700  1 -- 172.21.15.38:0/1069934743 <== mon.0 v2:172.21.15.38:3300/0 7 ==== mon_command_ack([{"prefix": "log", "logtext": ["Ended test tasks.cephfs.test_client_limits.TestClientLimits.test_client_oldest_tid"]}]=0  v430) v1 ==== 150+0+0 (secure 0 0 0) 0x7f79e815f5f0 con 0x7f79e80b1fc0
...
2023-07-25T15:21:34.797 INFO:tasks.cephfs_test_runner:test_client_oldest_tid (tasks.cephfs.test_client_limits.TestClientLimits) ... ok

The test case test_client_release_bug was triggered later after test_client_oldest_tid:

2023-07-25T15:24:15.925 INFO:tasks.cephfs_test_runner:Starting test: test_client_release_bug (tasks.cephfs.test_client_limits.TestClientLimits)
2023-07-25T15:24:15.925 DEBUG:teuthology.orchestra.run.smithi038:> sudo adjust-ulimits ceph-coverage /home/ubuntu/cephtest/archive/coverage timeout 120 ceph --cluster ceph log 'Starting test tasks.cephfs.test_client_limits.TestClientLimits.test_client_release_bug'
...

But the test_client_oldest_tid didn't clean the client inject fixed oldest tid option.

Actions

Also available in: Atom PDF