Problematic interaction of io_uring and CIFS

Problematic interaction of io_uring and CIFS

[Fabian Ebner]

[-- Attachment #1: Type: text/plain, Size: 2852 bytes --]

(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

and, for 8ef12efe26c8:
> Jun 29 12:50:35 pve702 kernel: [   92.099496] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
> Jun 29 12:50:35 pve702 kernel: [   92.110467] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server

If there's any additional information I should provide, just let me know.

[0]: https://forum.proxmox.com/threads/110464/post-475858
[1]:
https://wiki.samba.org/index.php/LinuxCIFS_troubleshooting#Enabling_Debugging

[-- Attachment #2: kernel-5.18.6-cifs-dbg --]
[-- Type: text/plain, Size: 55717 bytes --]

Jun 29 11:25:38 pve702 kernel: [   86.558961] CIFS: fs/cifs/connect.c: RFC1002 header 0x1050
Jun 29 11:25:38 pve702 kernel: [   86.558965] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=2584 offset=360448 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.558967] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000658c0204 iov_len=0
Jun 29 11:25:38 pve702 kernel: [   86.558968] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000658c0204 iov_len=80
Jun 29 11:25:38 pve702 kernel: [   86.558970] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jun 29 11:25:38 pve702 kernel: [   86.558977] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jun 29 11:25:38 pve702 kernel: [   86.558979] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=2584 state=4 result=0 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.558982] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8190
Jun 29 11:25:38 pve702 kernel: [   86.559511] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8126
Jun 29 11:25:38 pve702 kernel: [   86.559515] CIFS: fs/cifs/smb2ops.c: smb2_adjust_credits: adjust added 63 credits total=8189
Jun 29 11:25:38 pve702 kernel: [   86.559516] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1376256 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.559522] CIFS: fs/cifs/transport.c: Sending smb: smb_len=117
Jun 29 11:25:38 pve702 kernel: [   86.559680] CIFS: fs/cifs/connect.c: RFC1002 header 0x1050
Jun 29 11:25:38 pve702 kernel: [   86.559684] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=2585 offset=1376256 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.559686] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000658c0204 iov_len=0
Jun 29 11:25:38 pve702 kernel: [   86.559688] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000658c0204 iov_len=80
Jun 29 11:25:38 pve702 kernel: [   86.559689] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jun 29 11:25:38 pve702 kernel: [   86.559697] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jun 29 11:25:38 pve702 kernel: [   86.559698] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=2585 state=4 result=0 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.559701] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8190
Jun 29 11:25:38 pve702 kernel: [   86.559838] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8126
Jun 29 11:25:38 pve702 kernel: [   86.559843] CIFS: fs/cifs/smb2ops.c: smb2_adjust_credits: adjust added 63 credits total=8189
Jun 29 11:25:38 pve702 kernel: [   86.559845] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=2424832 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.559850] CIFS: fs/cifs/transport.c: Sending smb: smb_len=117
Jun 29 11:25:38 pve702 kernel: [   86.559992] CIFS: fs/cifs/connect.c: RFC1002 header 0x1050
Jun 29 11:25:38 pve702 kernel: [   86.559997] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=2586 offset=2424832 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.559999] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000658c0204 iov_len=0
Jun 29 11:25:38 pve702 kernel: [   86.560000] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000658c0204 iov_len=80
Jun 29 11:25:38 pve702 kernel: [   86.560008] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jun 29 11:25:38 pve702 kernel: [   86.560013] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jun 29 11:25:38 pve702 kernel: [   86.560015] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=2586 state=4 result=0 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.560018] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8190
Jun 29 11:25:38 pve702 kernel: [   86.560261] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8126
Jun 29 11:25:38 pve702 kernel: [   86.560266] CIFS: fs/cifs/smb2ops.c: smb2_adjust_credits: adjust added 63 credits total=8189
Jun 29 11:25:38 pve702 kernel: [   86.560268] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=4521984 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.560286] CIFS: fs/cifs/transport.c: Sending smb: smb_len=117
Jun 29 11:25:38 pve702 kernel: [   86.560685] CIFS: fs/cifs/connect.c: RFC1002 header 0x1050
Jun 29 11:25:38 pve702 kernel: [   86.560693] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=2587 offset=4521984 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.560698] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000658c0204 iov_len=0
Jun 29 11:25:38 pve702 kernel: [   86.560701] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000658c0204 iov_len=80
Jun 29 11:25:38 pve702 kernel: [   86.560704] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jun 29 11:25:38 pve702 kernel: [   86.560710] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jun 29 11:25:38 pve702 kernel: [   86.560713] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=2587 state=4 result=0 bytes=4096
Jun 29 11:25:38 pve702 kernel: [   86.560720] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8190
Jun 29 11:25:39 pve702 kernel: [   86.790452] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 90 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790461] CIFS: fs/cifs/smb2pdu.c: async write at 1376256 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790479] CIFS: fs/cifs/smb2pdu.c: async write at 1380352 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790490] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 90) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790493] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 91 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790497] CIFS: fs/cifs/smb2pdu.c: async write at 3350528 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790521] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 91) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790523] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 92 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790526] CIFS: fs/cifs/smb2pdu.c: async write at 1612185600 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790572] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 92) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790575] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 93 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790577] CIFS: fs/cifs/smb2pdu.c: async write at 2149187584 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790619] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 93) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790622] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 94 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790624] CIFS: fs/cifs/smb2pdu.c: async write at 2149240832 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790639] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 94) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790641] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 95 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790642] CIFS: fs/cifs/smb2pdu.c: async write at 2149289984 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790685] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 95) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790691] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 96 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790693] CIFS: fs/cifs/smb2pdu.c: async write at 2152919040 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790719] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 96) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.790721] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 97 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.790723] CIFS: fs/cifs/smb2pdu.c: async write at 2180411392 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.790739] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 97) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.791244] smb2_calc_size: 17 callbacks suppressed
Jun 29 11:25:39 pve702 kernel: [   86.791249] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791253] smb2_check_message: 7 callbacks suppressed
Jun 29 11:25:39 pve702 kernel: [   86.791254] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2952
Jun 29 11:25:39 pve702 kernel: [   86.791271] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791273] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2953
Jun 29 11:25:39 pve702 kernel: [   86.791282] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791283] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2954
Jun 29 11:25:39 pve702 kernel: [   86.791495] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791498] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2955
Jun 29 11:25:39 pve702 kernel: [   86.791503] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791504] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2957
Jun 29 11:25:39 pve702 kernel: [   86.791507] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791507] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2958
Jun 29 11:25:39 pve702 kernel: [   86.791510] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791511] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2960
Jun 29 11:25:39 pve702 kernel: [   86.791513] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791514] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2959
Jun 29 11:25:39 pve702 kernel: [   86.791525] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jun 29 11:25:39 pve702 kernel: [   86.791526] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2956
Jun 29 11:25:39 pve702 kernel: [   86.791835] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 98 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.791839] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   86.791843] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   86.791848] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   86.793033] CIFS: fs/cifs/smb2misc.c: SMB2 len 73
Jun 29 11:25:39 pve702 kernel: [   86.793037] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8190
Jun 29 11:25:39 pve702 kernel: [   86.793975] cifs_sync_mid_result: 17 callbacks suppressed
Jun 29 11:25:39 pve702 kernel: [   86.793977] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=2961 state=4
Jun 29 11:25:39 pve702 kernel: [   86.793980] cifs_small_buf_release: 17 callbacks suppressed
Jun 29 11:25:39 pve702 kernel: [   86.793981] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   86.793983] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 98) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.795147] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 99 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.795152] CIFS: fs/cifs/smb2pdu.c: async write at 1612185600 4096 bytes
Jun 29 11:25:39 pve702 kernel: [   86.795212] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 99) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.795368] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 2963
Jun 29 11:25:39 pve702 kernel: [   86.795569] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 100 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.795572] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   86.795575] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   86.795577] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8188
Jun 29 11:25:39 pve702 kernel: [   86.796879] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   86.797013] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=2965 state=4
Jun 29 11:25:39 pve702 kernel: [   86.797016] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   86.797018] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 100) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.797445] CIFS: fs/cifs/file.c: VFS: in cifs_write_from_iter as Xid: 101 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.797474] CIFS: fs/cifs/file.c: VFS: leaving cifs_write_from_iter (xid = 101) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.797927] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 103 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.797931] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   86.797934] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   86.797936] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   86.799140] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8185
Jun 29 11:25:39 pve702 kernel: [   86.799439] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=2970 state=4
Jun 29 11:25:39 pve702 kernel: [   86.799443] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   86.799445] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 103) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.800540] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 105 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.800543] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   86.800546] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   86.800549] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8188
Jun 29 11:25:39 pve702 kernel: [   86.801753] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   86.801895] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=2979 state=4
Jun 29 11:25:39 pve702 kernel: [   86.801900] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   86.801903] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 105) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.806239] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 108 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.806243] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   86.806246] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   86.806248] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8180
Jun 29 11:25:39 pve702 kernel: [   86.807227] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8187
Jun 29 11:25:39 pve702 kernel: [   86.808350] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=3009 state=4
Jun 29 11:25:39 pve702 kernel: [   86.808354] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   86.808357] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 108) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.809283] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 110 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   86.809287] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   86.809290] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   86.809292] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   86.810474] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8190
Jun 29 11:25:39 pve702 kernel: [   86.810550] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=3021 state=4
Jun 29 11:25:39 pve702 kernel: [   86.810554] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   86.810557] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 110) rc = 0
Jun 29 11:25:39 pve702 kernel: [   86.899021] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8186
Jun 29 11:25:39 pve702 kernel: [   86.899610] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 3 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   87.245988] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 112 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.245994] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   87.245998] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   87.246001] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   87.247237] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8190
Jun 29 11:25:39 pve702 kernel: [   87.247814] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=4869 state=4
Jun 29 11:25:39 pve702 kernel: [   87.247821] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   87.247824] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 112) rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.402898] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 115 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.402906] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   87.402912] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   87.402919] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   87.404738] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=5272 state=4
Jun 29 11:25:39 pve702 kernel: [   87.404744] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   87.404746] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 115) rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.405322] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 117 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.405324] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   87.405327] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   87.405328] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   87.406579] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=5277 state=4
Jun 29 11:25:39 pve702 kernel: [   87.406582] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   87.406585] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 117) rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.410843] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 120 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.410846] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.qcow2 datasync: 0x1
Jun 29 11:25:39 pve702 kernel: [   87.410849] CIFS: fs/cifs/smb2pdu.c: flush
Jun 29 11:25:39 pve702 kernel: [   87.410851] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8189
Jun 29 11:25:39 pve702 kernel: [   87.412247] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=5284 state=4
Jun 29 11:25:39 pve702 kernel: [   87.412255] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jun 29 11:25:39 pve702 kernel: [   87.412260] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 120) rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.439910] CIFS: fs/cifs/transport.c: signal is pending after attempt to send
Jun 29 11:25:39 pve702 kernel: [   87.439920] CIFS: fs/cifs/transport.c: partial send (wanted=65652 sent=53364): terminating session
Jun 29 11:25:39 pve702 kernel: [   87.439970] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
Jun 29 11:25:39 pve702 kernel: [   87.440440] CIFS: fs/cifs/connect.c: Mark tcp session as need reconnect
Jun 29 11:25:39 pve702 kernel: [   87.440443] CIFS: fs/cifs/connect.c: cifs_mark_tcp_ses_conns_for_reconnect: marking necessary sessions and tcons for reconnect
Jun 29 11:25:39 pve702 kernel: [   87.440450] CIFS: fs/cifs/sess.c: Set reconnect bitmask for chan 0; now 0x1
Jun 29 11:25:39 pve702 kernel: [   87.440455] CIFS: fs/cifs/connect.c: cifs_abort_connection: tearing down socket
Jun 29 11:25:39 pve702 kernel: [   87.440457] CIFS: fs/cifs/connect.c: State: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.440460] CIFS: fs/cifs/connect.c: Post shutdown state: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.440493] CIFS: fs/cifs/connect.c: cifs_abort_connection: moving mids to private list
Jun 29 11:25:39 pve702 kernel: [   87.440495] CIFS: fs/cifs/connect.c: cifs_abort_connection: issuing mid callbacks
Jun 29 11:25:39 pve702 kernel: [   87.440506] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: probably server name is whole unc: \\192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.440514] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: unc is IP, skipping dns upcall: 192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.440516] CIFS: fs/cifs/connect.c: reconn_set_ipaddr_from_hostname: next dns resolution scheduled for 9088680469733379950 seconds in the future
Jun 29 11:25:39 pve702 kernel: [   87.440519] CIFS: fs/cifs/connect.c: __cifs_reconnect: reconn_set_ipaddr_from_hostname: rc=0
Jun 29 11:25:39 pve702 kernel: [   87.440526] CIFS: fs/cifs/connect.c: generic_ip_connect: connecting to 192.168.20.241:445
Jun 29 11:25:39 pve702 kernel: [   87.440547] CIFS: fs/cifs/connect.c: Socket created
Jun 29 11:25:39 pve702 kernel: [   87.440550] CIFS: fs/cifs/connect.c: sndbuf 16384 rcvbuf 131072 rcvtimeo 0x6d6
Jun 29 11:25:39 pve702 kernel: [   87.441300] CIFS: fs/cifs/smb2pdu.c: smb2_reconnect: aborting reconnect due to a received signal by the process
Jun 29 11:25:39 pve702 kernel: [   87.560702] CIFS: fs/cifs/smb2ops.c: smb2_set_credits: set 1 credits
Jun 29 11:25:39 pve702 kernel: [   87.560711] CIFS: fs/cifs/smb2ops.c: set credits to 1 due to smb2 reconnect
Jun 29 11:25:39 pve702 kernel: [   87.560734] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.560745] CIFS: fs/cifs/smb2pdu.c: Negotiate protocol
Jun 29 11:25:39 pve702 kernel: [   87.560752] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.560806] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jun 29 11:25:39 pve702 kernel: [   87.560808] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.565083] smb2_calc_size: 8 callbacks suppressed
Jun 29 11:25:39 pve702 kernel: [   87.565085] CIFS: fs/cifs/smb2misc.c: SMB2 data length 74 offset 128
Jun 29 11:25:39 pve702 kernel: [   87.565088] CIFS: fs/cifs/smb2misc.c: length of negcontexts 60 pad 6
Jun 29 11:25:39 pve702 kernel: [   87.565101] CIFS: fs/cifs/smb2pdu.c: mode 0x1
Jun 29 11:25:39 pve702 kernel: [   87.565103] CIFS: fs/cifs/smb2pdu.c: negotiated smb3.1.1 dialect
Jun 29 11:25:39 pve702 kernel: [   87.565109] CIFS: fs/cifs/smb2pdu.c: decoding 2 negotiate contexts
Jun 29 11:25:39 pve702 kernel: [   87.565110] CIFS: fs/cifs/smb2pdu.c: decode SMB3.11 encryption neg context of len 4
Jun 29 11:25:39 pve702 kernel: [   87.565111] CIFS: fs/cifs/smb2pdu.c: SMB311 cipher type:2
Jun 29 11:25:39 pve702 kernel: [   87.565114] CIFS: fs/cifs/connect.c: Free previous auth_key.response = 0000000061b01a87
Jun 29 11:25:39 pve702 kernel: [   87.565117] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.565119] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.565119] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.565121] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: 48b0efa2
Jun 29 11:25:39 pve702 kernel: [   87.565396] CIFS: fs/cifs/smb2misc.c: SMB2 data length 202 offset 72
Jun 29 11:25:39 pve702 kernel: [   87.565404] CIFS: Status code returned 0xc0000016 STATUS_MORE_PROCESSING_REQUIRED
Jun 29 11:25:39 pve702 kernel: [   87.565418] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000016 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.565422] CIFS: fs/cifs/sess.c: decode_ntlmssp_challenge: negotiate=0xe2088235 challenge=0xe28a8235
Jun 29 11:25:39 pve702 kernel: [   87.565426] CIFS: fs/cifs/smb2pdu.c: rawntlmssp session setup challenge phase
Jun 29 11:25:39 pve702 kernel: [   87.565427] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: 48b0efa2
Jun 29 11:25:39 pve702 kernel: [   87.571398] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 72
Jun 29 11:25:39 pve702 kernel: [   87.571426] CIFS: fs/cifs/smb2pdu.c: SMB2/3 session established successfully
Jun 29 11:25:39 pve702 kernel: [   87.571428] CIFS: fs/cifs/sess.c: Cleared reconnect bitmask for chan 0; now 0x0
Jun 29 11:25:39 pve702 kernel: [   87.571439] CIFS: fs/cifs/smb2pdu.c: TCON
Jun 29 11:25:39 pve702 kernel: [   87.572058] CIFS: fs/cifs/smb2pdu.c: connection to disk share
Jun 29 11:25:39 pve702 kernel: [   87.572064] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.572068] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.572069] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 132 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.572070] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.572071] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.572074] CIFS: fs/cifs/file.c: inode = 0x0000000065dff21a file flags 0xc002 for \images\109\vm-109-disk-0.qcow2
Jun 29 11:25:39 pve702 kernel: [   87.572075] CIFS: fs/cifs/smb2pdu.c: Binding to sess id: f7cd8472
Jun 29 11:25:39 pve702 kernel: [   87.572090] CIFS: fs/cifs/smb2pdu.c: create/open
Jun 29 11:25:39 pve702 kernel: [   87.572207] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
Jun 29 11:25:39 pve702 kernel: [   87.572220] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED
Jun 29 11:25:39 pve702 kernel: [   87.572228] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc00000d0 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.572233] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5
Jun 29 11:25:39 pve702 kernel: [   87.572453] CIFS: fs/cifs/smb2ops.c: trying to put 1 credits from the old server instance 1
Jun 29 11:25:39 pve702 kernel: [   87.572458] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 133 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.572468] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.572470] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.572472] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.572474] CIFS: fs/cifs/smb2pdu.c: Binding to sess id: f7cd8472
Jun 29 11:25:39 pve702 kernel: [   87.574196] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
Jun 29 11:25:39 pve702 kernel: [   87.574201] CIFS: fs/cifs/smb2ops.c: Session expired or deleted
Jun 29 11:25:39 pve702 kernel: [   87.574205] CIFS: fs/cifs/connect.c: Mark tcp session as need reconnect
Jun 29 11:25:39 pve702 kernel: [   87.574208] CIFS: fs/cifs/connect.c: cifs_mark_tcp_ses_conns_for_reconnect: marking necessary sessions and tcons for reconnect
Jun 29 11:25:39 pve702 kernel: [   87.574210] CIFS: fs/cifs/connect.c: cifs_abort_connection: tearing down socket
Jun 29 11:25:39 pve702 kernel: [   87.574211] CIFS: fs/cifs/connect.c: State: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.574225] CIFS: fs/cifs/connect.c: Post shutdown state: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.574250] CIFS: fs/cifs/connect.c: cifs_abort_connection: moving mids to private list
Jun 29 11:25:39 pve702 kernel: [   87.574252] CIFS: fs/cifs/connect.c: cifs_abort_connection: issuing mid callbacks
Jun 29 11:25:39 pve702 kernel: [   87.574259] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: probably server name is whole unc: \\192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.574262] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: unc is IP, skipping dns upcall: 192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.574265] CIFS: fs/cifs/connect.c: reconn_set_ipaddr_from_hostname: next dns resolution scheduled for 9088680469733379950 seconds in the future
Jun 29 11:25:39 pve702 kernel: [   87.574269] CIFS: fs/cifs/connect.c: __cifs_reconnect: reconn_set_ipaddr_from_hostname: rc=0
Jun 29 11:25:39 pve702 kernel: [   87.574271] CIFS: fs/cifs/connect.c: generic_ip_connect: connecting to 192.168.20.241:445
Jun 29 11:25:39 pve702 kernel: [   87.574321] CIFS: fs/cifs/connect.c: Socket created
Jun 29 11:25:39 pve702 kernel: [   87.574323] CIFS: fs/cifs/connect.c: sndbuf 16384 rcvbuf 131072 rcvtimeo 0x6d6
Jun 29 11:25:39 pve702 kernel: [   87.574349] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -11
Jun 29 11:25:39 pve702 kernel: [   87.574602] CIFS: fs/cifs/connect.c: cifs_put_tcon: tc_count=2
Jun 29 11:25:39 pve702 kernel: [   87.574609] CIFS: fs/cifs/smb2ops.c: smb2_set_credits: set 1 credits
Jun 29 11:25:39 pve702 kernel: [   87.574610] CIFS: fs/cifs/smb2ops.c: set credits to 1 due to smb2 reconnect
Jun 29 11:25:39 pve702 kernel: [   87.574618] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.574620] CIFS: fs/cifs/smb2pdu.c: Negotiate protocol
Jun 29 11:25:39 pve702 kernel: [   87.574679] CIFS: fs/cifs/file.c: cifs_reopen returned 0xfffffff5
Jun 29 11:25:39 pve702 kernel: [   87.574682] CIFS: fs/cifs/file.c: oplock: 2
Jun 29 11:25:39 pve702 kernel: [   87.574684] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 132) rc = -11
Jun 29 11:25:39 pve702 kernel: [   87.574686] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 134 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.574689] CIFS: fs/cifs/file.c: inode = 0x0000000065dff21a file flags 0xc002 for \images\109\vm-109-disk-0.qcow2
Jun 29 11:25:39 pve702 kernel: [   87.574732] CIFS: fs/cifs/smb2pdu.c: create/open
Jun 29 11:25:39 pve702 kernel: [   87.574736] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.580473] CIFS: fs/cifs/smb2misc.c: SMB2 data length 74 offset 128
Jun 29 11:25:39 pve702 kernel: [   87.580483] CIFS: fs/cifs/smb2misc.c: length of negcontexts 60 pad 6
Jun 29 11:25:39 pve702 kernel: [   87.580511] CIFS: fs/cifs/smb2pdu.c: mode 0x1
Jun 29 11:25:39 pve702 kernel: [   87.580513] CIFS: fs/cifs/smb2pdu.c: negotiated smb3.1.1 dialect
Jun 29 11:25:39 pve702 kernel: [   87.580518] CIFS: fs/cifs/smb2pdu.c: decoding 2 negotiate contexts
Jun 29 11:25:39 pve702 kernel: [   87.580520] CIFS: fs/cifs/smb2pdu.c: decode SMB3.11 encryption neg context of len 4
Jun 29 11:25:39 pve702 kernel: [   87.580522] CIFS: fs/cifs/smb2pdu.c: SMB311 cipher type:2
Jun 29 11:25:39 pve702 kernel: [   87.580524] CIFS: fs/cifs/connect.c: Free previous auth_key.response = 000000005b183786
Jun 29 11:25:39 pve702 kernel: [   87.580528] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.580530] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.580532] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.580535] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: f7cd8472
Jun 29 11:25:39 pve702 kernel: [   87.581045] CIFS: fs/cifs/smb2misc.c: SMB2 data length 202 offset 72
Jun 29 11:25:39 pve702 kernel: [   87.581056] CIFS: Status code returned 0xc0000016 STATUS_MORE_PROCESSING_REQUIRED
Jun 29 11:25:39 pve702 kernel: [   87.581063] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000016 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.581069] CIFS: fs/cifs/sess.c: decode_ntlmssp_challenge: negotiate=0xe2088235 challenge=0xe28a8235
Jun 29 11:25:39 pve702 kernel: [   87.581074] CIFS: fs/cifs/smb2pdu.c: rawntlmssp session setup challenge phase
Jun 29 11:25:39 pve702 kernel: [   87.581076] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: f7cd8472
Jun 29 11:25:39 pve702 kernel: [   87.587027] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 72
Jun 29 11:25:39 pve702 kernel: [   87.587055] CIFS: fs/cifs/smb2pdu.c: SMB2/3 session established successfully
Jun 29 11:25:39 pve702 kernel: [   87.587057] CIFS: fs/cifs/sess.c: Cleared reconnect bitmask for chan 0; now 0x0
Jun 29 11:25:39 pve702 kernel: [   87.587070] CIFS: fs/cifs/smb2pdu.c: TCON
Jun 29 11:25:39 pve702 kernel: [   87.587467] CIFS: fs/cifs/smb2pdu.c: connection to pipe share
Jun 29 11:25:39 pve702 kernel: [   87.587479] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.587483] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jun 29 11:25:39 pve702 kernel: [   87.587485] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jun 29 11:25:39 pve702 kernel: [   87.587487] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses ipc: \\192.168.20.241\IPC$
Jun 29 11:25:39 pve702 kernel: [   87.587488] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels finished
Jun 29 11:25:39 pve702 kernel: [   87.587491] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jun 29 11:25:39 pve702 kernel: [   87.587490] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.587493] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x0, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.587497] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.587500] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.587504] CIFS: fs/cifs/smb2pdu.c: Binding to sess id: 1128d761
Jun 29 11:25:39 pve702 kernel: [   87.587682] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
Jun 29 11:25:39 pve702 kernel: [   87.587704] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED
Jun 29 11:25:39 pve702 kernel: [   87.587710] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc00000d0 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.587714] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5
Jun 29 11:25:39 pve702 kernel: [   87.587889] CIFS: fs/cifs/file.c: cifs_reopen returned 0xfffffffb
Jun 29 11:25:39 pve702 kernel: [   87.587890] CIFS: fs/cifs/file.c: oplock: 2
Jun 29 11:25:39 pve702 kernel: [   87.587893] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 133) rc = -5
Jun 29 11:25:39 pve702 kernel: [   87.587897] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.587903] CIFS: fs/cifs/connect.c: cifs_put_tcon: tc_count=2
Jun 29 11:25:39 pve702 kernel: [   87.587906] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels finished
Jun 29 11:25:39 pve702 kernel: [   87.587908] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 135 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.587912] CIFS: fs/cifs/file.c: inode = 0x0000000065dff21a file flags 0xc002 for \images\109\vm-109-disk-0.qcow2
Jun 29 11:25:39 pve702 kernel: [   87.587921] CIFS: fs/cifs/smb2pdu.c: create/open
Jun 29 11:25:39 pve702 kernel: [   87.587924] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x0, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.587926] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.587935] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jun 29 11:25:39 pve702 kernel: [   87.587937] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x0, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.587938] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.587939] CIFS: fs/cifs/connect.c: cifs_put_tcon: tc_count=2
Jun 29 11:25:39 pve702 kernel: [   87.587941] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels finished
Jun 29 11:25:39 pve702 kernel: [   87.589450] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
Jun 29 11:25:39 pve702 kernel: [   87.589456] CIFS: fs/cifs/smb2ops.c: Session expired or deleted
Jun 29 11:25:39 pve702 kernel: [   87.589460] CIFS: fs/cifs/connect.c: Mark tcp session as need reconnect
Jun 29 11:25:39 pve702 kernel: [   87.589461] CIFS: fs/cifs/connect.c: cifs_mark_tcp_ses_conns_for_reconnect: marking necessary sessions and tcons for reconnect
Jun 29 11:25:39 pve702 kernel: [   87.589465] CIFS: fs/cifs/connect.c: cifs_abort_connection: tearing down socket
Jun 29 11:25:39 pve702 kernel: [   87.589467] CIFS: fs/cifs/connect.c: State: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.589484] CIFS: fs/cifs/connect.c: Post shutdown state: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.589492] CIFS: fs/cifs/connect.c: cifs_abort_connection: moving mids to private list
Jun 29 11:25:39 pve702 kernel: [   87.589494] CIFS: fs/cifs/connect.c: cifs_abort_connection: issuing mid callbacks
Jun 29 11:25:39 pve702 kernel: [   87.589502] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: probably server name is whole unc: \\192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.589506] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: unc is IP, skipping dns upcall: 192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.589509] CIFS: fs/cifs/connect.c: reconn_set_ipaddr_from_hostname: next dns resolution scheduled for 9088680469733379950 seconds in the future
Jun 29 11:25:39 pve702 kernel: [   87.589512] CIFS: fs/cifs/file.c: cifs_reopen returned 0xfffffff5
Jun 29 11:25:39 pve702 kernel: [   87.589512] CIFS: fs/cifs/connect.c: __cifs_reconnect: reconn_set_ipaddr_from_hostname: rc=0
Jun 29 11:25:39 pve702 kernel: [   87.589516] CIFS: fs/cifs/file.c: oplock: 2
Jun 29 11:25:39 pve702 kernel: [   87.589519] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 135) rc = -11
Jun 29 11:25:39 pve702 kernel: [   87.589520] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 136 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.589524] CIFS: fs/cifs/connect.c: generic_ip_connect: connecting to 192.168.20.241:445
Jun 29 11:25:39 pve702 kernel: [   87.589539] CIFS: fs/cifs/connect.c: Socket created
Jun 29 11:25:39 pve702 kernel: [   87.589540] CIFS: fs/cifs/connect.c: sndbuf 16384 rcvbuf 131072 rcvtimeo 0x6d6
Jun 29 11:25:39 pve702 kernel: [   87.589605] CIFS: fs/cifs/file.c: inode = 0x0000000065dff21a file flags 0xc002 for \images\109\vm-109-disk-0.qcow2
Jun 29 11:25:39 pve702 kernel: [   87.589620] CIFS: fs/cifs/smb2pdu.c: create/open
Jun 29 11:25:39 pve702 kernel: [   87.589681] CIFS: fs/cifs/smb2ops.c: smb2_set_credits: set 1 credits
Jun 29 11:25:39 pve702 kernel: [   87.589686] CIFS: fs/cifs/smb2ops.c: set credits to 1 due to smb2 reconnect
Jun 29 11:25:39 pve702 kernel: [   87.589701] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jun 29 11:25:39 pve702 kernel: [   87.589703] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.589706] CIFS: fs/cifs/smb2pdu.c: Negotiate protocol
Jun 29 11:25:39 pve702 kernel: [   87.589746] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jun 29 11:25:39 pve702 kernel: [   87.593779] CIFS: fs/cifs/smb2misc.c: length of negcontexts 60 pad 6
Jun 29 11:25:39 pve702 kernel: [   87.593794] CIFS: fs/cifs/smb2pdu.c: mode 0x1
Jun 29 11:25:39 pve702 kernel: [   87.593798] CIFS: fs/cifs/smb2pdu.c: negotiated smb3.1.1 dialect
Jun 29 11:25:39 pve702 kernel: [   87.593803] CIFS: fs/cifs/smb2pdu.c: decoding 2 negotiate contexts
Jun 29 11:25:39 pve702 kernel: [   87.593805] CIFS: fs/cifs/smb2pdu.c: decode SMB3.11 encryption neg context of len 4
Jun 29 11:25:39 pve702 kernel: [   87.593807] CIFS: fs/cifs/smb2pdu.c: SMB311 cipher type:2
Jun 29 11:25:39 pve702 kernel: [   87.593808] CIFS: fs/cifs/connect.c: Free previous auth_key.response = 000000005b183786
Jun 29 11:25:39 pve702 kernel: [   87.593812] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.593815] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.593816] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.593818] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: 1128d761
Jun 29 11:25:39 pve702 kernel: [   87.594110] CIFS: Status code returned 0xc0000016 STATUS_MORE_PROCESSING_REQUIRED
Jun 29 11:25:39 pve702 kernel: [   87.594117] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000016 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.594122] CIFS: fs/cifs/sess.c: decode_ntlmssp_challenge: negotiate=0xe2088235 challenge=0xe28a8235
Jun 29 11:25:39 pve702 kernel: [   87.594126] CIFS: fs/cifs/smb2pdu.c: rawntlmssp session setup challenge phase
Jun 29 11:25:39 pve702 kernel: [   87.594127] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: 1128d761
Jun 29 11:25:39 pve702 kernel: [   87.599700] CIFS: fs/cifs/smb2pdu.c: SMB2/3 session established successfully
Jun 29 11:25:39 pve702 kernel: [   87.599705] CIFS: fs/cifs/sess.c: Cleared reconnect bitmask for chan 0; now 0x0
Jun 29 11:25:39 pve702 kernel: [   87.599713] CIFS: fs/cifs/smb2pdu.c: TCON
Jun 29 11:25:39 pve702 kernel: [   87.600305] CIFS: fs/cifs/smb2pdu.c: connection to disk share
Jun 29 11:25:39 pve702 kernel: [   87.600311] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.600315] CIFS: fs/cifs/connect.c: cifs_put_tcon: tc_count=2
Jun 29 11:25:39 pve702 kernel: [   87.600336] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.600338] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.600340] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.600342] CIFS: fs/cifs/smb2pdu.c: Binding to sess id: 25423a26
Jun 29 11:25:39 pve702 kernel: [   87.600468] CIFS: Status code returned 0xc00000d0 STATUS_REQUEST_NOT_ACCEPTED
Jun 29 11:25:39 pve702 kernel: [   87.600474] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc00000d0 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.600477] CIFS: VFS: \\192.168.20.241 Send error in SessSetup = -5
Jun 29 11:25:39 pve702 kernel: [   87.600793] CIFS: fs/cifs/file.c: cifs_reopen returned 0xfffffffb
Jun 29 11:25:39 pve702 kernel: [   87.600794] CIFS: fs/cifs/file.c: oplock: 2
Jun 29 11:25:39 pve702 kernel: [   87.600796] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 134) rc = -5
Jun 29 11:25:39 pve702 kernel: [   87.600806] CIFS: fs/cifs/file.c: inode = 0x0000000065dff21a file flags 0xc002 for \images\109\vm-109-disk-0.qcow2
Jun 29 11:25:39 pve702 kernel: [   87.600812] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.600817] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jun 29 11:25:39 pve702 kernel: [   87.600819] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jun 29 11:25:39 pve702 kernel: [   87.600821] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses ipc: \\192.168.20.241\IPC$
Jun 29 11:25:39 pve702 kernel: [   87.600823] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels finished
Jun 29 11:25:39 pve702 kernel: [   87.600826] CIFS: fs/cifs/smb2pdu.c: create/open
Jun 29 11:25:39 pve702 kernel: [   87.601911] CIFS: fs/cifs/smb2ops.c: Session expired or deleted
Jun 29 11:25:39 pve702 kernel: [   87.601916] CIFS: fs/cifs/connect.c: Mark tcp session as need reconnect
Jun 29 11:25:39 pve702 kernel: [   87.601918] CIFS: fs/cifs/connect.c: cifs_mark_tcp_ses_conns_for_reconnect: marking necessary sessions and tcons for reconnect
Jun 29 11:25:39 pve702 kernel: [   87.601920] CIFS: fs/cifs/connect.c: cifs_abort_connection: tearing down socket
Jun 29 11:25:39 pve702 kernel: [   87.601922] CIFS: fs/cifs/connect.c: State: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.601945] CIFS: fs/cifs/connect.c: Post shutdown state: 0x3 Flags: 0x0
Jun 29 11:25:39 pve702 kernel: [   87.601951] CIFS: fs/cifs/connect.c: cifs_abort_connection: moving mids to private list
Jun 29 11:25:39 pve702 kernel: [   87.601952] CIFS: fs/cifs/connect.c: cifs_abort_connection: issuing mid callbacks
Jun 29 11:25:39 pve702 kernel: [   87.601958] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: probably server name is whole unc: \\192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.601960] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: unc is IP, skipping dns upcall: 192.168.20.241
Jun 29 11:25:39 pve702 kernel: [   87.601962] CIFS: fs/cifs/connect.c: reconn_set_ipaddr_from_hostname: next dns resolution scheduled for 9088680469733379950 seconds in the future
Jun 29 11:25:39 pve702 kernel: [   87.601966] CIFS: fs/cifs/connect.c: __cifs_reconnect: reconn_set_ipaddr_from_hostname: rc=0
Jun 29 11:25:39 pve702 kernel: [   87.601967] CIFS: fs/cifs/connect.c: generic_ip_connect: connecting to 192.168.20.241:445
Jun 29 11:25:39 pve702 kernel: [   87.601975] CIFS: fs/cifs/file.c: cifs_reopen returned 0xfffffff5
Jun 29 11:25:39 pve702 kernel: [   87.601975] CIFS: fs/cifs/connect.c: Socket created
Jun 29 11:25:39 pve702 kernel: [   87.601978] CIFS: fs/cifs/connect.c: sndbuf 16384 rcvbuf 131072 rcvtimeo 0x6d6
Jun 29 11:25:39 pve702 kernel: [   87.601979] CIFS: fs/cifs/file.c: oplock: 2
Jun 29 11:25:39 pve702 kernel: [   87.601982] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 136) rc = -11
Jun 29 11:25:39 pve702 kernel: [   87.601986] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 137 with uid: 0
Jun 29 11:25:39 pve702 kernel: [   87.601988] CIFS: fs/cifs/file.c: inode = 0x0000000065dff21a file flags 0xc002 for \images\109\vm-109-disk-0.qcow2
Jun 29 11:25:39 pve702 kernel: [   87.601993] CIFS: fs/cifs/smb2pdu.c: create/open
Jun 29 11:25:39 pve702 kernel: [   87.601994] CIFS: fs/cifs/smb2pdu.c: smb2_reconnect: aborting reconnect due to a received signal by the process
Jun 29 11:25:39 pve702 kernel: [   87.601996] CIFS: fs/cifs/file.c: cifs_reopen returned 0xfffffe00
Jun 29 11:25:39 pve702 kernel: [   87.601997] CIFS: fs/cifs/file.c: oplock: 2
Jun 29 11:25:39 pve702 kernel: [   87.601998] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 137) rc = -512
Jun 29 11:25:39 pve702 kernel: [   87.602105] CIFS: fs/cifs/smb2ops.c: smb2_set_credits: set 1 credits
Jun 29 11:25:39 pve702 kernel: [   87.602109] CIFS: fs/cifs/smb2ops.c: set credits to 1 due to smb2 reconnect
Jun 29 11:25:39 pve702 kernel: [   87.602118] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jun 29 11:25:39 pve702 kernel: [   87.602122] CIFS: fs/cifs/smb2pdu.c: Negotiate protocol
Jun 29 11:25:39 pve702 kernel: [   87.606178] CIFS: fs/cifs/smb2misc.c: length of negcontexts 60 pad 6
Jun 29 11:25:39 pve702 kernel: [   87.612152] CIFS: fs/cifs/smb2pdu.c: mode 0x1
Jun 29 11:25:39 pve702 kernel: [   87.612160] CIFS: fs/cifs/smb2pdu.c: negotiated smb3.1.1 dialect
Jun 29 11:25:39 pve702 kernel: [   87.612166] CIFS: fs/cifs/smb2pdu.c: decoding 2 negotiate contexts
Jun 29 11:25:39 pve702 kernel: [   87.612168] CIFS: fs/cifs/smb2pdu.c: decode SMB3.11 encryption neg context of len 4
Jun 29 11:25:39 pve702 kernel: [   87.612170] CIFS: fs/cifs/smb2pdu.c: SMB311 cipher type:2
Jun 29 11:25:39 pve702 kernel: [   87.612172] CIFS: fs/cifs/connect.c: Free previous auth_key.response = 000000005b183786
Jun 29 11:25:39 pve702 kernel: [   87.612177] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jun 29 11:25:39 pve702 kernel: [   87.612180] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jun 29 11:25:39 pve702 kernel: [   87.612182] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jun 29 11:25:39 pve702 kernel: [   87.612186] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: 25423a26
Jun 29 11:25:39 pve702 kernel: [   87.620054] CIFS: Status code returned 0xc0000016 STATUS_MORE_PROCESSING_REQUIRED
Jun 29 11:25:39 pve702 kernel: [   87.620065] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000016 to POSIX err -5
Jun 29 11:25:39 pve702 kernel: [   87.620073] CIFS: fs/cifs/sess.c: decode_ntlmssp_challenge: negotiate=0xe2088235 challenge=0xe28a8235
Jun 29 11:25:39 pve702 kernel: [   87.620077] CIFS: fs/cifs/smb2pdu.c: rawntlmssp session setup challenge phase
Jun 29 11:25:39 pve702 kernel: [   87.620080] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: 25423a26
Jun 29 11:25:39 pve702 kernel: [   87.626394] CIFS: fs/cifs/smb2pdu.c: SMB2/3 session established successfully
Jun 29 11:25:39 pve702 kernel: [   87.626400] CIFS: fs/cifs/sess.c: Cleared reconnect bitmask for chan 0; now 0x0
Jun 29 11:25:39 pve702 kernel: [   87.626407] CIFS: fs/cifs/smb2pdu.c: TCON
Jun 29 11:25:39 pve702 kernel: [   87.627083] CIFS: fs/cifs/smb2pdu.c: connection to disk share
Jun 29 11:25:39 pve702 kernel: [   87.627089] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.627093] CIFS: fs/cifs/connect.c: cifs_put_tcon: tc_count=2
Jun 29 11:25:39 pve702 kernel: [   87.627097] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jun 29 11:25:39 pve702 kernel: [   87.627099] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jun 29 11:25:39 pve702 kernel: [   87.627100] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jun 29 11:25:39 pve702 kernel: [   87.627101] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses ipc: \\192.168.20.241\IPC$
Jun 29 11:25:39 pve702 kernel: [   87.627103] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels finished
Jun 29 11:25:40 pve702 kernel: [   87.931326] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 138 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.931335] CIFS: fs/cifs/inode.c: Update attributes:  inode 0x0000000040c6d6b7 count 1 dentry: 0x00000000e37f44f0 d_time 0 jiffies 4294914258
Jun 29 11:25:40 pve702 kernel: [   87.932294] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 319
Jun 29 11:25:40 pve702 kernel: [   87.932297] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 319 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.932300] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 138) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.934147] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 139 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.934152] CIFS: fs/cifs/inode.c: Update attributes: \dump inode 0x00000000cf25111c count 1 dentry: 0x000000006242bdd1 d_time 4294897571 jiffies 4294914259
Jun 29 11:25:40 pve702 kernel: [   87.934797] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 11001916822272032900
Jun 29 11:25:40 pve702 kernel: [   87.934800] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 11001916822272032900 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.934802] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 139) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.934817] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 140 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.934819] CIFS: fs/cifs/inode.c: Update attributes: \private inode 0x00000000e90c88c2 count 1 dentry: 0x0000000066982e92 d_time 4294897572 jiffies 4294914259
Jun 29 11:25:40 pve702 kernel: [   87.935117] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 113
Jun 29 11:25:40 pve702 kernel: [   87.935119] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 113 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.935120] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 140) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.935132] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 141 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.935133] CIFS: fs/cifs/inode.c: Update attributes: \template inode 0x00000000bbb749ac count 1 dentry: 0x000000006c9ccc4a d_time 4294897572 jiffies 4294914259
Jun 29 11:25:40 pve702 kernel: [   87.935422] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 114
Jun 29 11:25:40 pve702 kernel: [   87.935424] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 114 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.935425] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 141) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.935427] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 142 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.935428] CIFS: fs/cifs/inode.c: Update attributes: \template\cache inode 0x0000000019253485 count 1 dentry: 0x000000005c653f96 d_time 4294897572 jiffies 4294914259
Jun 29 11:25:40 pve702 kernel: [   87.935747] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 115
Jun 29 11:25:40 pve702 kernel: [   87.935749] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 115 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.935750] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 142) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.935762] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 143 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.935764] CIFS: fs/cifs/inode.c: Update attributes: \template\iso inode 0x000000003e8e4a38 count 1 dentry: 0x00000000335cbebc d_time 4294897572 jiffies 4294914259
Jun 29 11:25:40 pve702 kernel: [   87.936052] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 116
Jun 29 11:25:40 pve702 kernel: [   87.936054] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 116 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.936055] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 143) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.936066] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 144 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.936068] CIFS: fs/cifs/inode.c: Update attributes: \snippets inode 0x000000001bee8638 count 1 dentry: 0x0000000062920d50 d_time 4294897572 jiffies 4294914259
Jun 29 11:25:40 pve702 kernel: [   87.936607] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 117
Jun 29 11:25:40 pve702 kernel: [   87.936610] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 117 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.936611] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 144) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.936628] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 145 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.936630] CIFS: fs/cifs/inode.c: Update attributes: \images inode 0x00000000d1e72e2b count 1 dentry: 0x00000000d2161375 d_time 4294910159 jiffies 4294914260
Jun 29 11:25:40 pve702 kernel: [   87.936915] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 118
Jun 29 11:25:40 pve702 kernel: [   87.936917] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 118 is unchanged
Jun 29 11:25:40 pve702 kernel: [   87.936918] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 145) rc = 0
Jun 29 11:25:40 pve702 kernel: [   87.938299] CIFS: fs/cifs/cifsfs.c: VFS: in cifs_statfs as Xid: 146 with uid: 0
Jun 29 11:25:40 pve702 kernel: [   87.938896] CIFS: fs/cifs/cifsfs.c: VFS: leaving cifs_statfs (xid = 146) rc = 0

