* Problematic interaction of io_uring and CIFS @ 2022-07-08 12:05 Fabian Ebner 2022-07-08 17:48 ` Enzo Matsumiya 2022-07-08 18:12 ` Jens Axboe 0 siblings, 2 replies; 10+ messages in thread From: Fabian Ebner @ 2022-07-08 12:05 UTC (permalink / raw) To: io-uring, linux-cifs; +Cc: Thomas Lamprecht [-- 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-07-08 12:05 Problematic interaction of io_uring and CIFS Fabian Ebner @ 2022-07-08 17:48 ` Enzo Matsumiya 2022-07-09 3:30 ` Shyam Prasad N 2022-07-08 18:12 ` Jens Axboe 1 sibling, 1 reply; 10+ messages in thread From: Enzo Matsumiya @ 2022-07-08 17:48 UTC (permalink / raw) To: Fabian Ebner; +Cc: io-uring, linux-cifs, Thomas Lamprecht 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-07-08 17:48 ` Enzo Matsumiya @ 2022-07-09 3:30 ` Shyam Prasad N 2022-07-09 3:39 ` Shyam Prasad N 0 siblings, 1 reply; 10+ messages in thread From: Shyam Prasad N @ 2022-07-09 3:30 UTC (permalink / raw) To: Enzo Matsumiya; +Cc: Fabian Ebner, io-uring, CIFS, Thomas Lamprecht On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-07-09 3:30 ` Shyam Prasad N @ 2022-07-09 3:39 ` Shyam Prasad N 2022-07-11 13:40 ` Fabian Ebner 0 siblings, 1 reply; 10+ messages in thread From: Shyam Prasad N @ 2022-07-09 3:39 UTC (permalink / raw) To: Enzo Matsumiya; +Cc: Fabian Ebner, io-uring, CIFS, Thomas Lamprecht On Sat, Jul 9, 2022 at 9:00 AM Shyam Prasad N <[email protected]> wrote: > > On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-07-09 3:39 ` Shyam Prasad N @ 2022-07-11 13:40 ` Fabian Ebner 2022-08-26 8:21 ` Fiona Ebner 0 siblings, 1 reply; 10+ messages in thread From: Fabian Ebner @ 2022-07-11 13:40 UTC (permalink / raw) To: Shyam Prasad N, Enzo Matsumiya, Jens Axboe Cc: io-uring, CIFS, Thomas Lamprecht [-- 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 <[email protected]> wrote: >> >> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-07-11 13:40 ` Fabian Ebner @ 2022-08-26 8:21 ` Fiona Ebner 2022-10-04 8:59 ` Fiona Ebner 0 siblings, 1 reply; 10+ messages in thread From: Fiona Ebner @ 2022-08-26 8:21 UTC (permalink / raw) To: Shyam Prasad N, Enzo Matsumiya, Jens Axboe Cc: io-uring, CIFS, Thomas Lamprecht 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 <[email protected]> wrote: >>> >>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-08-26 8:21 ` Fiona Ebner @ 2022-10-04 8:59 ` Fiona Ebner 2022-10-04 14:02 ` Jens Axboe 0 siblings, 1 reply; 10+ messages in thread From: Fiona Ebner @ 2022-10-04 8:59 UTC (permalink / raw) To: Shyam Prasad N, Enzo Matsumiya, Jens Axboe Cc: io-uring, CIFS, Thomas Lamprecht 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 <[email protected]> wrote: >>>> >>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-10-04 8:59 ` Fiona Ebner @ 2022-10-04 14:02 ` Jens Axboe 2022-10-05 8:20 ` Fiona Ebner 0 siblings, 1 reply; 10+ messages in thread From: Jens Axboe @ 2022-10-04 14:02 UTC (permalink / raw) To: Fiona Ebner, Shyam Prasad N, Enzo Matsumiya Cc: io-uring, CIFS, Thomas Lamprecht 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 <[email protected]> wrote: >>>>> >>>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-10-04 14:02 ` Jens Axboe @ 2022-10-05 8:20 ` Fiona Ebner 0 siblings, 0 replies; 10+ messages in thread From: Fiona Ebner @ 2022-10-05 8:20 UTC (permalink / raw) To: Jens Axboe, Shyam Prasad N, Enzo Matsumiya Cc: io-uring, CIFS, Thomas Lamprecht 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 <[email protected]> wrote: >>>>>> >>>>>> On Fri, Jul 8, 2022 at 11:22 PM Enzo Matsumiya <[email protected]> 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: Problematic interaction of io_uring and CIFS 2022-07-08 12:05 Problematic interaction of io_uring and CIFS Fabian Ebner 2022-07-08 17:48 ` Enzo Matsumiya @ 2022-07-08 18:12 ` Jens Axboe 1 sibling, 0 replies; 10+ messages in thread From: Jens Axboe @ 2022-07-08 18:12 UTC (permalink / raw) To: Fabian Ebner, io-uring, linux-cifs; +Cc: Thomas Lamprecht 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 ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2022-10-05 8:21 UTC | newest] Thread overview: 10+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2022-07-08 12:05 Problematic interaction of io_uring and CIFS Fabian Ebner 2022-07-08 17:48 ` Enzo Matsumiya 2022-07-09 3:30 ` Shyam Prasad N 2022-07-09 3:39 ` Shyam Prasad N 2022-07-11 13:40 ` Fabian Ebner 2022-08-26 8:21 ` Fiona Ebner 2022-10-04 8:59 ` Fiona Ebner 2022-10-04 14:02 ` Jens Axboe 2022-10-05 8:20 ` Fiona Ebner 2022-07-08 18:12 ` Jens Axboe
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox