Bug 404890 - copy file failed on remote sftp host
Summary: copy file failed on remote sftp host
Status: RESOLVED FIXED
Alias: None
Product: kio-extras
Classification: Frameworks and Libraries
Component: SFTP (show other bugs)
Version: 18.12.2
Platform: Arch Linux Linux
: NOR normal
Target Milestone: ---
Assignee: Plasma Bugs List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-02-28 06:03 UTC by ovl
Modified: 2020-05-14 12:00 UTC (History)
3 users (show)

See Also:
Latest Commit:
Version Fixed In: 20.04.2


Attachments
attachment log with error on copy big file and success copy small one (21.26 KB, text/plain)
2020-03-31 09:08 UTC, ovl
Details
log with error on copy file with kio-extras 20.04.0-1 (7.98 KB, text/plain)
2020-05-07 21:53 UTC, ovl
Details

Note You need to log in before you can comment on or make changes to this bug.
Description ovl 2019-02-28 06:03:36 UTC
SUMMARY kio-extras all versions 18.12.x (18.12.0 - 18.12.2) 

downgrade to 18.08.3 resolve problem

STEPS TO REPRODUCE
1. Open krusader both panels on remote sftp host  
2. Select sufficiently large file (> 1Mb) and copy it from left panel to right 

OBSERVED RESULT
zero size file with extension .part


EXPECTED RESULT


SOFTWARE/OS VERSIONS
Windows: 
MacOS: 
Linux/KDE Plasma: 
(available in About System)
KDE Plasma Version: 
KDE Frameworks Version: 
Qt Version: 

ADDITIONAL INFORMATION
Comment 1 ovl 2019-04-24 04:10:23 UTC
kio-extras-19.04.0-1 - problem not resolved
Comment 2 ovl 2019-12-13 15:02:59 UTC
kio-extras-19.12.0-1 - problem not resolved
Comment 3 Harald Sitter 2020-03-04 16:57:27 UTC
Still a problem with 19.12? Can you reproduce this with dolphin? What libssh version are you using?
Comment 4 Bug Janitor Service 2020-03-19 04:33:17 UTC
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!
Comment 5 ovl 2020-03-20 04:04:44 UTC
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
Comment 6 Harald Sitter 2020-03-20 09:41:46 UTC
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.
Comment 7 ovl 2020-03-31 09:07:33 UTC
> 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
Comment 8 ovl 2020-03-31 09:08:33 UTC
Created attachment 127130 [details]
attachment log with error on copy big file and success copy small one
Comment 9 Harald Sitter 2020-03-31 09:19:18 UTC
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.
Comment 10 ovl 2020-05-07 21:53:55 UTC
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
Comment 11 ovl 2020-05-07 22:02:23 UTC
it seems the problem was not resolved in kio-extras 20.04.0-1 - log file with error in previous attachment
Comment 12 Harald Sitter 2020-05-08 09:49:48 UTC
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.
Comment 13 Harald Sitter 2020-05-11 13:16:27 UTC
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.
Comment 14 Harald Sitter 2020-05-14 12:00:54 UTC
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