[-- Attachment #3: kernel-5.18.6-qemu-trace --]
[-- Type: text/plain, Size: 2330 bytes --]

luring_co_submit bs 0x55d65e397f70 s 0x55d65e39f210 luringcb 0x7f7e5f0f2800 fd 16 offset 3635503104 nbytes 4096 type 1
luring_do_submit LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 1 inflight 0
luring_co_submit bs 0x55d65e397f70 s 0x55d65e39f210 luringcb 0x7f7e5f2f4800 fd 16 offset 848687104 nbytes 12288 type 1
luring_do_submit LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 2 inflight 0
luring_io_unplug LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 2 inflight 0
luring_io_uring_submit LuringState 0x55d65e39f210 ret 2
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5f0f2800 ret 4096
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5f2f4800 ret 12288
luring_io_plug LuringState 0x55d65e39f210 plug
luring_co_submit bs 0x55d65e397f70 s 0x55d65e39f210 luringcb 0x7f7e5eff1640 fd 16 offset 3494113280 nbytes 4096 type 2
luring_do_submit LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 1 inflight 0
luring_co_submit bs 0x55d65e397f70 s 0x55d65e39f210 luringcb 0x7f7e5eef0640 fd 16 offset 190185472 nbytes 1310720 type 2
luring_do_submit LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 2 inflight 0
luring_co_submit bs 0x55d65e397f70 s 0x55d65e39f210 luringcb 0x7f7e5edef640 fd 16 offset 191496192 nbytes 323584 type 2
luring_do_submit LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 3 inflight 0
luring_io_unplug LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 3 inflight 0
luring_io_uring_submit LuringState 0x55d65e39f210 ret 3
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5eff1640 ret 4096
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5edef640 ret -4
luring_io_plug LuringState 0x55d65e39f210 plug
luring_co_submit bs 0x55d65e397f70 s 0x55d65e39f210 luringcb 0x7f7e5ecee800 fd 16 offset 3495968768 nbytes 4096 type 1
luring_do_submit LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 2 inflight 1
luring_io_unplug LuringState 0x55d65e39f210 blocked 0 plugged 1 queued 2 inflight 1
luring_io_uring_submit LuringState 0x55d65e39f210 ret 2
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5edef640 ret -5
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5eef0640 ret -5
luring_process_completion LuringState 0x55d65e39f210 luringcb 0x7f7e5ecee800 ret -4

Re: Problematic interaction of io_uring and CIFS

[Enzo Matsumiya]

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.

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
180 Jun 29 11:25:39 pve702 kernel: [   87.439970] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
<cifs marks all sessions and tcons for reconnect and gets in the
erroneous reconnect loop as shown above>


Cheers,

Enzo

Re: Problematic interaction of io_uring and CIFS

[Shyam Prasad N]

On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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.
>
> 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
> 180 Jun 29 11:25:39 pve702 kernel: [   87.439970] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
> <cifs marks all sessions and tcons for reconnect and gets in the
> 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?
Also, what server are you using? Has that changed across these attempts?

Can you please dump the output of:
cat /proc/fs/cifs/DebugData
when the issue is happening?

-- 
Regards,
Shyam

Re: Problematic interaction of io_uring and CIFS

[Shyam Prasad N]

On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <nspmangalore@gmail.com> wrote:
>
> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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.
> >
> > 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.

> > 180 Jun 29 11:25:39 pve702 kernel: [   87.439970] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
> > <cifs marks all sessions and tcons for reconnect and gets in the
> > 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?
> Also, what server are you using? Has that changed across these attempts?
>
> Can you please dump the output of:
> cat /proc/fs/cifs/DebugData
> when the issue is happening?
>
> --
> Regards,
> Shyam



-- 
Regards,
Shyam

Re: Problematic interaction of io_uring and CIFS

[Fabian Ebner]

[-- Attachment #1: Type: text/plain, Size: 7971 bytes --]

Am 09.07.22 um 05:39 schrieb Shyam Prasad N:
> On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <nspmangalore@gmail.com> wrote:
>>
>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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
>>> <cifs marks all sessions and tcons for reconnect and gets in the
>>> 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

[-- Attachment #2: kernel-5.18.6-patched-io-uring-cp --]
[-- Type: text/plain, Size: 18329 bytes --]

Jul 11 12:17:06 pve702 kernel: [  865.202505] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 903 with uid: 0
Jul 11 12:17:06 pve702 kernel: [  865.202513] CIFS: fs/cifs/inode.c: Update attributes: \file inode 0x00000000f4340c2c count 1 dentry: 0x00000000b32eb9bd d_time 0 jiffies 4295108498
Jul 11 12:17:06 pve702 kernel: [  865.202534] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 3 credits total=8189
Jul 11 12:17:06 pve702 kernel: [  865.202543] CIFS: fs/cifs/transport.c: Sending smb: smb_len=356
Jul 11 12:17:06 pve702 kernel: [  865.203220] CIFS: fs/cifs/connect.c: RFC1002 header 0x208
Jul 11 12:17:06 pve702 kernel: [  865.203235] smb2_calc_size: 8 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.203238] CIFS: fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
Jul 11 12:17:06 pve702 kernel: [  865.203242] smb2_calc_size: 17 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.203243] CIFS: fs/cifs/smb2misc.c: SMB2 len 208
Jul 11 12:17:06 pve702 kernel: [  865.203248] smb2_add_credits: 17 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.203268] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=8189
Jul 11 12:17:06 pve702 kernel: [  865.203276] CIFS: fs/cifs/smb2misc.c: SMB2 data length 110 offset 72
Jul 11 12:17:06 pve702 kernel: [  865.203277] CIFS: fs/cifs/smb2misc.c: SMB2 len 182
Jul 11 12:17:06 pve702 kernel: [  865.203279] smb2_check_message: 7 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.203280] CIFS: fs/cifs/smb2misc.c: Calculated size 182 length 184 mismatch mid 1086
Jul 11 12:17:06 pve702 kernel: [  865.203282] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=8189
Jul 11 12:17:06 pve702 kernel: [  865.203286] CIFS: fs/cifs/smb2misc.c: SMB2 len 124
Jul 11 12:17:06 pve702 kernel: [  865.203287] CIFS: fs/cifs/smb2misc.c: Calculated size 124 length 128 mismatch mid 1087
Jul 11 12:17:06 pve702 kernel: [  865.203289] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 3 credits total=8192
Jul 11 12:17:06 pve702 kernel: [  865.203301] cifs_sync_mid_result: 17 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.203303] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=1085 state=4
Jul 11 12:17:06 pve702 kernel: [  865.203306] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=1086 state=4
Jul 11 12:17:06 pve702 kernel: [  865.203308] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=1087 state=4
Jul 11 12:17:06 pve702 kernel: [  865.203310] cifs_small_buf_release: 17 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.203311] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.203313] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.203314] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.203323] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 119
Jul 11 12:17:06 pve702 kernel: [  865.203325] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: invalidating inode 119 mapping
Jul 11 12:17:06 pve702 kernel: [  865.203329] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 903) rc = 0
Jul 11 12:17:06 pve702 kernel: [  865.278590] CIFS: fs/cifs/file.c: VFS: in cifs_open as Xid: 904 with uid: 0
Jul 11 12:17:06 pve702 kernel: [  865.278600] CIFS: fs/cifs/file.c: inode = 0x00000000f4340c2c file flags are 0x8241 for \file
Jul 11 12:17:06 pve702 kernel: [  865.278618] CIFS: fs/cifs/smb2pdu.c: create/open
Jul 11 12:17:06 pve702 kernel: [  865.278624] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8191
Jul 11 12:17:06 pve702 kernel: [  865.278644] CIFS: fs/cifs/transport.c: Sending smb: smb_len=284
Jul 11 12:17:06 pve702 kernel: [  865.279552] CIFS: fs/cifs/connect.c: RFC1002 header 0x11c
Jul 11 12:17:06 pve702 kernel: [  865.279560] CIFS: fs/cifs/smb2misc.c: SMB2 data length 132 offset 152
Jul 11 12:17:06 pve702 kernel: [  865.279562] CIFS: fs/cifs/smb2misc.c: SMB2 len 284
Jul 11 12:17:06 pve702 kernel: [  865.279566] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8192
Jul 11 12:17:06 pve702 kernel: [  865.279575] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=1088 state=4
Jul 11 12:17:06 pve702 kernel: [  865.279579] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.279582] CIFS: fs/cifs/smb2pdu.c: parse query id context 0x98b2f9b6c4e8ee38 0x26
Jul 11 12:17:06 pve702 kernel: [  865.279687] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 119
Jul 11 12:17:06 pve702 kernel: [  865.279690] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 119 is unchanged
Jul 11 12:17:06 pve702 kernel: [  865.279694] CIFS: fs/cifs/smb2ops.c: RHW Lease granted on inode 00000000f4340c2c
Jul 11 12:17:06 pve702 kernel: [  865.279696] CIFS: fs/cifs/file.c: VFS: leaving cifs_open (xid = 904) rc = 0
Jul 11 12:17:06 pve702 kernel: [  865.279702] CIFS: fs/cifs/inode.c: VFS: in cifs_setattr_nounix as Xid: 905 with uid: 0
Jul 11 12:17:06 pve702 kernel: [  865.279704] CIFS: fs/cifs/inode.c: setattr on file file attrs->ia_valid 0xa068
Jul 11 12:17:06 pve702 kernel: [  865.279707] CIFS: fs/cifs/smb2pdu.c: flush
Jul 11 12:17:06 pve702 kernel: [  865.279709] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8191
Jul 11 12:17:06 pve702 kernel: [  865.279714] CIFS: fs/cifs/transport.c: Sending smb: smb_len=92
Jul 11 12:17:06 pve702 kernel: [  865.280988] CIFS: fs/cifs/connect.c: RFC1002 header 0x49
Jul 11 12:17:06 pve702 kernel: [  865.280993] CIFS: fs/cifs/smb2misc.c: SMB2 len 73
Jul 11 12:17:06 pve702 kernel: [  865.280995] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 1 credits total=8192
Jul 11 12:17:06 pve702 kernel: [  865.281664] CIFS: fs/cifs/connect.c: RFC1002 header 0x44
Jul 11 12:17:06 pve702 kernel: [  865.281668] CIFS: fs/cifs/smb2misc.c: SMB2 len 68
Jul 11 12:17:06 pve702 kernel: [  865.281670] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=8192
Jul 11 12:17:06 pve702 kernel: [  865.281678] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=1089 state=4
Jul 11 12:17:06 pve702 kernel: [  865.281680] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.281697] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8191
Jul 11 12:17:06 pve702 kernel: [  865.281702] CIFS: fs/cifs/transport.c: Sending smb: smb_len=108
Jul 11 12:17:06 pve702 kernel: [  865.281789] CIFS: fs/cifs/connect.c: RFC1002 header 0x42
Jul 11 12:17:06 pve702 kernel: [  865.281792] CIFS: fs/cifs/smb2misc.c: SMB2 len 66
Jul 11 12:17:06 pve702 kernel: [  865.281794] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8192
Jul 11 12:17:06 pve702 kernel: [  865.281800] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=17 mid=1090 state=4
Jul 11 12:17:06 pve702 kernel: [  865.281802] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.281804] CIFS: fs/cifs/inode.c: SetFSize for attrs rc = 0
Jul 11 12:17:06 pve702 kernel: [  865.281817] CIFS: fs/cifs/inode.c: CIFS - CTIME changed
Jul 11 12:17:06 pve702 kernel: [  865.281821] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=8191
Jul 11 12:17:06 pve702 kernel: [  865.281825] CIFS: fs/cifs/transport.c: Sending smb: smb_len=140
Jul 11 12:17:06 pve702 kernel: [  865.281945] CIFS: fs/cifs/connect.c: RFC1002 header 0x42
Jul 11 12:17:06 pve702 kernel: [  865.281949] CIFS: fs/cifs/smb2misc.c: SMB2 len 66
Jul 11 12:17:06 pve702 kernel: [  865.281951] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 1 credits total=8192
Jul 11 12:17:06 pve702 kernel: [  865.281957] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=17 mid=1091 state=4
Jul 11 12:17:06 pve702 kernel: [  865.281959] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.281964] CIFS: fs/cifs/inode.c: VFS: leaving cifs_setattr_nounix (xid = 905) rc = 0
Jul 11 12:17:06 pve702 kernel: [  865.283560] cifs_write_begin: 236166 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.283564] CIFS: fs/cifs/file.c: write_begin from 0 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283569] cifs_write_end: 236166 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.283570] CIFS: fs/cifs/file.c: write_end for page 00000000f8aa1049 from pos 0 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283576] CIFS: fs/cifs/file.c: write_begin from 4096 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283589] CIFS: fs/cifs/file.c: write_end for page 000000005169ec85 from pos 4096 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283592] CIFS: fs/cifs/file.c: write_begin from 8192 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283595] CIFS: fs/cifs/file.c: write_end for page 00000000a626e831 from pos 8192 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283599] CIFS: fs/cifs/file.c: write_begin from 12288 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283603] CIFS: fs/cifs/file.c: write_end for page 000000002beab1fc from pos 12288 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283607] CIFS: fs/cifs/file.c: write_begin from 16384 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283611] CIFS: fs/cifs/file.c: write_end for page 00000000db0ea6c7 from pos 16384 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283614] CIFS: fs/cifs/file.c: write_begin from 20480 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283617] CIFS: fs/cifs/file.c: write_end for page 000000008e21eb2b from pos 20480 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283619] CIFS: fs/cifs/file.c: write_begin from 24576 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283622] CIFS: fs/cifs/file.c: write_end for page 000000000475781b from pos 24576 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283624] CIFS: fs/cifs/file.c: write_begin from 28672 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283627] CIFS: fs/cifs/file.c: write_end for page 00000000733eeb02 from pos 28672 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283642] CIFS: fs/cifs/file.c: write_begin from 32768 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283645] CIFS: fs/cifs/file.c: write_end for page 00000000c3ed1a59 from pos 32768 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.283646] CIFS: fs/cifs/file.c: write_begin from 36864 len 4096
Jul 11 12:17:06 pve702 kernel: [  865.283649] CIFS: fs/cifs/file.c: write_end for page 00000000d9d75786 from pos 36864 with 4096 bytes
Jul 11 12:17:06 pve702 kernel: [  865.646780] cifs_writepages: 7 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.646785] CIFS: fs/cifs/file.c: VFS: in cifs_writepages as Xid: 906 with uid: 0
Jul 11 12:17:06 pve702 kernel: [  865.646793] smb2_wait_mtu_credits: 210 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.646795] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:06 pve702 kernel: [  865.647145] CIFS: fs/cifs/smb2pdu.c: async write at 0 4194304 bytes
Jul 11 12:17:06 pve702 kernel: [  865.647159] CIFS: fs/cifs/transport.c: Sending smb: smb_len=4194420
Jul 11 12:17:06 pve702 kernel: [  865.647245] CIFS: fs/cifs/transport.c: signal is pending after attempt to send
Jul 11 12:17:06 pve702 kernel: [  865.647247] CIFS: fs/cifs/transport.c: partial send (wanted=4194420 sent=143476): terminating session
Jul 11 12:17:06 pve702 kernel: [  865.647250] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
Jul 11 12:17:06 pve702 kernel: [  865.647279] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:06 pve702 kernel: [  865.647663] cifs_writepages: 7 callbacks suppressed
Jul 11 12:17:06 pve702 kernel: [  865.647663] CIFS: fs/cifs/file.c: VFS: leaving cifs_writepages (xid = 906) rc = -512
Jul 11 12:17:06 pve702 kernel: [  865.647666] CIFS: fs/cifs/file.c: Flush inode 00000000f4340c2c file 00000000f4d1ed5a rc -512
Jul 11 12:17:07 pve702 kernel: [  866.664757] CIFS: fs/cifs/file.c: closing last open instance for inode 00000000f4340c2c
Jul 11 12:17:07 pve702 kernel: [  866.664765] CIFS: fs/cifs/file.c: VFS: in _cifsFileInfo_put as Xid: 907 with uid: 0
Jul 11 12:17:07 pve702 kernel: [  866.664770] CIFS: fs/cifs/smb2pdu.c: Close
Jul 11 12:17:07 pve702 kernel: [  866.664773] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:10 pve702 kernel: [  869.772194] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 908 with uid: 0
Jul 11 12:17:10 pve702 kernel: [  869.772203] CIFS: fs/cifs/inode.c: Update attributes:  inode 0x00000000397399f0 count 1 dentry: 0x00000000cb312abc d_time 0 jiffies 4295109640
Jul 11 12:17:11 pve702 kernel: [  870.504711] CIFS: fs/cifs/file.c: VFS: in cifs_writepages as Xid: 909 with uid: 0
Jul 11 12:17:11 pve702 kernel: [  870.504721] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.505046] cifs_writepages: 208 callbacks suppressed
Jul 11 12:17:11 pve702 kernel: [  870.505048] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.505304] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.505616] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.505856] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.506168] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.506408] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.506735] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.506975] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.507283] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.507523] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.507816] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.508056] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.508351] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.508582] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.508915] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.509133] CIFS: fs/cifs/smb2ops.c: smb2_wait_mtu_credits: removed 64 credits total=8128
Jul 11 12:17:11 pve702 kernel: [  870.513053] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.513614] CIFS: VFS: No writable handle in writepages rc=-9
Jul 11 12:17:11 pve702 kernel: [  870.514956] CIFS: fs/cifs/file.c: VFS: leaving cifs_writepages (xid = 909) rc = -9
Jul 11 12:17:12 pve702 pvestatd[1498]: got timeout
Jul 11 12:17:12 pve702 pvestatd[1498]: unable to activate storage 'mysmb' - directory '/mnt/pve/mysmb' does not exist or is unreachable
Jul 11 12:17:12 pve702 kernel: [  871.772720] CIFS: fs/cifs/smb2pdu.c: smb2_reconnect: aborting reconnect due to a received signal by the process
Jul 11 12:17:12 pve702 kernel: [  871.772731] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 12:17:12 pve702 kernel: [  871.772737] CIFS: fs/cifs/inode.c: cifs_get_inode_info: unhandled err rc -512
Jul 11 12:17:12 pve702 kernel: [  871.772742] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 908) rc = -512
Jul 11 12:17:13 pve702 kernel: [  872.296700] CIFS: fs/cifs/connect.c: Mark tcp session as need reconnect
Jul 11 12:17:13 pve702 kernel: [  872.296707] CIFS: fs/cifs/connect.c: cifs_mark_tcp_ses_conns_for_reconnect: marking necessary sessions and tcons for reconnect
Jul 11 12:17:13 pve702 kernel: [  872.296710] CIFS: fs/cifs/sess.c: Set reconnect bitmask for chan 0; now 0x1
Jul 11 12:17:13 pve702 kernel: [  872.296713] CIFS: fs/cifs/connect.c: cifs_abort_connection: tearing down socket
Jul 11 12:17:13 pve702 kernel: [  872.296714] CIFS: fs/cifs/connect.c: State: 0x3 Flags: 0x0
Jul 11 12:17:13 pve702 kernel: [  872.296756] CIFS: fs/cifs/connect.c: Post shutdown state: 0x3 Flags: 0x0
Jul 11 12:17:13 pve702 kernel: [  872.296763] CIFS: fs/cifs/connect.c: cifs_abort_connection: moving mids to private list
Jul 11 12:17:13 pve702 kernel: [  872.296764] CIFS: fs/cifs/connect.c: cifs_abort_connection: issuing mid callbacks
Jul 11 12:17:13 pve702 kernel: [  872.296767] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: probably server name is whole unc: \\192.168.20.241
Jul 11 12:17:13 pve702 kernel: [  872.296770] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: unc is IP, skipping dns upcall: 192.168.20.241
Jul 11 12:17:13 pve702 kernel: [  872.296772] CIFS: fs/cifs/connect.c: reconn_set_ipaddr_from_hostname: next dns resolution scheduled for 600 seconds in the future
Jul 11 12:17:13 pve702 kernel: [  872.296775] CIFS: fs/cifs/connect.c: __cifs_reconnect: reconn_set_ipaddr_from_hostname: rc=0
Jul 11 12:17:13 pve702 kernel: [  872.296776] CIFS: fs/cifs/connect.c: generic_ip_connect: connecting to 192.168.20.241:445
Jul 11 12:17:13 pve702 kernel: [  872.296786] CIFS: fs/cifs/connect.c: Socket created
Jul 11 12:17:13 pve702 kernel: [  872.296787] CIFS: fs/cifs/connect.c: sndbuf 16384 rcvbuf 131072 rcvtimeo 0x6d6
Jul 11 12:17:13 pve702 kernel: [  872.297150] CIFS: fs/cifs/smb2ops.c: smb2_set_credits: set 1 credits
Jul 11 12:17:13 pve702 kernel: [  872.297153] CIFS: fs/cifs/smb2ops.c: set credits to 1 due to smb2 reconnect
Jul 11 12:17:13 pve702 kernel: [  872.297164] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jul 11 12:17:13 pve702 kernel: [  872.297166] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jul 11 12:17:13 pve702 kernel: [  872.297170] CIFS: fs/cifs/smb2pdu.c: Negotiate protocol


