CephFS: smb2.create fails for shares configured with vfs_ceph_new

[anoopcs9]

It starts with smb2.create for vfs_ceph_new configured shares and further disrupts the cluster.

testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-vfs-new-smb2.create] FAILED [ 77%]
testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-vfs-smb2.bench] FAILED [ 78%]
testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-kclient-smb2.rename] FAILED [ 78%]
testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-kclient-smb2.mkdir] FAILED [ 79%]
testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-kclient-smb2.charset] FAILED [ 80%]
testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-vfs-new-smb2.deny] FAILED [ 81%]
testcases/smbtorture/test_smbtorture.py::test_smbtorture[share-cephfs-default-kclient-smb2.secleak] FAILED [ 82%]
testcases/containers/test_containers.py::test_containers[192.168.123.10-share-cephfs-default-kclient-smallfiles] FAILED [ 83%]
testcases/containers/test_containers.py::test_containers[192.168.123.10-share-cephfs-default-vfs-smallfiles] FAILED [ 84%]
testcases/containers/test_containers.py::test_containers[192.168.123.10-share-cephfs-default-kclient-ltp] FAILED [ 85%]
testcases/containers/test_containers.py::test_containers[192.168.123.10-share-cephfs-default-vfs-ltp] FAILED [ 85%]
testcases/containers/test_containers.py::test_containers[192.168.123.10-share-cephfs-default-vfs-new-smallfiles] FAILED [ 86%]
testcases/containers/test_containers.py::test_containers[192.168.123.10-share-cephfs-default-vfs-new-ltp] FAILED [ 87%]
testcases/misc/test_dbm.py::test_dbm_consistency_premounted[test_dir0] SKIPPED [ 88%]
testcases/misc/test_dbm.py::test_dbm_consistency[192.168.123.10-share-cephfs-default-vfs-new] ERROR [ 89%]
testcases/misc/test_dbm.py::test_dbm_consistency[192.168.123.10-share-cephfs-default-kclient] ERROR [ 90%]
testcases/misc/test_dbm.py::test_dbm_consistency[192.168.123.10-share-cephfs-default-vfs] ERROR [ 91%]
testcases/loading/test_loading.py::test_loading[192.168.123.10-share-cephfs-default-kclient] FAILED [ 92%]
testcases/loading/test_loading.py::test_loading[192.168.123.10-share-cephfs-default-vfs] FAILED [ 92%]
testcases/loading/test_loading.py::test_loading[192.168.123.10-share-cephfs-default-vfs-new] FAILED [ 93%]
testcases/consistency/test_consistency.py::test_consistency[192.168.123.10-share-cephfs-default-vfs-new] FAILED [ 94%]
testcases/consistency/test_consistency.py::test_consistency[192.168.123.10-share-cephfs-default-vfs] FAILED [ 95%]
testcases/consistency/test_consistency.py::test_consistency[192.168.123.10-share-cephfs-default-kclient] FAILED [ 96%]
testcases/misc/test_stress.py::test_check_mnt_stress[192.168.123.10-share-cephfs-default-vfs] ERROR [ 97%]
testcases/misc/test_stress.py::test_check_mnt_stress[192.168.123.10-share-cephfs-default-vfs-new] ERROR [ 98%]
testcases/misc/test_stress.py::test_check_mnt_stress[192.168.123.10-share-cephfs-default-kclient] ERROR [ 99%]
testcases/misc/test_stress.py::test_check_mnt_stress_premounted[test_dir0] SKIPPED [100%]

[anoopcs9]

Here's the pattern observed:

=================================== FAILURES ===================================
__________ test_smbtorture[share-cephfs-default-vfs-new-smb2.create] ___________
Failure in running test - smb2.create
----------------------------- Captured stdout call -----------------------------
Command: /bin/smbtorture --fullname --option=torture:progress=no --option=torture:sharedelay=100000 --option=torture:writetimeupdatedelay=500000 --format=subunit --target=samba3 --user=test1%x //192.168.123.10/share-cephfs-default-vfs-new smb2.create|/usr/bin/python3 /root/sit-test-cases/testcases/smbtorture/selftest/filter-subunit --fail-on-empty --prefix=samba3. --expected-failures=/root/sit-test-cases/testcases/smbtorture/selftest/knownfail --expected-failures=/root/sit-test-cases/testcases/smbtorture/selftest/knownfail.d --expected-failures=/root/sit-test-cases/testcases/smbtorture/selftest/expectedfail.d --flapping=/root/sit-test-cases/testcases/smbtorture/selftest/flapping --flapping=/root/sit-test-cases/testcases/smbtorture/selftest/flapping.d --flapping=/root/sit-test-cases/testcases/smbtorture/selftest/flapping.cephfs|/usr/bin/python3 /root/sit-test-cases/testcases/smbtorture/selftest/format-subunit

