Actions
Bug #61409
openqa: _test_stale_caps does not wait for file flush before stat
Status:
Pending Backport
Priority:
Normal
Assignee:
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:
the f.flush() call will hang and the script will not move on to the "while True" loop.
Actions