[-- Attachment #3: kernel-5.18.6-patched-kvm --]
[-- Type: text/plain, Size: 27407 bytes --]

Jul 11 15:10:12 pve702 kernel: [ 5884.322632] smb2_async_readv: 287 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.322638] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901592576 bytes=16384
Jul 11 15:10:12 pve702 kernel: [ 5884.323235] cifs_readv_receive: 343 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.323237] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11347 offset=1901592576 bytes=16384
Jul 11 15:10:12 pve702 kernel: [ 5884.323242] cifs_readv_receive: 287 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.323243] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.323246] cifs_readv_receive: 287 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.323247] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323249] cifs_readv_receive: 287 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.323250] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323299] cifs_readv_receive: 287 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.323300] CIFS: fs/cifs/cifssmb.c: total_read=16464 buflen=16464 remaining=16384
Jul 11 15:10:12 pve702 kernel: [ 5884.323303] smb2_readv_callback: 287 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.323304] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11347 state=4 result=0 bytes=16384
Jul 11 15:10:12 pve702 kernel: [ 5884.323601] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901608960 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323628] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901613056 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323633] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901617152 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323636] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901621248 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323638] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901625344 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323642] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901629440 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323645] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901633536 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323650] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901637632 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323654] CIFS: fs/cifs/smb2pdu.c: smb2_async_readv: offset=1901641728 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323784] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11348 offset=1901608960 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323790] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.323791] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323792] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323795] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323796] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11348 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323816] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11349 offset=1901613056 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323818] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.323819] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323820] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323823] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323824] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11349 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323954] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11350 offset=1901617152 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323956] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.323958] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323958] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.323961] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.323962] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11350 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324011] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11351 offset=1901621248 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324014] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.324015] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324015] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324018] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324019] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11351 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324113] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11352 offset=1901625344 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324116] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.324117] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324118] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324120] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324121] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11352 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324143] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11353 offset=1901629440 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324145] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.324146] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324147] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324149] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324151] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11353 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324166] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11354 offset=1901633536 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324168] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.324173] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324174] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324176] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324177] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11354 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324276] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11355 offset=1901637632 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324278] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.324279] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324280] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324282] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324295] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11355 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324299] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: mid=11356 offset=1901641728 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324304] CIFS: fs/cifs/cifssmb.c: 0: iov_base=00000000d5eb689a iov_len=0
Jul 11 15:10:12 pve702 kernel: [ 5884.324305] CIFS: fs/cifs/cifssmb.c: 1: iov_base=00000000d5eb689a iov_len=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324306] CIFS: fs/cifs/cifssmb.c: cifs_readv_receive: total_read=80 data_offset=80
Jul 11 15:10:12 pve702 kernel: [ 5884.324308] CIFS: fs/cifs/cifssmb.c: total_read=4176 buflen=4176 remaining=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.324309] CIFS: fs/cifs/smb2pdu.c: smb2_readv_callback: mid=11356 state=4 result=0 bytes=4096
Jul 11 15:10:12 pve702 kernel: [ 5884.365216] smb2_calc_size: 60 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.365222] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365225] smb2_check_message: 50 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.365226] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11365
Jul 11 15:10:12 pve702 kernel: [ 5884.365591] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365593] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11366
Jul 11 15:10:12 pve702 kernel: [ 5884.365744] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365746] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11367
Jul 11 15:10:12 pve702 kernel: [ 5884.365750] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365751] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11368
Jul 11 15:10:12 pve702 kernel: [ 5884.365753] CIFS: fs/cifs/smb2misc.c: SMB2 len 73
Jul 11 15:10:12 pve702 kernel: [ 5884.365770] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365772] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11370
Jul 11 15:10:12 pve702 kernel: [ 5884.365937] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365939] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11371
Jul 11 15:10:12 pve702 kernel: [ 5884.365962] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365963] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11372
Jul 11 15:10:12 pve702 kernel: [ 5884.365967] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.365967] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11369
Jul 11 15:10:12 pve702 kernel: [ 5884.366115] CIFS: fs/cifs/smb2misc.c: SMB2 len 81
Jul 11 15:10:12 pve702 kernel: [ 5884.366116] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11373
Jul 11 15:10:12 pve702 kernel: [ 5884.366301] CIFS: fs/cifs/smb2misc.c: Calculated size 81 length 80 mismatch mid 11374
Jul 11 15:10:12 pve702 kernel: [ 5884.367422] CIFS: fs/cifs/transport.c: signal is pending after attempt to send
Jul 11 15:10:12 pve702 kernel: [ 5884.367427] CIFS: fs/cifs/transport.c: partial send (wanted=65652 sent=41076): terminating session
Jul 11 15:10:12 pve702 kernel: [ 5884.367429] CIFS: VFS: \\192.168.20.241 Error -512 sending data on socket to server
Jul 11 15:10:12 pve702 kernel: [ 5884.367476] CIFS: fs/cifs/connect.c: Mark tcp session as need reconnect
Jul 11 15:10:12 pve702 kernel: [ 5884.367787] cifs_small_buf_release: 17 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.367789] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.367887] CIFS: fs/cifs/connect.c: cifs_mark_tcp_ses_conns_for_reconnect: marking necessary sessions and tcons for reconnect
Jul 11 15:10:12 pve702 kernel: [ 5884.367942] CIFS: fs/cifs/sess.c: Set reconnect bitmask for chan 0; now 0x1
Jul 11 15:10:12 pve702 kernel: [ 5884.367948] CIFS: fs/cifs/connect.c: cifs_abort_connection: tearing down socket
Jul 11 15:10:12 pve702 kernel: [ 5884.367955] CIFS: fs/cifs/connect.c: State: 0x3 Flags: 0x4
Jul 11 15:10:12 pve702 kernel: [ 5884.367959] CIFS: fs/cifs/connect.c: Post shutdown state: 0x3 Flags: 0x4
Jul 11 15:10:12 pve702 kernel: [ 5884.367996] CIFS: fs/cifs/connect.c: cifs_abort_connection: moving mids to private list
Jul 11 15:10:12 pve702 kernel: [ 5884.367999] CIFS: fs/cifs/connect.c: cifs_abort_connection: issuing mid callbacks
Jul 11 15:10:12 pve702 kernel: [ 5884.368006] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368007] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368008] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368009] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368010] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368011] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368012] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368013] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368014] CIFS: fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release
Jul 11 15:10:12 pve702 kernel: [ 5884.368033] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: probably server name is whole unc: \\192.168.20.241
Jul 11 15:10:12 pve702 kernel: [ 5884.368038] CIFS: fs/cifs/dns_resolve.c: dns_resolve_server_name_to_ip: unc is IP, skipping dns upcall: 192.168.20.241
Jul 11 15:10:12 pve702 kernel: [ 5884.368101] CIFS: fs/cifs/connect.c: reconn_set_ipaddr_from_hostname: next dns resolution scheduled for 253793842095562701 seconds in the future
Jul 11 15:10:12 pve702 kernel: [ 5884.368106] CIFS: fs/cifs/connect.c: __cifs_reconnect: reconn_set_ipaddr_from_hostname: rc=0
Jul 11 15:10:12 pve702 kernel: [ 5884.368108] CIFS: fs/cifs/connect.c: generic_ip_connect: connecting to 192.168.20.241:445
Jul 11 15:10:12 pve702 kernel: [ 5884.368117] CIFS: fs/cifs/connect.c: Socket created
Jul 11 15:10:12 pve702 kernel: [ 5884.368118] CIFS: fs/cifs/connect.c: sndbuf 16384 rcvbuf 131072 rcvtimeo 0x6d6
Jul 11 15:10:12 pve702 kernel: [ 5884.368213] CIFS: fs/cifs/smb2ops.c: smb2_set_credits: set 1 credits
Jul 11 15:10:12 pve702 kernel: [ 5884.368216] CIFS: fs/cifs/smb2ops.c: set credits to 1 due to smb2 reconnect
Jul 11 15:10:12 pve702 kernel: [ 5884.368226] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels
Jul 11 15:10:12 pve702 kernel: [ 5884.368256] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jul 11 15:10:12 pve702 kernel: [ 5884.368264] CIFS: fs/cifs/smb2pdu.c: Negotiate protocol
Jul 11 15:10:12 pve702 kernel: [ 5884.368269] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=0
Jul 11 15:10:12 pve702 kernel: [ 5884.368304] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jul 11 15:10:12 pve702 kernel: [ 5884.368307] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jul 11 15:10:12 pve702 kernel: [ 5884.368309] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x1, tcon reconnect: 1
Jul 11 15:10:12 pve702 kernel: [ 5884.372925] smb2_calc_size: 8 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.372927] CIFS: fs/cifs/smb2misc.c: SMB2 data length 74 offset 128
Jul 11 15:10:12 pve702 kernel: [ 5884.372930] CIFS: fs/cifs/smb2misc.c: length of negcontexts 60 pad 6
Jul 11 15:10:12 pve702 kernel: [ 5884.372937] cifs_sync_mid_result: 17 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.372938] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=0 mid=0 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.372944] CIFS: fs/cifs/smb2pdu.c: mode 0x1
Jul 11 15:10:12 pve702 kernel: [ 5884.372946] CIFS: fs/cifs/smb2pdu.c: negotiated smb3.1.1 dialect
Jul 11 15:10:12 pve702 kernel: [ 5884.372949] CIFS: fs/cifs/smb2pdu.c: decoding 2 negotiate contexts
Jul 11 15:10:12 pve702 kernel: [ 5884.372950] CIFS: fs/cifs/smb2pdu.c: decode SMB3.11 encryption neg context of len 4
Jul 11 15:10:12 pve702 kernel: [ 5884.372951] CIFS: fs/cifs/smb2pdu.c: SMB311 cipher type:2
Jul 11 15:10:12 pve702 kernel: [ 5884.372976] CIFS: fs/cifs/connect.c: Free previous auth_key.response = 00000000fa32e721
Jul 11 15:10:12 pve702 kernel: [ 5884.372979] CIFS: fs/cifs/connect.c: Security Mode: 0x1 Capabilities: 0x300047 TimeAdjust: 0
Jul 11 15:10:12 pve702 kernel: [ 5884.372981] CIFS: fs/cifs/smb2pdu.c: Session Setup
Jul 11 15:10:12 pve702 kernel: [ 5884.372983] CIFS: fs/cifs/smb2pdu.c: sess setup type 2
Jul 11 15:10:12 pve702 kernel: [ 5884.372985] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: eee95f8b
Jul 11 15:10:12 pve702 kernel: [ 5884.372988] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=0
Jul 11 15:10:12 pve702 kernel: [ 5884.373312] CIFS: fs/cifs/smb2misc.c: SMB2 data length 202 offset 72
Jul 11 15:10:12 pve702 kernel: [ 5884.373317] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=1 mid=1 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.373325] CIFS: Status code returned 0xc0000016 STATUS_MORE_PROCESSING_REQUIRED
Jul 11 15:10:12 pve702 kernel: [ 5884.373339] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000016 to POSIX err -5
Jul 11 15:10:12 pve702 kernel: [ 5884.373343] CIFS: fs/cifs/sess.c: decode_ntlmssp_challenge: negotiate=0xe2088235 challenge=0xe28a8235
Jul 11 15:10:12 pve702 kernel: [ 5884.373347] CIFS: fs/cifs/smb2pdu.c: rawntlmssp session setup challenge phase
Jul 11 15:10:12 pve702 kernel: [ 5884.373348] CIFS: fs/cifs/smb2pdu.c: Fresh session. Previous: eee95f8b
Jul 11 15:10:12 pve702 kernel: [ 5884.373362] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=0
Jul 11 15:10:12 pve702 kernel: [ 5884.379700] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 72
Jul 11 15:10:12 pve702 kernel: [ 5884.379707] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=1 mid=2 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.379718] CIFS: fs/cifs/smb2pdu.c: SMB2/3 session established successfully
Jul 11 15:10:12 pve702 kernel: [ 5884.379719] CIFS: fs/cifs/sess.c: Cleared reconnect bitmask for chan 0; now 0x0
Jul 11 15:10:12 pve702 kernel: [ 5884.379725] CIFS: fs/cifs/smb2pdu.c: TCON
Jul 11 15:10:12 pve702 kernel: [ 5884.379728] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=129
Jul 11 15:10:12 pve702 kernel: [ 5884.380336] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=3 mid=3 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.380339] CIFS: fs/cifs/smb2pdu.c: connection to disk share
Jul 11 15:10:12 pve702 kernel: [ 5884.380341] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jul 11 15:10:12 pve702 kernel: [ 5884.380369] CIFS: fs/cifs/connect.c: cifs_put_tcon: tc_count=2
Jul 11 15:10:12 pve702 kernel: [ 5884.380371] CIFS: fs/cifs/smb2pdu.c: sess reconnect mask: 0x0, tcon reconnect: 1
Jul 11 15:10:12 pve702 kernel: [ 5884.380377] CIFS: fs/cifs/smb2ops.c: trying to put 1 credits from the old server instance 44
Jul 11 15:10:12 pve702 kernel: [ 5884.380396] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 23416 with uid: 0
Jul 11 15:10:12 pve702 kernel: [ 5884.380400] CIFS: fs/cifs/file.c: inode = 0x000000001fc26bdc file flags 0xc002 for \images\109\vm-109-disk-0.raw
Jul 11 15:10:12 pve702 kernel: [ 5884.380408] CIFS: fs/cifs/smb2pdu.c: create/open
Jul 11 15:10:12 pve702 kernel: [ 5884.380414] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=192
Jul 11 15:10:12 pve702 kernel: [ 5884.380436] CIFS: fs/cifs/smb2ops.c: trying to put 1 credits from the old server instance 44
Jul 11 15:10:12 pve702 kernel: [ 5884.380438] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 23417 with uid: 0
Jul 11 15:10:12 pve702 kernel: [ 5884.380441] CIFS: fs/cifs/smb2ops.c: trying to put 1 credits from the old server instance 44
Jul 11 15:10:12 pve702 kernel: [ 5884.380442] CIFS: fs/cifs/file.c: VFS: in cifs_reopen_file as Xid: 23418 with uid: 0
Jul 11 15:10:12 pve702 kernel: [ 5884.380444] CIFS: fs/cifs/smb2pdu.c: reconnect tcon rc = 0
Jul 11 15:10:12 pve702 kernel: [ 5884.380445] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jul 11 15:10:12 pve702 kernel: [ 5884.380446] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses_count=2
Jul 11 15:10:12 pve702 kernel: [ 5884.380447] CIFS: fs/cifs/connect.c: cifs_put_smb_ses: ses ipc: \\192.168.20.241\IPC$
Jul 11 15:10:12 pve702 kernel: [ 5884.380449] CIFS: fs/cifs/smb2pdu.c: Reconnecting tcons and channels finished
Jul 11 15:10:12 pve702 kernel: [ 5884.380557] CIFS: fs/cifs/smb2misc.c: SMB2 data length 0 offset 0
Jul 11 15:10:12 pve702 kernel: [ 5884.380561] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=4 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.380563] CIFS: Status code returned 0xc0000034 STATUS_OBJECT_NAME_NOT_FOUND
Jul 11 15:10:12 pve702 kernel: [ 5884.380568] CIFS: fs/cifs/smb2maperror.c: Mapping SMB2 status code 0xc0000034 to POSIX err -2
Jul 11 15:10:12 pve702 kernel: [ 5884.380573] CIFS: fs/cifs/smb2pdu.c: create/open
Jul 11 15:10:12 pve702 kernel: [ 5884.380575] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=201
Jul 11 15:10:12 pve702 kernel: [ 5884.381100] CIFS: fs/cifs/smb2misc.c: SMB2 data length 132 offset 152
Jul 11 15:10:12 pve702 kernel: [ 5884.381105] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=5 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.381107] CIFS: fs/cifs/smb2pdu.c: parse query id context 0x98b3069f5636c2f0 0x26
Jul 11 15:10:12 pve702 kernel: [ 5884.381111] CIFS: fs/cifs/smb2ops.c: RHW Lease granted on inode 000000001fc26bdc
Jul 11 15:10:12 pve702 kernel: [ 5884.381112] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 23416) rc = 0
Jul 11 15:10:12 pve702 kernel: [ 5884.381163] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 23417) rc = -13
Jul 11 15:10:12 pve702 kernel: [ 5884.381216] CIFS: fs/cifs/file.c: VFS: leaving cifs_reopen_file (xid = 23418) rc = -13
Jul 11 15:10:12 pve702 kernel: [ 5884.418297] CIFS: fs/cifs/file.c: VFS: in cifs_fsync as Xid: 23419 with uid: 0
Jul 11 15:10:12 pve702 kernel: [ 5884.418307] CIFS: fs/cifs/file.c: Sync file - name: vm-109-disk-0.raw datasync: 0x1
Jul 11 15:10:12 pve702 kernel: [ 5884.418323] CIFS: fs/cifs/smb2pdu.c: flush
Jul 11 15:10:12 pve702 kernel: [ 5884.418331] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 1 credits total=618
Jul 11 15:10:12 pve702 kernel: [ 5884.419900] smb2_is_status_pending: 2 callbacks suppressed
Jul 11 15:10:12 pve702 kernel: [ 5884.419906] CIFS: fs/cifs/smb2ops.c: smb2_is_status_pending: status pending add 10 credits total=628
Jul 11 15:10:12 pve702 kernel: [ 5884.425145] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=7 mid=57 state=4
Jul 11 15:10:12 pve702 kernel: [ 5884.425159] CIFS: fs/cifs/file.c: VFS: leaving cifs_fsync (xid = 23419) rc = 0
Jul 11 15:10:16 pve702 kernel: [ 5888.156015] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 23420 with uid: 0
Jul 11 15:10:16 pve702 kernel: [ 5888.156025] CIFS: fs/cifs/inode.c: Update attributes:  inode 0x00000000a130a655 count 1 dentry: 0x00000000cc2f9000 d_time 0 jiffies 4296364428
Jul 11 15:10:16 pve702 kernel: [ 5888.156046] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 3 credits total=625
Jul 11 15:10:16 pve702 kernel: [ 5888.156061] __smb_send_rqst: 183 callbacks suppressed
Jul 11 15:10:16 pve702 kernel: [ 5888.156063] CIFS: fs/cifs/transport.c: Sending smb: smb_len=348
Jul 11 15:10:16 pve702 kernel: [ 5888.156697] cifs_demultiplex_thread: 133 callbacks suppressed
Jul 11 15:10:16 pve702 kernel: [ 5888.156700] CIFS: fs/cifs/connect.c: RFC1002 header 0x200
Jul 11 15:10:16 pve702 kernel: [ 5888.156706] CIFS: fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
Jul 11 15:10:16 pve702 kernel: [ 5888.156710] smb2_add_credits: 134 callbacks suppressed
Jul 11 15:10:16 pve702 kernel: [ 5888.156711] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=625
Jul 11 15:10:16 pve702 kernel: [ 5888.156715] CIFS: fs/cifs/smb2misc.c: SMB2 data length 102 offset 72
Jul 11 15:10:16 pve702 kernel: [ 5888.156717] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=625
Jul 11 15:10:16 pve702 kernel: [ 5888.156720] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 30 credits total=655
Jul 11 15:10:16 pve702 kernel: [ 5888.156736] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=58 state=4
Jul 11 15:10:16 pve702 kernel: [ 5888.156739] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=59 state=4
Jul 11 15:10:16 pve702 kernel: [ 5888.156740] CIFS: fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=60 state=4
Jul 11 15:10:16 pve702 kernel: [ 5888.156745] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 319
Jul 11 15:10:16 pve702 kernel: [ 5888.156747] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 319 is unchanged
Jul 11 15:10:16 pve702 kernel: [ 5888.156749] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 23420) rc = 0
Jul 11 15:10:16 pve702 kernel: [ 5888.158515] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 23421 with uid: 0
Jul 11 15:10:16 pve702 kernel: [ 5888.158527] CIFS: fs/cifs/inode.c: Update attributes: \private inode 0x00000000a1af0814 count 1 dentry: 0x00000000387cc9c7 d_time 4294897279 jiffies 4296364429
Jul 11 15:10:16 pve702 kernel: [ 5888.158543] CIFS: fs/cifs/transport.c: wait_for_free_credits: remove 3 credits total=652
Jul 11 15:10:16 pve702 kernel: [ 5888.158550] CIFS: fs/cifs/transport.c: Sending smb: smb_len=356
Jul 11 15:10:16 pve702 kernel: [ 5888.159335] CIFS: fs/cifs/connect.c: RFC1002 header 0x210
Jul 11 15:10:16 pve702 kernel: [ 5888.159343] CIFS: fs/cifs/smb2misc.c: SMB2 data length 56 offset 152
Jul 11 15:10:16 pve702 kernel: [ 5888.159346] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=652
Jul 11 15:10:16 pve702 kernel: [ 5888.159349] CIFS: fs/cifs/smb2misc.c: SMB2 data length 116 offset 72
Jul 11 15:10:16 pve702 kernel: [ 5888.159351] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 0 credits total=652
Jul 11 15:10:16 pve702 kernel: [ 5888.159354] CIFS: fs/cifs/smb2ops.c: smb2_add_credits: added 30 credits total=682
Jul 11 15:10:16 pve702 kernel: [ 5888.159375] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 11001916822272032900
Jul 11 15:10:16 pve702 kernel: [ 5888.159378] CIFS: fs/cifs/inode.c: cifs_revalidate_cache: inode 11001916822272032900 is unchanged
Jul 11 15:10:16 pve702 kernel: [ 5888.159380] CIFS: fs/cifs/inode.c: VFS: leaving cifs_revalidate_dentry_attr (xid = 23421) rc = 0
Jul 11 15:10:16 pve702 kernel: [ 5888.159407] CIFS: fs/cifs/inode.c: VFS: in cifs_revalidate_dentry_attr as Xid: 23422 with uid: 0
Jul 11 15:10:16 pve702 kernel: [ 5888.159409] CIFS: fs/cifs/inode.c: Update attributes: \images inode 0x00000000f3b86d71 count 1 dentry: 0x00000000aad9d7e9 d_time 4294969503 jiffies 4296364429

