Am 09.07.22 um 05:39 schrieb Shyam Prasad N: > On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N wrote: >> >> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya wrote: >>> >>> On 07/08, Fabian Ebner wrote: >>>> (Re-sending without the log from the older kernel, because the mail hit >>>> the 100000 char limit with that) >>>> >>>> Hi, >>>> it seems that in kernels >= 5.15, io_uring and CIFS don't interact >>>> nicely sometimes, leading to IO errors. Unfortunately, my reproducer is >>>> a QEMU VM with a disk on CIFS (original report by one of our users [0]), >>>> but I can try to cook up something simpler if you want. >>>> >>>> Bisecting got me to 8ef12efe26c8 ("io_uring: run regular file >>>> completions from task_work") being the first bad commit. >>>> >>>> Attached are debug logs taken with Ubuntu's build of 5.18.6. QEMU trace >>>> was taken with '-trace luring*' and CIFS debug log was enabled as >>>> described in [1]. >>>> >>>> Without CIFS debugging, the error messages in syslog are, for 5.18.6: >>>>> Jun 29 12:41:45 pve702 kernel: [ 112.664911] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.796227] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.796250] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.797781] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -11 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.798065] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -11 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.813485] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.813497] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.826829] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.826837] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.839369] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.839381] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.851854] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.851867] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5 >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.870763] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED >>>>> Jun 29 12:41:46 pve702 kernel: [ 112.870777] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5 >>> >>> It looks like this has something to do with multiple session setups on >>> the same channel, and there's a fix introduced in 5.19-rc1: >>> >>> 5752bf645f9 "cifs: avoid parallel session setups on same channel" >>> >>> Can you build a test kernel with that commit and test it again? I >>> couldn't reproduce this with a small liburing test program. If you can >>> provide one, I'd be happy to take a deeper look at this bug. >>> I did, and with the patch all the STATUS_REQUEST_NOT_ACCEPTED and SessSetup errors are gone, but the "Error -512 sending data on socket to server" and the IO error with kvm remain. When using 5.15 or the kernel built from 8ef12efe26c8, it was also only that error. Looking at what QEMU sees from io_uring: with the unpatched 5.18.6 there's -EIO returned for some requests, but not anymore with 5752bf645f9 applied. On the patched kernel, the problematic request has a positive return value, but it's a short write and QEMU doesn't like that and propagates -ENOSPC up its IO stack. Is this actually the root cause of the issue? Is it correct by io_uring to return a short write here or would QEMU need to adapt? As for reproducing the issue: Within the kvm instance, I'm simply doing dd if=/dev/urandom of=file bs=1M count=1000 and it triggers consistently. Sometimes it already happens while the guest is booting. I also tested with io_uring-cp (from liburing's examples/, I used the liburing2.2 git tag), copying a large file with CIFS as the target. Since with kvm there's > CIFS: fs/cifs/transport.c: signal is pending after attempt to send in the log, I simply tried to Ctrl+C the copy operation, and I'm sometimes able to get the same error (and hopefully it is the same issue). Interrupting quickly seems to have better chances for triggering it and having CIFS debugging enabled feels like it might expand the time window. >>> Please note that the actual root cause of the error (CIFS needing >>> reconnect) is not very clear to me, but I don't have experience with >>> io_uring anyway: >>> >>> 178 Jun 29 11:25:39 pve702 kernel: [ 87.439910] CIFS: fs/cifs/transport.c: signal is pending after attempt to send >>> 179 Jun 29 11:25:39 pve702 kernel: [ 87.439920] CIFS: fs/cifs/transport.c: partial send (wanted=65652 sent=53364): terminating session > > This error indicates that the socket could only send partial data to > the server. This causes the client to reconnect. While I don't think > this is the primary issue here, it is definitely an issue. Please look > into that as well. > With the other issue gone, there's more weight to this one. Do you have any concrete suggestions what to look for? >>> 180 Jun 29 11:25:39 pve702 kernel: [ 87.439970] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server >>> >> erroneous reconnect loop as shown above> >>> >>> >>> Cheers, >>> >>> Enzo >> >> Hi Fabian, >> >> It looks like the server is rejecting new binding session requests >> with STATUS_REQUEST_NOT_ACCEPTED. >> Are you saying that the issue is specific to 5.15+ kernel, and the >> issue doesn't happen on older kernels? At least I haven't been able to trigger the issue with kernels without commit 8ef12efe26c8, but that commit might just have exposed an already existing issue. >> Also, what server are you using? Has that changed across these attempts? >> The server hasn't changed. I'm using the samba package from Debian Bullseye 2:4.13.13+dfsg-1~deb11u4 and kernel 5.15.39-1-pve, which is custom built, but based on the one from Ubuntu Jammy. >> Can you please dump the output of: >> cat /proc/fs/cifs/DebugData >> when the issue is happening? >> Sure: > Display Internal CIFS Data Structures for Debugging > --------------------------------------------------- > CIFS Version 2.36 > Features: DFS,FSCACHE,STATS,DEBUG,ALLOW_INSECURE_LEGACY,CIFS_POSIX,UPCALL(SPNEGO),XATTR,ACL,WITNESS > CIFSMaxBufSize: 16384 > Active VFS Requests: 0 > > Servers: > 1) ConnectionId: 0x1 Hostname: 192.168.20.241 > Number of credits: 8190 Dialect 0x311 > TCP status: 1 Instance: 1 > Local Users To Server: 1 SecMode: 0x1 Req On Wire: 0 > In Send: 0 In MaxReq Wait: 0 > > Sessions: > 1) Address: 192.168.20.241 Uses: 1 Capability: 0x300047 Session Status: 1 > Security type: RawNTLMSSP SessionId: 0xc962c9b5 > User: 0 Cred User: 0 > > Shares: > 0) IPC: \\192.168.20.241\IPC$ Mounts: 1 DevInfo: 0x0 Attributes: 0x0 > PathComponentMax: 0 Status: 0 type: 0 Serial Number: 0x0 > Share Capabilities: None Share Flags: 0x0 > tid: 0x6c21c0c4 Maximal Access: 0x1f00a9 > > 1) \\192.168.20.241\restricted Mounts: 1 DevInfo: 0x20 Attributes: 0x1006f > PathComponentMax: 255 Status: 0 type: DISK Serial Number: 0x57ccc1af > Share Capabilities: None Aligned, Partition Aligned, Share Flags: 0x0 > tid: 0x37af111c Optimal sector size: 0x200 Maximal Access: 0x1f01ff > > > MIDs: > -- > > Witness registrations: Attached are the CIFS debug logs for the patched kernel with kvm and io_uring-cp triggering the issue. Thanks and Best Regards, Fabi