smbtorture 4.22.0pre1-UNKNOWN
Using seed 1732678803
time: 2024-11-27 03:40:03.850324Z
progress: 18
test: samba3.smb2.create.gentest
time: 2024-11-27 03:40:03.850619Z
time: 2024-11-27 03:40:03.929876Z
xfail: samba3.smb2.create.gentest [
Exception: (../../source4/torture/smb2/create.c:167) Incorrect status NT_STATUS_OK - should be NT_STATUS_INVALID_PARAMETER

]
test: samba3.smb2.create.blob
time: 2024-11-27 03:40:03.929901Z
Testing alloc size
Testing durable open
Testing query maximal access
Testing timewarp
time: 2024-11-27 03:40:04.020321Z
xfail: samba3.smb2.create.blob [
Exception: (../../source4/torture/smb2/create.c:430) Incorrect status NT_STATUS_MEDIA_WRITE_PROTECTED - should be NT_STATUS_OBJECT_NAME_NOT_FOUND

]
test: samba3.smb2.create.open
time: 2024-11-27 03:40:04.020340Z
Checking SMB2 Open
time: 2024-11-27 03:43:04.239544Z
xfail: samba3.smb2.create.open [
Exception: (../../source4/torture/smb2/create.c:741) Incorrect status NT_STATUS_IO_TIMEOUT - should be NT_STATUS_OK

]
test: samba3.smb2.create.brlocked
time: 2024-11-27 03:43:04.239573Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:44:04.317626Z
failure: samba3.smb2.create.brlocked [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.multi
time: 2024-11-27 03:44:04.317644Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:45:04.395465Z
failure: samba3.smb2.create.multi [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.delete
time: 2024-11-27 03:45:04.395495Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:46:04.455373Z
failure: samba3.smb2.create.delete [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.leading-slash
time: 2024-11-27 03:46:04.455387Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:47:04.479505Z
failure: samba3.smb2.create.leading-slash [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.impersonation
time: 2024-11-27 03:47:04.479519Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:48:04.554733Z
failure: samba3.smb2.create.impersonation [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.aclfile
time: 2024-11-27 03:48:04.554748Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:49:04.630329Z
failure: samba3.smb2.create.aclfile [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.acldir
time: 2024-11-27 03:49:04.630360Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:50:04.706431Z
failure: samba3.smb2.create.acldir [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.nulldacl
time: 2024-11-27 03:50:04.706445Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:51:04.799440Z
failure: samba3.smb2.create.nulldacl [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.mkdir-dup
time: 2024-11-27 03:51:04.799454Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:52:04.876057Z
failure: samba3.smb2.create.mkdir-dup [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.mkdir-visible
time: 2024-11-27 03:52:04.876086Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:53:04.950929Z
failure: samba3.smb2.create.mkdir-visible [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.dir-alloc-size
time: 2024-11-27 03:53:04.950944Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:54:05.026952Z
failure: samba3.smb2.create.dir-alloc-size [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.dosattr_tmp_dir
time: 2024-11-27 03:54:05.026990Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:55:05.102414Z
failure: samba3.smb2.create.dosattr_tmp_dir [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.quota-fake-file
time: 2024-11-27 03:55:05.102444Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:56:05.178412Z
xfail: samba3.smb2.create.quota-fake-file [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.path-length
time: 2024-11-27 03:56:05.178442Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:57:05.254679Z
failure: samba3.smb2.create.path-length [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]
test: samba3.smb2.create.bench-path-contention-shared
time: 2024-11-27 03:57:05.254719Z
Failed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
time: 2024-11-27 03:58:05.328899Z
failure: samba3.smb2.create.bench-path-contention-shared [
Exception: ../../source4/torture/smb2/smb2.c:37: Establishing SMB2 connection failed

]

smbtorture 4.22.0pre1-UNKNOWN
Using seed 1732678803
XTesting alloc size
Testing durable open
Testing query maximal access
Testing timewarp
XChecking SMB2 Open
XFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
XFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
FFailed to connect to SMB2 share \192.168.123.10\share-cephfs-default-vfs-new - NT_STATUS_IO_TIMEOUT
F
FAILED (14 failures, 0 errors and 0 unexpected successes in 0 testsuites)

There might be more detail in ./subunit or ./summary.

[anoopcs9]

The very first failure is seen from smb2.create.open when it tries to create a non-existing directory. It turned out to be a mds crash on server side as described in #69059.

[anoopcs9]

Possible fix: ceph/ceph#60889

[anoopcs9]

Possible fix: ceph/ceph#60889

mds crash fix has been merged but there are still failures due to another crash on libcephfs client side.

test: samba3.smb2.create.brlocked
time: 2025-01-17 07:58:57.169107Z
Testing SMB2 open with a byte range locked file
time: 2025-01-17 07:58:57.680396Z
failure: samba3.smb2.create.brlocked [
Exception: (../../source4/torture/smb2/create.c:891) Incorrect status NT_STATUS_CONNECTION_DISCONNECTED - should be NT_STATUS_OK
]
test: samba3.smb2.create.multi
time: 2025-01-17 07:58:57.680418Z
Testing SMB2 Open with multiple connections
waiting for replies
File 0 returned status NT_STATUS_IO_TIMEOUT
File 1 returned status NT_STATUS_IO_TIMEOUT
File 2 returned status NT_STATUS_IO_TIMEOUT
time: 2025-01-17 08:00:02.057821Z
failure: samba3.smb2.create.multi [
Exception: ../../source4/torture/smb2/create.c:1061: Expression `0' failed: ../../source4/torture/smb2/create.c:1061
]
test: samba3.smb2.create.delete
time: 2025-01-17 08:00:02.057847Z
Checking SMB2_OPEN for delete on a readonly file.
time: 2025-01-17 08:00:02.541369Z
failure: samba3.smb2.create.delete [
Exception: (../../source4/torture/smb2/create.c:1089) Incorrect status NT_STATUS_CONNECTION_DISCONNECTED - should be NT_STATUS_OK
]
test: samba3.smb2.create.leading-slash
time: 2025-01-17 08:00:02.541396Z
Trying to create a directory with leading slash on path
time: 2025-01-17 08:00:02.607754Z
successful: samba3.smb2.create.leading-slash
test: samba3.smb2.create.impersonation
time: 2025-01-17 08:00:02.607767Z
Testing SMB2 open with an invalid impersonation level.
time: 2025-01-17 08:00:03.085687Z
failure: samba3.smb2.create.impersonation [
Exception: (../../source4/torture/smb2/create.c:1200) Incorrect status NT_STATUS_CONNECTION_DISCONNECTED - should be NT_STATUS_OK
]
test: samba3.smb2.create.aclfile
time: 2025-01-17 08:00:03.085716Z
Testing nttrans create with sec_desc on files
basic create
time: 2025-01-17 08:01:07.026372Z
failure: samba3.smb2.create.aclfile [
Exception: (../../source4/torture/smb2/create.c:603) Incorrect status NT_STATUS_CONNECTION_DISCONNECTED - should be NT_STATUS_OK
]
. . .
test: samba3.smb2.create.dir-alloc-size
time: 2025-01-17 08:01:10.778385Z
Checking initial allocation size on directories
time: 2025-01-17 08:01:11.280040Z
failure: samba3.smb2.create.dir-alloc-size [
Exception: ../../source4/torture/smb2/create.c:2078: status was NT_STATUS_CONNECTION_DISCONNECTED, expected NT_STATUS_OK: torture_smb2_testdir failed
]
test: samba3.smb2.create.dosattr_tmp_dir
time: 2025-01-17 08:01:11.280067Z
time: 2025-01-17 08:02:12.069491Z
failure: samba3.smb2.create.dosattr_tmp_dir [
Exception: ../../source4/torture/smb2/create.c:3691: status was NT_STATUS_IO_TIMEOUT, expected NT_STATUS_OK: smb2_create
]

[synarete]

@anoopcs9 I was able to reproduce this one using latest ceph (3162e265) which include the fix. We get SIGSEGV from libcephfs when in becomes NULL, probably here.

This happens when doing dfd = openat("/".. ) followed by lookup(dfd, "."). However, so far I was not able to reproduce it via normal mount (only via smbtorture). Still under investigation.

[anoopcs9]

@anoopcs9 I was able to reproduce this one using latest ceph (3162e265) which include the fix. We get SIGSEGV from libcephfs when in becomes NULL, probably here.

With the help of gdb, after stepping through smbd while running the smbtorture test case I could figure out a pattern for which I have created a reproducer as attached here.

libcephfs_ll_lookup_crash.c.txt

[anoopcs9]

@anoopcs9 I was able to reproduce this one using latest ceph (3162e265) which include the fix. We get SIGSEGV from libcephfs when in becomes NULL, probably here.

With the help of gdb, after stepping through smbd while running the smbtorture test case I could figure out a pattern for which I have created a reproducer as attached here.

libcephfs_ll_lookup_crash.c.txt

Tracker #69624 created in ceph upstream for further discussion.