Re: Problematic interaction of io_uring and CIFS

[Fiona Ebner]

Am 11.07.22 um 15:40 schrieb Fabian Ebner:
> Am 09.07.22 um 05:39 schrieb Shyam Prasad N:
>> On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <nspmangalore@gmail.com> wrote:
>>>
>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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.
>>>>>

I finally got around to taking another look at this issue (still present
in 5.19.3) and I think I've finally figured out the root cause:

After commit 8ef12efe26c8, for my reproducer, the write completion is
added to task_work with notify_method being TWA_SIGNAL and thus
TIF_NOTIFY_SIGNAL is set for the task.

After that, if we end up in sk_stream_wait_memory() via sock_sendmsg(),
signal_pending(current) will evaluate to true and thus -EINTR is
returned all the way up to sock_sendmsg() in smb_send_kvec().

Related: in __smb_send_rqst() there too is a signal_pending(current)
check leading to the -ERESTARTSYS return value.

To verify that this is the cause, I wasn't able to trigger the issue
anymore with this hack applied (i.e. excluding the TIF_NOTIFY_SIGNAL check):

> diff --git a/net/core/stream.c b/net/core/stream.c
> index 06b36c730ce8..58e3825930bb 100644
> --- a/net/core/stream.c
> +++ b/net/core/stream.c
> @@ -134,7 +134,7 @@ int sk_stream_wait_memory(struct sock *sk, long *timeo_p)
>                         goto do_error;
>                 if (!*timeo_p)
>                         goto do_eagain;
> -               if (signal_pending(current))
> +               if (task_sigpending(current))
>                         goto do_interrupted;
>                 sk_clear_bit(SOCKWQ_ASYNC_NOSPACE, sk);
>                 if (sk_stream_memory_free(sk) && !vm_wait)


