Re: SFTP read-ahead problem

[Tilo Eckert <tilo.eckert@xxxxxxx>]

Hi,

eventually I took the time to dig into the packet processing code and
managed to find the bug that caused random "Short sftp packet!" errors.

When there are multiple pending read requests, the OpenSSH server stuffs
multiple SFTP data packets into one CHANNEL_DATA packet until 32KiB are
full. As a result, SFTP packets may be split and sent as payload of
multiple CHANNEL_DATA packets. At some point, the length field of the
SFTP packet will be the splitting point. This is what sftp_packet_read()
is unable to handle. It calls ssh_channel_read() with length 4 and
expects to get 4 bytes, which ssh_channel_read() does not guarantee. In
the split length field situation, less than 4 bytes are read which
results in the aforementioned error.

A patch is attached which reads the length field in a loop until 4 bytes
are read.

Tilo

Am 08.06.2015 um 13:09 schrieb Tilo Eckert:
> I used libssh 0.7.0 for my tests. The 0.6 branch from git has the same
> issue. Of the 0.6.x source tarballs none of them compiles here (ArchLinux).
> 
> Here is a verbose log where the sftp_close() does not get stuck (remote
> host, run with N=1024):
> https://paste.ee/p/A4N4i
> and here it gets stuck (same host/file, N=128):
> https://paste.ee/p/WoIeY
> 
> Regards,
> Tilo
> 
> Am 08.06.2015 um 12:04 schrieb Aris Adamantiadis:
>> Hi,
>>
>> I agree with your analysis. Which libssh version did you use ? Could you
>> try again with 0.6.0 and tell us if the same happens ?
>> Please attach verbose logs.
>>
>> Aris
>>
>> Le 08/06/15 11:46, Tilo Eckert a écrit :
>>> Hi,
>>>
>>> I am trying to implement a simple read-ahead mechanism for reading large
>>> files via SFTP using sftp_async_read_begin() and sftp_async_read(). On
>>> the first attempt to read a 4096 bytes block, I request N times 4K, and
>>> read the first 4K block. On successive reads, for each block read
>>> another one is requested to keep N requests on the wire.
>>>
>>> The problem is: sftp_async_read() suddenly fails with the error message
>>> "Short sftp packet!" after successfully reading a few hundred packets
>>> when N is large enough and the server is running OpenSSH. For a remote
>>> host over a 5 Mbit internet connection with 60ms latency, the issue
>>> starts when requesting more than about 70 blocks. In my tests on GBit
>>> LAN, the issue started for somewhat larger values of N.
>>>
>>> When I attempt to call sftp_async_read() or sftp_close() after the error
>>> occurs, I can see from the libssh log that all requests are actually
>>> fulfilled by the server (i.e. N * 4K are received by the socket). For
>>> certain combinations of N and network connection, calls to these
>>> functions also get stuck and never return. In other cases, closing fails
>>> with "Unknown packet type 0".
>>>
>>> Here is a sample program that demonstrates the issue:
>>> http://pastebin.com/gfiFKfDT
>>>
>>> I tested this with different OpenSSH versions between 6.0 and 6.8 on
>>> Windows and Linux, and with freeSSHd on Windows. With all OpenSSH
>>> versions, I get the described behavior. With freeSSHd, there are no
>>> issues at all. I successfully tested it with up to N=4096 (i.e. 16 MiB
>>> read-ahead).
>>>
>>> It looks to me like libssh starts to misinterpret packets under certain
>>> conditions. Maybe someone with deeper insight can investigate this.
>>>
>>> Regards,
>>> Tilo
>>>
>>
>>
> 
> 

From e0a3b56610ca35e2c24cc52b1efbe75b1b5479e2 Mon Sep 17 00:00:00 2001
From: Tilo Eckert <tilo.eckert@xxxxxxx>
Date: Fri, 31 Jul 2015 13:22:02 +0200
Subject: sftp: Fix incorrect handling of received length fields

Signed-off-by: Tilo Eckert <tilo.eckert@xxxxxxx>
---
 src/sftp.c | 20 +++++++++++++-------
 1 file changed, 13 insertions(+), 7 deletions(-)

diff --git a/src/sftp.c b/src/sftp.c
index 56093fb..39d0819 100644
--- a/src/sftp.c
+++ b/src/sftp.c
@@ -307,7 +307,7 @@ sftp_packet sftp_packet_read(sftp_session sftp) {
   sftp_packet packet = NULL;
   uint32_t tmp;
   size_t size;
-  int r;
+  int r, s;
 
   packet = malloc(sizeof(struct sftp_packet_struct));
   if (packet == NULL) {
@@ -322,12 +322,18 @@ sftp_packet sftp_packet_read(sftp_session sftp) {
     return NULL;
   }
 
-  r=ssh_channel_read(sftp->channel, buffer, 4, 0);
-  if (r < 0) {
-    ssh_buffer_free(packet->payload);
-    SAFE_FREE(packet);
-    return NULL;
-  }
+  r=0;
+  do {
+    // read from channel until 4 bytes have been read or an error occurs
+    s=ssh_channel_read(sftp->channel, buffer+r, 4-r, 0);
+    if (s < 0) {
+      ssh_buffer_free(packet->payload);
+      SAFE_FREE(packet);
+      return NULL;
+    } else {
+      r += s;
+    }
+  } while (r<4);
   ssh_buffer_add_data(packet->payload, buffer, r);
   if (buffer_get_u32(packet->payload, &tmp) != sizeof(uint32_t)) {
     ssh_set_error(sftp->session, SSH_FATAL, "Short sftp packet!");
-- 
2.5.0