Project

General

Profile

Bug #61409

qa: _test_stale_caps does not wait for file flush before stat

Added by Patrick Donnelly 9 months ago. Updated 7 months ago.

Status:
Pending Backport
Priority:
Normal
Category:
-
Target version:
% Done:

0%

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

Description

2023-05-24T04:34:41.092+0000 7f6a0a2a5700  1 -- [v2:172.21.15.78:6834/4229713409,v1:172.21.15.78:6836/4229713409] <== client.9872 v1:172.21.15.78:0/7005536 48 ==== client_request(client.9872:46 create #0x1/background_file 2023-05-24T04:34:41.092323+0000 caller_uid=1000, caller_gid=1265{6,36,1000,1265,}) v4 ==== 227+0+62 (unknown 473842443 0 1524826435) 0x56451e076f00 con 0x56451debe800
...
2023-05-24T04:34:41.095+0000 7f6a04299700  1 -- [v2:172.21.15.78:6834/4229713409,v1:172.21.15.78:6836/4229713409] --> v1:172.21.15.78:0/7005536 -- client_reply(???:46 = 0 (0) Success safe) v1 -- 0x56451d030700 con 0x56451debe800

...
2023-05-24T04:34:42.746+0000 7f6a0a2a5700  1 -- [v2:172.21.15.78:6834/4229713409,v1:172.21.15.78:6836/4229713409] <== client.9878 v1:192.168.0.1:0/2658763465 8 ==== client_request(client.9878:4 lookup #0x1/background_file 2023-05-24T04:34:42.746500+0000 caller_uid=1000, caller_gid=1265{6,36,1000,1265,}) v4 ==== 183+0+0 (unknown 1669729697 0 0) 0x56451e076300 con 0x56451e04a000
...
2023-05-24T04:34:42.747+0000 7f6a0a2a5700  1 -- [v2:172.21.15.78:6834/4229713409,v1:172.21.15.78:6836/4229713409] --> v1:172.21.15.78:0/7005536 -- client_caps(revoke ino 0x10000000000 1 seq 2 caps=pAsLsXsxFsxcrwb dirty=- wanted=pAsxXsxFxwb follows 0 size 0/4194304 ts 1/18446744073709551615 mtime 2023-05-24T04:34:41.092323+0000 ctime 2023-05-24T04:34:41.092323+0000 change_attr 0) v12 -- 0x56451e049500 con 0x56451debe800
...
2023-05-24T04:34:42.747+0000 7f6a0a2a5700  1 -- [v2:172.21.15.78:6834/4229713409,v1:172.21.15.78:6836/4229713409] <== client.9872 v1:172.21.15.78:0/7005536 54 ==== client_caps(update ino 0x10000000000 1 seq 2 tid 2 caps=pAsLsXsxFsxcrwb dirty=Fw wanted=pAsxXsxFxwb follows 1 size 7/0 mtime 2023-05-24T04:34:41.097323+0000 ctime 2023-05-24T04:34:41.097323+0000 change_attr 1 xattrs(v=18446744072647710505 l=0)) v10 ==== 236+0+0 (unknown 2252655934 0 0) 0x56451df95500 con 0x56451debe800
...
2023-05-24T04:34:42.747+0000 7f6a0a2a5700  7 mds.0.locker   size 0 -> 7 for [inode 0x10000000000 [2,head] /background_file auth v2 pv4 ap=2 DIRTYPARENT s=0 n(v0 1=1+0)->n(v0 rc2023-05-24T04:34:41.097323+0000 1=1+0)/n(v0 1=1+0) (iauth excl->sync) (ifile excl) (ixattr excl) (iversion lock) cr={9872=0-4194304@1} caps={9872=pAsLsXsxFsxcrwb/pAsxXsxFxwb@2},l=9872 | request=1 lock=1 caps=1 dirtyparent=1 dirty=1 waiter=1 authpin=1 0x56451df8bb80]

From: /teuthology/pdonnell-2023-05-23_18:20:18-fs-wip-pdonnell-testing-20230523.134409-distro-default-smithi/7284331/remote/smithi078/log/ceph-mds.c.log.gz

Related snippet of teuthology.log:

2023-05-24T04:34:40.966 DEBUG:teuthology.orchestra.run.smithi078:> set -ex
2023-05-24T04:34:40.966 DEBUG:teuthology.orchestra.run.smithi078:> dd if=/proc/self/mounts of=/dev/stdout
2023-05-24T04:34:40.987 DEBUG:teuthology.orchestra.run.smithi078:> stdin-killer -- python3 -c '
2023-05-24T04:34:40.988 DEBUG:teuthology.orchestra.run.smithi078:> import fcntl
2023-05-24T04:34:40.988 DEBUG:teuthology.orchestra.run.smithi078:> import os
2023-05-24T04:34:40.989 DEBUG:teuthology.orchestra.run.smithi078:> import sys
2023-05-24T04:34:40.990 DEBUG:teuthology.orchestra.run.smithi078:> import time
2023-05-24T04:34:40.991 DEBUG:teuthology.orchestra.run.smithi078:>
2023-05-24T04:34:40.991 DEBUG:teuthology.orchestra.run.smithi078:> fcntl.fcntl(sys.stdin, fcntl.F_SETFL, fcntl.fcntl(sys.stdin, fcntl.F_GETFL) | os.O_NONBLOCK)
2023-05-24T04:34:40.991 DEBUG:teuthology.orchestra.run.smithi078:>
2023-05-24T04:34:40.992 DEBUG:teuthology.orchestra.run.smithi078:> with open("/home/ubuntu/cephtest/mnt.0/background_file", '"'"'w'"'"') as f:
2023-05-24T04:34:40.992 DEBUG:teuthology.orchestra.run.smithi078:>     f.write('"'"'content'"'"')
2023-05-24T04:34:40.993 DEBUG:teuthology.orchestra.run.smithi078:>     f.flush()
2023-05-24T04:34:40.993 DEBUG:teuthology.orchestra.run.smithi078:>     f.write('"'"'content2'"'"')
2023-05-24T04:34:40.993 DEBUG:teuthology.orchestra.run.smithi078:>     while True:
2023-05-24T04:34:40.994 DEBUG:teuthology.orchestra.run.smithi078:>         print("open_background: keeping file open", file=sys.stderr)
2023-05-24T04:34:40.994 DEBUG:teuthology.orchestra.run.smithi078:>         try:
2023-05-24T04:34:40.994 DEBUG:teuthology.orchestra.run.smithi078:>              if os.read(0, 4096) == b"":
2023-05-24T04:34:40.994 DEBUG:teuthology.orchestra.run.smithi078:>                   break
2023-05-24T04:34:40.995 DEBUG:teuthology.orchestra.run.smithi078:>         except BlockingIOError:
2023-05-24T04:34:40.995 DEBUG:teuthology.orchestra.run.smithi078:>             pass
2023-05-24T04:34:40.995 DEBUG:teuthology.orchestra.run.smithi078:>         time.sleep(2)
2023-05-24T04:34:40.996 DEBUG:teuthology.orchestra.run.smithi078:> '
2023-05-24T04:34:41.030 DEBUG:teuthology.orchestra.run.smithi078:> stat /home/ubuntu/cephtest/mnt.0/background_file
2023-05-24T04:34:41.052 DEBUG:teuthology.orchestra.run:got remote process result: 1
2023-05-24T04:34:41.054 INFO:teuthology.orchestra.run.smithi078.stderr:stat: cannot statx '/home/ubuntu/cephtest/mnt.0/background_file': No such file or directory
2023-05-24T04:34:42.055 DEBUG:teuthology.orchestra.run.smithi078:> stat /home/ubuntu/cephtest/mnt.0/background_file
2023-05-24T04:34:42.075 INFO:teuthology.orchestra.run.smithi078.stdout:  File: /home/ubuntu/cephtest/mnt.0/background_file
2023-05-24T04:34:42.075 INFO:teuthology.orchestra.run.smithi078.stdout:  Size: 7                Blocks: 1          IO Block: 4194304 regular file
2023-05-24T04:34:42.075 INFO:teuthology.orchestra.run.smithi078.stdout:Device: 2eh/46d  Inode: 1099511627776  Links: 1
2023-05-24T04:34:42.075 INFO:teuthology.orchestra.run.smithi078.stdout:Access: (0664/-rw-rw-r--)  Uid: ( 1000/  ubuntu)   Gid: ( 1265/  ubuntu)
2023-05-24T04:34:42.075 INFO:teuthology.orchestra.run.smithi078.stdout:Context: unconfined_u:object_r:cephfs_t:s0
2023-05-24T04:34:42.076 INFO:teuthology.orchestra.run.smithi078.stdout:Access: 2023-05-24 04:34:41.092323278 +0000
2023-05-24T04:34:42.076 INFO:teuthology.orchestra.run.smithi078.stdout:Modify: 2023-05-24 04:34:41.097323188 +0000
2023-05-24T04:34:42.076 INFO:teuthology.orchestra.run.smithi078.stdout:Change: 2023-05-24 04:34:41.097323188 +0000
2023-05-24T04:34:42.076 INFO:teuthology.orchestra.run.smithi078.stdout: Birth: 2023-05-24 04:34:41.092323278 +0000
2023-05-24T04:34:42.076 DEBUG:tasks.cephfs.mount:File background_file became visible from 0 after 1s

Because we stop the netns of the mount before this flush call can complete:

https://github.com/ceph/ceph/blob/27270968c7bd9316f4e08107c5dea41f20962eae/qa/tasks/cephfs/mount.py#L956

the f.flush() call will hang and the script will not move on to the "while True" loop.


Related issues

Copied to CephFS - Backport #62268: pacific: qa: _test_stale_caps does not wait for file flush before stat Resolved
Copied to CephFS - Backport #62269: reef: qa: _test_stale_caps does not wait for file flush before stat In Progress
Copied to CephFS - Backport #62270: quincy: qa: _test_stale_caps does not wait for file flush before stat In Progress

History

#1 Updated by Patrick Donnelly 9 months ago

  • Status changed from In Progress to Fix Under Review
  • Pull request ID set to 51995

#2 Updated by Venky Shankar 7 months ago

  • Status changed from Fix Under Review to Pending Backport

#3 Updated by Backport Bot 7 months ago

  • Copied to Backport #62268: pacific: qa: _test_stale_caps does not wait for file flush before stat added

#4 Updated by Backport Bot 7 months ago

  • Copied to Backport #62269: reef: qa: _test_stale_caps does not wait for file flush before stat added

#5 Updated by Backport Bot 7 months ago

  • Copied to Backport #62270: quincy: qa: _test_stale_caps does not wait for file flush before stat added

#6 Updated by Backport Bot 7 months ago

  • Tags set to backport_processed

#7 Updated by Casey Bodley 7 months ago

backports should include the flake8 cleanup from https://github.com/ceph/ceph/pull/52732

#8 Updated by Patrick Donnelly 7 months ago

Casey Bodley wrote:

backports should include the flake8 cleanup from https://github.com/ceph/ceph/pull/52732

Apparently this issue is only in main.

Also available in: Atom PDF