In __cifs_writev() we have

>     /*
>      * If at least one write was successfully sent, then discard any rc
>      * value from the later writes. If the other write succeeds, then
>      * we'll end up returning whatever was written. If it fails, then
>      * we'll get a new rc value from that.
>      */

so it can happen that collect_uncached_write_data() will (correctly)
report a short write when calling ctx->iocb->ki_complete().

But QEMU's io_uring backend treats a short write as an -ENOSPC error,
which also is a bug? Or does the kernel give any guarantees in that
direction?

Still, it doesn't seem ideal that the "interrupt" happens and in fact
__smb_send_rqst() tries to avoid it, but fails to do so, because of the
unexpected TIF_NOTIFY_SIGNAL:
>     /*
>      * We should not allow signals to interrupt the network send because
>      * any partial send will cause session reconnects thus increasing
>      * latency of system calls and overload a server with unnecessary
>      * requests.
>      */
> 
>     sigfillset(&mask);
>     sigprocmask(SIG_BLOCK, &mask, &oldmask);

Do you have any suggestions for how to proceed?

Best Regards,
Fiona

Re: Problematic interaction of io_uring and CIFS

[Fiona Ebner]

Am 26.08.22 um 10:21 schrieb Fiona Ebner:
> Am 11.07.22 um 15:40 schrieb Fabian Ebner:
>> Am 09.07.22 um 05:39 schrieb Shyam Prasad N:
>>> On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <nspmangalore@gmail.com> wrote:
>>>>
>>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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.
>>>>>>
> 
> I finally got around to taking another look at this issue (still present
> in 5.19.3) and I think I've finally figured out the root cause:
> 
> After commit 8ef12efe26c8, for my reproducer, the write completion is
> added to task_work with notify_method being TWA_SIGNAL and thus
> TIF_NOTIFY_SIGNAL is set for the task.
> 
> After that, if we end up in sk_stream_wait_memory() via sock_sendmsg(),
> signal_pending(current) will evaluate to true and thus -EINTR is
> returned all the way up to sock_sendmsg() in smb_send_kvec().
> 
> Related: in __smb_send_rqst() there too is a signal_pending(current)
> check leading to the -ERESTARTSYS return value.
> 
> To verify that this is the cause, I wasn't able to trigger the issue
> anymore with this hack applied (i.e. excluding the TIF_NOTIFY_SIGNAL check):
> 
>> diff --git a/net/core/stream.c b/net/core/stream.c
>> index 06b36c730ce8..58e3825930bb 100644
>> --- a/net/core/stream.c
>> +++ b/net/core/stream.c
>> @@ -134,7 +134,7 @@ int sk_stream_wait_memory(struct sock *sk, long *timeo_p)
>>                         goto do_error;
>>                 if (!*timeo_p)
>>                         goto do_eagain;
>> -               if (signal_pending(current))
>> +               if (task_sigpending(current))
>>                         goto do_interrupted;
>>                 sk_clear_bit(SOCKWQ_ASYNC_NOSPACE, sk);
>>                 if (sk_stream_memory_free(sk) && !vm_wait)
> 
> 
> In __cifs_writev() we have
> 
>>     /*
>>      * If at least one write was successfully sent, then discard any rc
>>      * value from the later writes. If the other write succeeds, then
>>      * we'll end up returning whatever was written. If it fails, then
>>      * we'll get a new rc value from that.
>>      */
> 
> so it can happen that collect_uncached_write_data() will (correctly)
> report a short write when calling ctx->iocb->ki_complete().
> 
> But QEMU's io_uring backend treats a short write as an -ENOSPC error,
> which also is a bug? Or does the kernel give any guarantees in that
> direction?
> 
> Still, it doesn't seem ideal that the "interrupt" happens and in fact
> __smb_send_rqst() tries to avoid it, but fails to do so, because of the
> unexpected TIF_NOTIFY_SIGNAL:
>>     /*
>>      * We should not allow signals to interrupt the network send because
>>      * any partial send will cause session reconnects thus increasing
>>      * latency of system calls and overload a server with unnecessary
>>      * requests.
>>      */
>>
>>     sigfillset(&mask);
>>     sigprocmask(SIG_BLOCK, &mask, &oldmask);
> 
> Do you have any suggestions for how to proceed?
> 

