Subject: Re: SFTP Compression support

Re: SFTP Compression support

From: TJ Saunders <tj_at_castaglia.org>
Date: Tue, 31 Aug 2010 13:53:11 -0700 (PDT)

> Yes its 1.2.7. Compiled with mingw 4.4 under windows 7, OpenSSL 0.9.8 and
> zlib 1.2.3.
> As I've said, compression works when dealing with channels, but can't open
> sftp file handles.

I think that prior to 1.2.7, this wasn't possible -- attempting to use
compression would fail at KEXINIT time. The enabling of compression at
KEXINIT time was fixed by:

  http://trac.libssh2.org/ticket/180

However, it seems that fixing compression for KEXINIT revealed further
issues with using compression.

Using a build of libssh2-1.2.7 with --enable-debug, and tracing enabled, I
obtained the following trace for a case where libssh2 (via the Net::SSH2
Perl module) is used to authenticate, start sftp, open and read a file
from the server:

[libssh2] 2.627289 Conn: Connection Established - ID: 0/0 win: 4294967295/65536 pack: 32768/32768
[libssh2] 2.627309 Conn: starting request(subsystem) on channel 0/0, message=sftp
=> libssh2_transport_write plain (27 bytes)
0000: 62 00 00 00 00 00 00 00 09 73 75 62 73 79 73 74 : b........subsyst
0010: 65 6D 01 00 00 00 04 73 66 74 70 : em.....sftp
[libssh2] 2.627430 Socket: Sent 52/52 bytes at 0x982d9b0
=> libssh2_transport_write send() (52 bytes)
0000: 04 4F 35 48 5F D7 43 CE 7D F9 85 23 52 E4 0D 64 : .O5H_.C.}..#R..d
0010: 0C 9B 94 21 0D 37 66 5C 8B 18 7E 9B DF 81 04 26 : ...!.7f\..~....&
0020: 65 1E 4A 08 72 32 A2 E7 4B E7 CF 9B 44 1D 61 62 : e.J.r2..K...D.ab
0030: 29 00 87 47 : )..G
[libssh2] 2.627481 Transport: Looking for packet of type: 99
[libssh2] 2.627491 Transport: Looking for packet of type: 100
[libssh2] 2.627505 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.627518 Failure Event: -37 - Would block to request SFTP subsystem
[libssh2] 2.628586 Transport: Looking for packet of type: 99
[libssh2] 2.628603 Transport: Looking for packet of type: 100
[libssh2] 2.628618 Socket: Recved 52/16384 bytes to 0x981c578+0
=> libssh2_transport_read() raw (52 bytes)
0000: 03 24 AA 16 61 A1 4F 6A A6 8F 4E 9B B8 83 1D CD : .$..a.Oj..N.....
0010: C6 FB 04 92 49 B4 07 AD 4A 5E 62 1D 54 AB F8 82 : ....I...J^b.T...
0020: 2C 21 BD E4 71 1D 22 86 24 6D E2 4A EE 71 53 16 : ,!..q.".$m.J.qS.
0030: 35 83 F6 94 : 5...
=> libssh2_transport_read() plain (5 bytes)
0000: 63 00 00 00 00 : c....
[libssh2] 2.628704 Transport: Packet type 99 received, length=5
[libssh2] 2.628717 Transport: Looking for packet of type: 99
[libssh2] 2.628728 Conn: Setting channel 0/0 handle_extended_data mode to 1
[libssh2] 2.628746 SFTP: Sending FXP_INIT packet advertising version 3 support
[libssh2] 2.628758 Conn: Writing 9 bytes on channel 0/0, stream #0
[libssh2] 2.628773 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.628786 Conn: Sending 9 bytes on channel 0/0, stream_id=0
=> libssh2_transport_write plain (18 bytes)
0000: 5E 00 00 00 00 00 00 00 09 00 00 00 05 01 00 00 : ^...............
0010: 00 03 : ..
[libssh2] 2.628890 Socket: Sent 52/52 bytes at 0x982d9b0
=> libssh2_transport_write send() (52 bytes)
0000: AC 50 E0 7F E7 BC 8F 02 4D D1 E1 DF 4B 79 ED 0B : .P......M...Ky..
0010: B9 10 E6 AE 69 4D F9 9D F8 B6 F4 54 CD EB A8 BD : ....iM.....T....
0020: 5E 2A FA 28 CF B3 A0 27 9A 4C EC 2E 6A A6 79 97 : ^*.(...'.L..j.y.
0030: C6 5A BA DB : .Z..
[libssh2] 2.628942 SFTP: Requiring packet 2 id 0
[libssh2] 2.628952 SFTP: Asking for 2 packet
[libssh2] 2.628962 SFTP: recv packet
[libssh2] 2.628972 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.628986 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.628999 Failure Event: -37 - Would block waiting for response from SFTP subsystem
[libssh2] 2.630686 SFTP: Requiring packet 2 id 0
[libssh2] 2.630704 SFTP: Asking for 2 packet
[libssh2] 2.630714 SFTP: recv packet
[libssh2] 2.630723 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.630739 Socket: Recved 116/16384 bytes to 0x981c578+0
=> libssh2_transport_read() raw (116 bytes)
0000: AA C9 DD C3 31 4B FA 16 B3 A5 05 40 B8 A5 30 E0 : ....1K.....@..0.
0010: 88 02 CD 4F 07 6D C6 62 1F 46 91 BC 79 77 1D C4 : ...O.m.b.F..yw..
0020: 28 F6 20 F0 3A 81 A4 D2 53 C6 DC A2 47 EE CC 0F : (. .:...S...G...
0030: F8 EF 22 36 34 60 70 BC 72 94 19 50 D3 E4 53 02 : .."64`p.r..P..S.
0040: 0C AB 6E 60 5F AE D2 FB D3 10 0C C0 A6 C8 D6 0C : ..n`_...........
0050: BA 47 78 58 0D 8B B6 F1 5F 6C DF 8D F4 F9 DB AB : .GxX...._l......
0060: 52 EC AC 83 CF EB D0 B0 44 AE 6C 81 92 6C 89 FE : R.......D.l..l..
0070: F9 92 60 F1 : ..`.
=> libssh2_transport_read() plain (127 bytes)
0000: 5E 00 00 00 00 00 00 00 76 00 00 00 72 02 00 00 : ^.......v...r...
0010: 00 03 00 00 00 08 76 65 72 73 69 6F 6E 73 00 00 : ......versions..
0020: 00 03 32 2C 33 00 00 00 18 70 6F 73 69 78 2D 72 : ..2,3....posix-r
0030: 65 6E 61 6D 65 40 6F 70 65 6E 73 73 68 2E 63 6F : ename_at_openssh.co
0040: 6D 00 00 00 01 31 00 00 00 13 73 74 61 74 76 66 : m....1....statvf
0050: 73 40 6F 70 65 6E 73 73 68 2E 63 6F 6D 00 00 00 : s_at_openssh.com...
0060: 01 32 00 00 00 14 66 73 74 61 74 76 66 73 40 6F : .2....fstatvfs_at_o
0070: 70 65 6E 73 73 68 2E 63 6F 6D 00 00 00 01 32 : penssh.com....2
[libssh2] 2.630919 Transport: Packet type 94 received, length=127
[libssh2] 2.630931 Conn: 118 bytes packet_add() for 0/0/0
[libssh2] 2.630945 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.630958 Conn: channel_read() got 4 of data from 0/0/0
[libssh2] 2.630971 Conn: Adjusting window 3932160 bytes for data on channel 0/0
=> libssh2_transport_write plain (9 bytes)
0000: 5D 00 00 00 00 00 3C 00 00 : ].....<..
[libssh2] 2.631064 Socket: Sent 52/52 bytes at 0x982d9b0
=> libssh2_transport_write send() (52 bytes)
0000: A2 4A 5F A9 7F 6B 40 46 EE 90 9D 96 2B 46 FC 04 : .J_..k_at_F....+F..
0010: 52 FD 2E 48 E3 B0 0B 7F 9B 2F 50 0E A6 D9 CA E9 : R..H...../P.....
0020: 08 4F B1 D9 5A 76 4B C5 C5 C5 1F 12 08 07 82 62 : .O..ZvK........b
0030: 9F 4B 03 6A : .K.j
[libssh2] 2.631114 Conn: channel_read() filled 4 adjusted 4
[libssh2] 2.631125 SFTP: Data begin - Packet Length: 114
[libssh2] 2.631138 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.631150 Conn: channel_read() got 114 of data from 0/0/0 [ul]
[libssh2] 2.631163 SFTP: Received packet 2 (len 114)
[libssh2] 2.631174 SFTP: Asking for 2 packet
[libssh2] 2.631184 SFTP: Got 2
[libssh2] 2.631193 SFTP: Enabling SFTP version 3 compatability

So far, so good -- we're past KEXINIT, past the INIT/VERSION exchange for
starting the SFTP subsystem. Now we send the OPEN request:

[libssh2] 2.631291 SFTP: Sending file open request
[libssh2] 2.631305 Conn: Writing 33 bytes on channel 0/0, stream #0
[libssh2] 2.631320 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.631332 Conn: Sending 33 bytes on channel 0/0, stream_id=0
=> libssh2_transport_write plain (42 bytes)
0000: 5E 00 00 00 00 00 00 00 21 00 00 00 1D 03 00 00 : ^.......!.......
0010: 00 00 00 00 00 08 74 65 73 74 2E 74 78 74 00 00 : ......test.txt..
0020: 00 01 00 00 00 04 00 00 81 B6 : ..........
[libssh2] 2.631445 Socket: Sent 68/68 bytes at 0x982a230
=> libssh2_transport_write send() (68 bytes)
0000: 32 45 77 61 5E 43 D5 7B F8 D9 AE F8 CC 46 AE 3F : 2Ewa^C.{.....F.?
0010: 5A E9 A6 2C C4 BA 92 6C 3B FF A2 2E A3 6F AF ED : Z..,...l;....o..
0020: 98 35 AC 8D 4D B3 43 76 89 C2 D7 B1 DD 3F F8 0E : .5..M.Cv.....?..
0030: D7 3D ED 26 92 50 C5 60 2E 30 5C 75 E3 1C CE 45 : .=.&.P.`.0\u...E
0040: 76 13 60 89 : v.`.
[libssh2] 2.631502 SFTP: Asking for 102 packet
[libssh2] 2.631512 SFTP: Asking for 101 packet
[libssh2] 2.631521 SFTP: recv packet
[libssh2] 2.631532 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.631545 Failure Event: -37 - Would block waiting for status message
[libssh2] 2.672505 SFTP: Asking for 102 packet
[libssh2] 2.672529 SFTP: Asking for 101 packet
[libssh2] 2.672539 SFTP: recv packet
[libssh2] 2.672549 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.672568 Socket: Recved 52/16384 bytes to 0x981c578+0
=> libssh2_transport_read() raw (52 bytes)
0000: 92 20 1B 6B 03 00 7D 6C 2A DC 76 79 74 AF 05 2F : . .k..}l*.vyt../
0010: 6B BD 28 0F BA 45 97 D5 D4 3A 52 69 11 D2 13 9E : k.(..E...:Ri....
0020: AB 2A EC 87 A8 E7 09 08 D9 67 13 73 B9 9C 58 D6 : .*.......g.s..X.
0030: 6F 8E D6 8D : o...
=> libssh2_transport_read() plain (28 bytes)
0000: 5E 00 00 00 00 00 00 00 13 00 00 00 0F 66 00 00 : ^............f..
0010: 00 00 00 00 00 06 72 55 63 66 56 4F : ......rUcfVO
[libssh2] 2.672678 Transport: Packet type 94 received, length=28
[libssh2] 2.672690 Conn: 19 bytes packet_add() for 0/0/0
[libssh2] 2.672705 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.672718 Conn: channel_read() got 4 of data from 0/0/0
[libssh2] 2.672730 SFTP: Data begin - Packet Length: 15
[libssh2] 2.672742 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.672753 Conn: channel_read() got 15 of data from 0/0/0 [ul]
[libssh2] 2.672766 SFTP: Received packet 102 (len 15)
[libssh2] 2.672777 SFTP: Asking for 102 packet
[libssh2] 2.672792 SFTP: Open command successful

OK, the OPEN request succeeded. Now we send a READ, to start getting the
data in that file:

[libssh2] 2.672957 SFTP: Reading 8192 bytes from SFTP handle
[libssh2] 2.672974 Conn: Writing 31 bytes on channel 0/0, stream #0
[libssh2] 2.672990 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.673002 Conn: Sending 31 bytes on channel 0/0, stream_id=0
=> libssh2_transport_write plain (40 bytes)
0000: 5E 00 00 00 00 00 00 00 1F 00 00 00 1B 05 00 00 : ^...............
0010: 00 01 00 00 00 06 72 55 63 66 56 4F 00 00 00 00 : ......rUcfVO....
0020: 00 00 00 00 00 00 20 00 : ...... .
[libssh2] 2.673143 Socket: Sent 52/52 bytes at 0x90542b0
=> libssh2_transport_write send() (52 bytes)
0000: 12 3E F6 BB CD 52 EA 5A 12 6F BD 8C 87 2D 5E F8 : .>...R.Z.o...-^.
0010: 14 1D BB 79 A3 E2 F4 C5 30 14 B2 AD 1A E6 12 DC : ...y....0.......
0020: 9B A7 5D A9 DA E1 C9 A2 A6 0D D2 A3 FE C4 57 93 : ..]...........W.
0030: 87 D5 C6 F1 : ....
[libssh2] 2.673195 SFTP: Asking for 103 packet
[libssh2] 2.673205 SFTP: Asking for 101 packet
[libssh2] 2.673215 SFTP: recv packet
[libssh2] 2.673226 Socket: Error recving 16384 bytes to 0x981c578+0: 11
[libssh2] 2.673238 Failure Event: -37 - Would block waiting for status message
[libssh2] 2.675898 SFTP: Asking for 103 packet
[libssh2] 2.675915 SFTP: Asking for 101 packet
[libssh2] 2.675925 SFTP: recv packet
[libssh2] 2.675934 Conn: channel_read() wants 4 bytes from channel 0/0 stream #0
[libssh2] 2.675951 Socket: Recved 84/16384 bytes to 0x981c578+0
=> libssh2_transport_read() raw (84 bytes)
0000: F8 11 28 3A 61 F8 B0 69 06 C4 70 BB 64 24 95 B3 : ..(:a..i..p.d$..
0010: B1 71 2D CB B8 FB 60 D2 9E 7C 99 FA 68 88 6B 6C : .q-...`..|..h.kl
0020: A7 93 52 08 B6 ED 32 32 25 50 3A 2C 97 BB 7C 73 : ..R...22%P:,..|s
0030: 2F DA D1 59 84 82 57 3A 7E 7D 02 F1 34 EF D4 B3 : /..Y..W:~}..4...
0040: C3 C5 3D 50 B2 98 46 4A EB B3 EE CC 7B D1 79 1F : ..=P..FJ....{.y.
0050: DD E0 AC 69 : ...i
[libssh2] 2.676521 Failure Event: -29 - compress/decompression failure
[libssh2] 2.676537 Failure Event: -1 - transport read
[libssh2] 2.676547 Failure Event: -21 - Read part of packet
[libssh2] 2.676558 Failure Event: -1 - Timeout waiting for status message

And there, I think, is a sign of the issue:

  [libssh2] 2.676521 Failure Event: -29 - compress/decompression failure

The question is, though: why did the decompression fail? And why does it
fail at this point, when reading file data (as opposed to earlier, when
decompressing the rest of the messages on that subsystem/channel)?

I'll keep poking at this to see if I can find any additional clues...

TJ

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

   And forget not that the earth delights to feel your bare feet
   and the winds long to play with your hair.

     -Kahlil Gibran

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
_______________________________________________
libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-devel
Received on 2010-08-31