Bug 404890

kio-extras-19.04.0-1 - problem not resolved

kio-extras-19.12.0-1 - problem not resolved

Still a problem with 19.12? Can you reproduce this with dolphin? What libssh version are you using?

Dear Bug Submitter,

This bug has been in NEEDSINFO status with no change for at least
15 days. Please provide the requested information as soon as
possible and set the bug status as REPORTED. Due to regular bug
tracker maintenance, if the bug is still in NEEDSINFO status with
no change in 30 days the bug will be closed as RESOLVED > WORKSFORME
due to lack of needed information.

For more information about our bug triaging procedures please read the
wiki located here:
https://community.kde.org/Guidelines_and_HOWTOs/Bug_triaging

If you have already provided the requested information, please
mark the bug as REPORTED so that the KDE team knows that the bug is
ready to be confirmed.

Thank you for helping us make KDE software even better for everyone!

Yes, the problem still exists in kde-extras 19.12.3-1

libssh - 0.9.3-1
linssh2 - 1.9.0-2

I can reproduce this with dolphin as well, copy/paste lead to zero size file.

Last version kde-extras without this problem was 18.08.3-2

Alas, I cannot reproduce.

Does this happen with any server (e.g. can you reproduce this with localhost)?
Are you sure the remote directory permissions are correct?
What is the server software/version?
Does the server possibly have additional settings other than the defaults of the server software?

Please start dolphin and generate debug output by causing the issue:

> killall kioslave5; killall -9 kiod5; QT_LOGGING_RULES="log_kio_sftp=true;log_kio_sftp.trace=true" KDE_FORK_SLAVES=1 dolphin --new-window '$SFTPURL'

then attach the output to the bug report please.

> Does this happen with any server (e.g. can you reproduce this with localhost)?
Yes, it happen with localhost as well.
Are you sure the remote directory permissions are correct?
Yes I'm sure. Problem does not exists if I copy really small file (1-2 kb) but at the same time copy failed if file size > 1-2 Mb. Problem with localhost was checked on
Archlinux:
kio-extras - 19.12.3-1
$uname -a
Linux archhost 5.5.11-arch1-1 #1 SMP PREEMPT Sun, 22 Mar 2020 16:33:15 +0000 x86_64 GNU/Linux

Ubuntu:
kio-extras - Version: 4:19.04.3-0ubuntu1 
$uname -a
Linux g3-3779 5.3.0-45-generic #37-Ubuntu SMP Thu Mar 26 20:41:27 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux 

> Please start dolphin and generate debug output by causing the issue
In attachment log with error on copy big file and success copy small one

Created attachment 127130 [details]
attachment log with error on copy big file and success copy small one

There we go

kf5.kio.core: finished() called twice! Please fix the kio_sftp KIO slave

This can, by design, no longer happen with the soon to be released 20.04 version. What happend was that the sftp plugin misbehaved and then got confused with itself causing that running instance to break and stop working.

Created attachment 128244 [details]
log with error on copy file with kio-extras 20.04.0-1

the problem still exists in kio-extras 20.04.0-1

it seems the problem was not resolved in kio-extras 20.04.0-1 - log file with error in previous attachment

Can confirm. I'm not yet sure how to solve this. What's happening is that there isn't actual support for remote->remote copies so KIO falls back to download in one instance and then streams that data into another instance for upload. Trouble is we read insanely huge chunks and I think the server fails to deal with writes of that size and eventually just closes the connection.

openssh falls over

> Mai 11 14:35:03 ajax kdeinit5[9480]: +++++++++++++++++++++ sftp_write
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ channel_write_common ] ( 2 )  channel_write_common: Remote window is 2096505 bytes. going to write 7864349 bytes
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ ssh_packet_need_rekey ] ( 3 )  ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=2296, in_blocks=2334
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ ssh_socket_unbuffered_write ] ( 3 )  ssh_socket_unbuffered_write: Enabling POLLOUT for socket
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ packet_send2 ] ( 3 )  packet_send2: packet: wrote [type=94, len=32784, padding_size=16, comp=32767, payload=32767]
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ channel_write_common ] ( 3 )  channel_write_common: channel_write wrote 32758 bytes
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ channel_write_common ] ( 2 )  channel_write_common: Remote window is 2063747 bytes. going to write 7831591 bytes
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ ssh_packet_need_rekey ] ( 3 )  ssh_packet_need_rekey: packet: [data_rekey_needed=0, out_blocks=4343, in_blocks=2334
> Mai 11 14:35:03 ajax sftp-server[9521]: error: bad message from 127.0.0.1 local user me
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ packet_send2 ] ( 3 )  packet_send2: packet: wrote [type=94, len=32784, padding_size=16, comp=32767, payload=32767]
> Mai 11 14:35:03 ajax sftp-server[9521]: forced close "/home/me/Public/subdir/file.part" bytes read 0 written 0
> Mai 11 14:35:03 ajax kdeinit5[9480]: log_kio_sftp: [ channel_write_common ] ( 3 )  channel_write_common: channel_write wrote 32758 bytes
> Mai 11 14:35:03 ajax sftp-server[9521]: session closed for local user me from [127.0.0.1]

because of 

> 	if (msg_len > SFTP_MAX_MSG_LENGTH) {
> 		error("bad message from %s local user %s",
> 		    client_addr, pw->pw_name);

defined in

> sftp-common.h:#define SFTP_MAX_MSG_LENGTH       (256 * 1024)

i.e. our write requests are just way too big for openssh

https://tools.ietf.org/html/draft-ietf-secsh-filexfer-00 doesn't seem to describe a solution for this. It merely states that servers SHOULD support read/write of 32768 bytes, but not really what happens when the client requests are larger than the server is willing to handle. I suppose it also doesn't help that openssh just closes the connection when this happens because that puts our client into a confused state as we think the session is still open but really it's not.

I believe the solution here is to simply serialize the writes into multiple requests so as to not exceed the limits.

Git commit 1df6174834bb3a126f630d4477bcdbda95f45a8b by Harald Sitter.
Committed on 14/05/2020 at 11:58.
Pushed by sitter into branch 'master'.

sftp: break large writes into multiple requests

Summary:
servers have arbitrary limits that we should stay below. to ensure this
happens use MAX_XFER_BUF_SIZE as maximum size per request. if we read
data large than that, break it apart into multiple requests

(I am mostly guessing here, the rfc doesn't seem to impose any size
 constraint on the write requests themselves, so probably packet
 constraints apply by default)
FIXED-IN: 20.04.2

Test Plan:
- fallocate -l 128M file
- sftp to localhost
- copy file from one dir to another
- compare checksums match

- open xls file (via kio-fuse)
- change
- save
- close
- open again
- changes are still there

Reviewers: ngraham, meven, feverfew

Reviewed By: ngraham, meven, feverfew

Subscribers: meven, feverfew, kde-frameworks-devel, kfm-devel

Tags: #dolphin, #frameworks

Differential Revision: https://phabricator.kde.org/D29634

M  +57   -12   sftp/kio_sftp.cpp
M  +8    -0    sftp/kio_sftp.h

https://commits.kde.org/kio-extras/1df6174834bb3a126f630d4477bcdbda95f45a8b