Ping. The issue is still present in Linux 6.0. Does it make sense to
also temporarily unset the task's TIF_NOTIFY_SIGNAL here or is that a
bad idea?

Best Regards,
Fiona

Re: Problematic interaction of io_uring and CIFS

[Jens Axboe]

On 10/4/22 2:59 AM, Fiona Ebner wrote:
> Am 26.08.22 um 10:21 schrieb Fiona Ebner:
>> Am 11.07.22 um 15:40 schrieb Fabian Ebner:
>>> Am 09.07.22 um 05:39 schrieb Shyam Prasad N:
>>>> On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <nspmangalore@gmail.com> wrote:
>>>>>
>>>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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.
>>>>>>>
>>
>> I finally got around to taking another look at this issue (still present
>> in 5.19.3) and I think I've finally figured out the root cause:
>>
>> After commit 8ef12efe26c8, for my reproducer, the write completion is
>> added to task_work with notify_method being TWA_SIGNAL and thus
>> TIF_NOTIFY_SIGNAL is set for the task.
>>
>> After that, if we end up in sk_stream_wait_memory() via sock_sendmsg(),
>> signal_pending(current) will evaluate to true and thus -EINTR is
>> returned all the way up to sock_sendmsg() in smb_send_kvec().
>>
>> Related: in __smb_send_rqst() there too is a signal_pending(current)
>> check leading to the -ERESTARTSYS return value.
>>
>> To verify that this is the cause, I wasn't able to trigger the issue
>> anymore with this hack applied (i.e. excluding the TIF_NOTIFY_SIGNAL check):
>>
>>> diff --git a/net/core/stream.c b/net/core/stream.c
>>> index 06b36c730ce8..58e3825930bb 100644
>>> --- a/net/core/stream.c
>>> +++ b/net/core/stream.c
>>> @@ -134,7 +134,7 @@ int sk_stream_wait_memory(struct sock *sk, long *timeo_p)
>>>                         goto do_error;
>>>                 if (!*timeo_p)
>>>                         goto do_eagain;
>>> -               if (signal_pending(current))
>>> +               if (task_sigpending(current))
>>>                         goto do_interrupted;
>>>                 sk_clear_bit(SOCKWQ_ASYNC_NOSPACE, sk);
>>>                 if (sk_stream_memory_free(sk) && !vm_wait)
>>
>>
>> In __cifs_writev() we have
>>
>>>     /*
>>>      * If at least one write was successfully sent, then discard any rc
>>>      * value from the later writes. If the other write succeeds, then
>>>      * we'll end up returning whatever was written. If it fails, then
>>>      * we'll get a new rc value from that.
>>>      */
>>
>> so it can happen that collect_uncached_write_data() will (correctly)
>> report a short write when calling ctx->iocb->ki_complete().
>>
>> But QEMU's io_uring backend treats a short write as an -ENOSPC error,
>> which also is a bug? Or does the kernel give any guarantees in that
>> direction?
>>
>> Still, it doesn't seem ideal that the "interrupt" happens and in fact
>> __smb_send_rqst() tries to avoid it, but fails to do so, because of the
>> unexpected TIF_NOTIFY_SIGNAL:
>>>     /*
>>>      * We should not allow signals to interrupt the network send because
>>>      * any partial send will cause session reconnects thus increasing
>>>      * latency of system calls and overload a server with unnecessary
>>>      * requests.
>>>      */
>>>
>>>     sigfillset(&mask);
>>>     sigprocmask(SIG_BLOCK, &mask, &oldmask);
>>
>> Do you have any suggestions for how to proceed?
>>
> 
> Ping. The issue is still present in Linux 6.0. Does it make sense to
> also temporarily unset the task's TIF_NOTIFY_SIGNAL here or is that a
> bad idea?

