After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 776824 - underlying SSH process exited on g_file_replace_contents_async() with larger file sizes
underlying SSH process exited on g_file_replace_contents_async() with larger ...
Status: RESOLVED FIXED
Product: gvfs
Classification: Core
Component: sftp backend
unspecified
Other Linux
: Normal critical
: ---
Assigned To: gvfs-maint
gvfs-maint
: 668477 (view as bug list)
Depends on:
Blocks: 767539
 
 
Reported: 2017-01-03 16:08 UTC by Olivier Sessink
Modified: 2017-06-07 11:51 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
sftp: Do not call force unmount twice (942 bytes, patch)
2017-01-04 16:59 UTC, Ondrej Holy
committed Details | Review
sftp: Report written size only on success (1.66 KB, patch)
2017-01-04 16:59 UTC, Ondrej Holy
rejected Details | Review
sftp: Mark error string as translatable (817 bytes, patch)
2017-01-04 17:00 UTC, Ondrej Holy
committed Details | Review
sftp: Limit writes to 32768 bytes (2.96 KB, patch)
2017-01-04 17:02 UTC, Ondrej Holy
none Details | Review
sftp: Limit writes to 32768 bytes (3.24 KB, patch)
2017-01-06 16:17 UTC, Ondrej Holy
committed Details | Review
sftp: Merge 3 constants into one (2.24 KB, patch)
2017-01-06 16:17 UTC, Ondrej Holy
committed Details | Review

Description Olivier Sessink 2017-01-03 16:08:04 UTC
Bluefish uses g_file_replace_contents_async to save files. 

In many different setups of clients and servers (Ubuntu, Arch, Fedora) the callback is called with error 0 and error message "The connection is closed (the underlying SSH process exited)". After this error the remote server is no longer mounted.

This only happens with larger files (say 300k or more).

This does not happen in other Bluefish code that uses g_file_copy_async(), and also not when trying to copy the same file with gvfs-copy or using scp or sftp on the commandline. This can be reproduced in muCommander.