You could try setting up with ring with IORING_SETUP_COOP_TASKRUN,
that'll avoid the TIF_NOTIFY_SIGNAL bits.

-- 
Jens Axboe

Re: Problematic interaction of io_uring and CIFS

[Fiona Ebner]

Am 04.10.22 um 16:02 schrieb Jens Axboe:
> On 10/4/22 2:59 AM, Fiona Ebner wrote:
>> Am 26.08.22 um 10:21 schrieb Fiona Ebner:
>>> Am 11.07.22 um 15:40 schrieb Fabian Ebner:
>>>> Am 09.07.22 um 05:39 schrieb Shyam Prasad N:
>>>>> On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <nspmangalore@gmail.com> wrote:
>>>>>>
>>>>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <ematsumiya@suse.de> 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.
>>>>>>>>
>>>
>>> I finally got around to taking another look at this issue (still present
>>> in 5.19.3) and I think I've finally figured out the root cause:
>>>
>>> After commit 8ef12efe26c8, for my reproducer, the write completion is
>>> added to task_work with notify_method being TWA_SIGNAL and thus
>>> TIF_NOTIFY_SIGNAL is set for the task.
>>>
>>> After that, if we end up in sk_stream_wait_memory() via sock_sendmsg(),
>>> signal_pending(current) will evaluate to true and thus -EINTR is
>>> returned all the way up to sock_sendmsg() in smb_send_kvec().
>>>
>>> Related: in __smb_send_rqst() there too is a signal_pending(current)
>>> check leading to the -ERESTARTSYS return value.
>>>
>>> To verify that this is the cause, I wasn't able to trigger the issue
>>> anymore with this hack applied (i.e. excluding the TIF_NOTIFY_SIGNAL check):
>>>
>>>> diff --git a/net/core/stream.c b/net/core/stream.c
>>>> index 06b36c730ce8..58e3825930bb 100644
>>>> --- a/net/core/stream.c
>>>> +++ b/net/core/stream.c
>>>> @@ -134,7 +134,7 @@ int sk_stream_wait_memory(struct sock *sk, long *timeo_p)
>>>>                         goto do_error;
>>>>                 if (!*timeo_p)
>>>>                         goto do_eagain;
>>>> -               if (signal_pending(current))
>>>> +               if (task_sigpending(current))
>>>>                         goto do_interrupted;
>>>>                 sk_clear_bit(SOCKWQ_ASYNC_NOSPACE, sk);
>>>>                 if (sk_stream_memory_free(sk) && !vm_wait)
>>>
>>>
>>> In __cifs_writev() we have
>>>
>>>>     /*
>>>>      * If at least one write was successfully sent, then discard any rc
>>>>      * value from the later writes. If the other write succeeds, then
>>>>      * we'll end up returning whatever was written. If it fails, then
>>>>      * we'll get a new rc value from that.
>>>>      */
>>>
>>> so it can happen that collect_uncached_write_data() will (correctly)
>>> report a short write when calling ctx->iocb->ki_complete().
>>>
>>> But QEMU's io_uring backend treats a short write as an -ENOSPC error,
>>> which also is a bug? Or does the kernel give any guarantees in that
>>> direction?
>>>
>>> Still, it doesn't seem ideal that the "interrupt" happens and in fact
>>> __smb_send_rqst() tries to avoid it, but fails to do so, because of the
>>> unexpected TIF_NOTIFY_SIGNAL:
>>>>     /*
>>>>      * We should not allow signals to interrupt the network send because
>>>>      * any partial send will cause session reconnects thus increasing
>>>>      * latency of system calls and overload a server with unnecessary
>>>>      * requests.
>>>>      */
>>>>
>>>>     sigfillset(&mask);
>>>>     sigprocmask(SIG_BLOCK, &mask, &oldmask);
>>>
>>> Do you have any suggestions for how to proceed?
>>>
>>
>> Ping. The issue is still present in Linux 6.0. Does it make sense to
>> also temporarily unset the task's TIF_NOTIFY_SIGNAL here or is that a
>> bad idea?
> 
> You could try setting up with ring with IORING_SETUP_COOP_TASKRUN,
> that'll avoid the TIF_NOTIFY_SIGNAL bits.
> 

Thank you for the suggestion. I tried this, but had no luck. AFAICT,
with IORING_SETUP_COOP_TASKRUN, the notify_method will be
TWA_SIGNAL_NO_IPI and when adding the task work, __set_notify_signal()
is called, which still sets the TIF_NOTIFY_SIGNAL for the task?

Even if it worked, I feel like making the "We should not allow signals
to interrupt the network send"-comment valid again would be nicer.

Best Regards,
Fiona

Re: Problematic interaction of io_uring and CIFS

[Jens Axboe]

On 7/8/22 6:05 AM, Fabian Ebner wrote:
> 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

I think that one is most likely fine, it just tells you that (most
likely) io_uring had task_work pending and that should get processed and
then the IO retried.

-- 
Jens Axboe