Trying to strace the ssh process gives me no useful information (but I don't know what to look for).

Bluefish calls g_file_replace_contents_async with an etag, backup is TRUE, G_FILE_CREATE_NONE, and a cancellable,   

How can we provide more debugging information what causes this problem?
Comment 1 Olivier Sessink 2017-01-03 16:12:53 UTC
forgot to add: when working on a remote sftp:// URL.

the original Bluefish bugreport is here: https://bugzilla.gnome.org/show_bug.cgi?id=767539
Comment 2 Ondrej Holy 2017-01-04 09:12:30 UTC
Thanks for your bug report. I can reproduce it by saving file in Bluefish on sftp://localhost/ on Fedora 25. I will debug it further...
Comment 3 Ondrej Holy 2017-01-04 12:47:58 UTC
Hmm, it fails, because max message length is exceeded.

From ssh debug output:
debug1: Exit status 11

From journal:
Jan 04 12:01:46 t450s sftp-server[7212]: error: bad message from 127.0.0.1 local user oholy

See relevant server source code:
https://github.com/openssh/openssh-portable/blob/00df97ff68a49a756d4b977cd02283690f5dfa34/sftp-server.c#L1414

Maximum allowed message size is (256 * 1024):
https://github.com/openssh/openssh-portable/blob/00df97ff68a49a756d4b977cd02283690f5dfa34/sftp-common.h#L28

Draft says that "All servers SHOULD support packets of at least 34000 bytes":
https://tools.ietf.org/html/draft-ietf-secsh-filexfer-02#section-3

It works nicely if I limit maximum size to 32768 bytes as per the draft, however, this will probably cause some slowdown :-(

But also sftp uses this limit:
https://github.com/openssh/openssh-portable/blob/dda78a03af32e7994f132d923c2046e98b7c56c8/sftp.c#L74

I wonder whether it worked earlier, the relevant gvfs code is from 2007...
Comment 4 Olivier Sessink 2017-01-04 13:18:26 UTC
I thought this was in my standard test-set, but it turns out that I only test loading of large files over sftp in Bluefish, and not saving those same files. So I don't know, perhaps the bug is already around for a long while.
Comment 5 Ondrej Holy 2017-01-04 16:59:47 UTC
Created attachment 342874 [details] [review]
sftp: Do not call force unmount twice

g_vfs_backend_force_unmount() might be called twice if command sending
fails. Use fail_jobs_and_unmount wrapper instead of calling _force_unmount()
directly.
Comment 6 Ondrej Holy 2017-01-04 16:59:58 UTC
Created attachment 342875 [details] [review]
sftp: Report written size only on success

The written size is reported regardless write job result. Report
the written size only on success.
Comment 7 Ondrej Holy 2017-01-04 17:00:38 UTC
Created attachment 342876 [details] [review]
sftp: Mark error string as translatable

The error string, which might be shown in UI is not marked as
translatable, fix it.
Comment 8 Ondrej Holy 2017-01-04 17:02:55 UTC
Created attachment 342880 [details] [review]
sftp: Limit writes to 32768 bytes

Write buffer is not limited in the backend and thus it might happen
that it tries to send data, which are too length. Unfortunatelly, in
that case the underlying SSH process may exit with "The connection is
closed (the underlying SSH process exited)" error and the backend is
force unmounted consequently.

It seems that there isn't any way to determine maximal allowed buffer
size for the server. The draft-ietf-secsh-filexfer-02.txt just says:

All servers SHOULD support packets of at least 34000 bytes (where the
packet size refers to the full length, including the header above).
This should allow for reads and writes of at most 32768 bytes.

Thus the maximal buffer size has to be limited to 32768. It will
probably cause some slowdown, but better than force unmount.
Comment 9 Ondrej Holy 2017-01-04 17:04:59 UTC
I am a just little confused what is a meaning of the following comment:
/* Ideally we shouldn't do this copy, but doing the writes as multiple writes caused problems on the read side in openssh */
https://git.gnome.org/browse/gvfs/tree/daemon/gvfsbackendsftp.c#n3955

Alex?
Comment 10 Ondrej Holy 2017-01-06 15:38:13 UTC
Comment on attachment 342876 [details] [review]
sftp: Mark error string as translatable

Attachment 342876 [details] pushed as d0bae4a - sftp: Mark error string as translatable
Comment 11 Ondrej Holy 2017-01-06 15:39:45 UTC
Review of attachment 342875 [details] [review]:

This is useless, because the written size is not sent to the client anyway...
Comment 12 Ondrej Holy 2017-01-06 16:17:36 UTC
Created attachment 343030 [details] [review]
sftp: Limit writes to 32768 bytes

Write buffer is not limited in the backend and thus it might happen
that it tries to send data, which are too length. Unfortunatelly, in
that case the underlying SSH process may exit with "The connection is
closed (the underlying SSH process exited)" error and the backend is
force unmounted consequently.

It seems that there isn't any way to determine maximal allowed buffer
size for the server. The draft-ietf-secsh-filexfer-02.txt just says:

All servers SHOULD support packets of at least 34000 bytes (where the
packet size refers to the full length, including the header above).
This should allow for reads and writes of at most 32768 bytes.

Thus the maximal buffer size has to be limited to 32768. It will
probably cause some slowdown, but better than force unmount.
Comment 13 Ondrej Holy 2017-01-06 16:17:45 UTC
Created attachment 343031 [details] [review]
sftp: Merge 3 constants into one

MAX_BUFFER_SIZE, PULL_BLOCKSIZE, and PUSH_BLOCKSIZE defines the same
value. Let's merge them into MAX_BUFFER_SIZE.
Comment 14 Ondrej Holy 2017-01-06 16:19:11 UTC
Comment on attachment 342874 [details] [review]
sftp: Do not call force unmount twice

Attachment 342874 [details] pushed as df8a5df - sftp: Do not call force unmount twice
Comment 15 Ondrej Holy 2017-01-16 15:06:42 UTC
Attachment 343030 [details] pushed as 1482097 - sftp: Limit writes to 32768 bytes
Attachment 343031 [details] pushed as b0e627b - sftp: Merge 3 constants into one

The former also pushed in gnome-3-22.
Comment 16 Ondrej Holy 2017-06-07 11:51:31 UTC
*** Bug 668477 has been marked as a duplicate of this bug. ***