Update: I had to move to Linux so I could mess with the examples. Easier
than creating a new VC project for the samples.
On Linux if I modify the buffer to be 65535, then I get a similar failure.
After the first few iterations of libssh2_sftp_write() it will hang trying
to do the next write (notice the -37 and -39 errors just like Jeremy is
reporting I think). Using the same sample but a buffer size of 1024 then
everything works just fine. I have not tried moving back to a buffer size of
1024 on my production code because the large buffer does work on older
versions of libssh2. The file I am trying to transfer is a 29MB BZip2'ed
archive if that matters.
Below is the trace and bt once it hangs.
Starting program:
/home/giermang/code/libssh2-1.2.1-20090917/example/simple/.libs/sftp_write
XX.XX.XX.XX
[libssh2] 0.985829 Conn: Setting blocking mode ON
[libssh2] 0.985962 Failure Event: -37 - Failed getting banner
[libssh2] 1.041698 Failure Event: -37 - Unable to exchange encryption keys
[libssh2] 1.048988 Failure Event: -37 - Unable to exchange encryption keys
Fingerprint: 4D 31 8F 78 0F 5B 55 92 9A BC FA 43 61 D6 53 89
libssh2_sftp_init()!
[libssh2] 1.620275 SFTP: Initializing SFTP subsystem
[libssh2] 1.620294 Conn: Allocated new channel ID#0
[libssh2] 1.620304 Conn: Opening Channel - win 65536 pack 32768
[libssh2] 1.620411 Failure Event: -37 - Would block
[libssh2] 1.620433 Failure Event: -37 - Would block starting up channel
[libssh2] 1.621779 Conn: Connection Established - ID: 0/0 win: 0/65536 pack:
32768/32768
[libssh2] 1.621805 Conn: starting request(subsystem) on channel 0/0,
message=sftp
[libssh2] 1.621871 Failure Event: -37 - Would block to request SFTP
subsystem
[libssh2] 1.639489 Conn: Window adjust received for channel 0/0, adding
131072 bytes, new window_size=131072
[libssh2] 1.639536 Conn: Setting channel 0/0 handle_extended_data mode to 1
[libssh2] 1.639549 SFTP: Sending FXP_INIT packet advertising version 3
support
[libssh2] 1.639559 Conn: Writing 9 bytes on channel 0/0, stream #0
[libssh2] 1.639578 Conn: Sending 9 bytes on channel 0/0, stream_id=0
[libssh2] 1.639644 SFTP: Requiring packet 2 id 0
[libssh2] 1.639656 SFTP: Asking for 2 packet
[libssh2] 1.639665 SFTP: recv packet
[libssh2] 1.639677 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 1.639691 Failure Event: -37 - Would block waiting for response
from SFTP subsystem
[libssh2] 1.655304 SFTP: Requiring packet 2 id 0
[libssh2] 1.655317 SFTP: Asking for 2 packet
[libssh2] 1.655326 SFTP: recv packet
[libssh2] 1.655334 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 1.655377 Conn: 9 bytes packet_add() for 0/0/0
[libssh2] 1.655402 Conn: channel_read() got 4 of data from 0/0/0
[libssh2] 1.655413 Conn: Adjusting window 39321600 bytes for data on channel
0/0
[libssh2] 1.655467 Conn: channel_read() filled 4 adjusted 4
[libssh2] 1.655479 SFTP: Data begin - Packet Length: 5
[libssh2] 1.655491 Conn: channel_read() got 5 of data from 0/0/0 [ul]
[libssh2] 1.655502 SFTP: Received packet 2 (len 5)
[libssh2] 1.655511 SFTP: Asking for 2 packet
[libssh2] 1.655520 SFTP: Got 2
[libssh2] 1.655528 SFTP: Enabling SFTP version 3 compatability
libssh2_sftp_open()!
[libssh2] 1.655561 SFTP: Sending file open request
[libssh2] 1.655571 Conn: Writing 56 bytes on channel 0/0, stream #0
[libssh2] 1.655584 Conn: Sending 56 bytes on channel 0/0, stream_id=0
[libssh2] 1.655615 SFTP: Asking for 102 packet
[libssh2] 1.655625 SFTP: Asking for 101 packet
[libssh2] 1.655634 SFTP: recv packet
[libssh2] 1.655649 Failure Event: -37 - Would block waiting for status
message
[libssh2] 1.699556 SFTP: Asking for 102 packet
[libssh2] 1.699576 SFTP: Asking for 101 packet
[libssh2] 1.699586 SFTP: recv packet
[libssh2] 1.699594 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 1.699632 Conn: 17 bytes packet_add() for 0/0/0
[libssh2] 1.699647 Conn: channel_read() got 4 of data from 0/0/0
[libssh2] 1.699657 SFTP: Data begin - Packet Length: 13
[libssh2] 1.699669 Conn: channel_read() got 13 of data from 0/0/0 [ul]
[libssh2] 1.699679 SFTP: Received packet 102 (len 13)
[libssh2] 1.699689 SFTP: Asking for 102 packet
[libssh2] 1.699701 SFTP: Open command successful
libssh2_sftp_open() is done, now send data!
[libssh2] 1.699880 SFTP: Writing 65535 bytes
[libssh2] 1.699993 Conn: Writing 32768 bytes on channel 0/0, stream #0
[libssh2] 1.700057 Conn: Sending 32768 bytes on channel 0/0, stream_id=0
[libssh2] 1.701486 Failure Event: -37 - Unable to send channel data
[libssh2] 1.704104 Conn: Writing 29 bytes on channel 0/0, stream #0
[libssh2] 1.704129 Conn: Sending 29 bytes on channel 0/0, stream_id=0
[libssh2] 1.704139 Failure Event: -39 - Unable to send channel data
[libssh2] 1.704208 Conn: Writing 32768 bytes on channel 0/0, stream #0
[libssh2] 1.704237 Conn: Sending 32768 bytes on channel 0/0, stream_id=0
[libssh2] 1.704370 Failure Event: -37 - Unable to send channel data
[libssh2] 1.705758 Conn: Writing 29 bytes on channel 0/0, stream #0
[libssh2] 1.705778 Conn: Sending 29 bytes on channel 0/0, stream_id=0
[libssh2] 1.705788 Failure Event: -39 - Unable to send channel data
[libssh2] 1.705907 Conn: Writing 32768 bytes on channel 0/0, stream #0
[libssh2] 1.705936 Conn: Sending 32768 bytes on channel 0/0, stream_id=0
[libssh2] 1.705971 Conn: Writing 29 bytes on channel 0/0, stream #0
[libssh2] 1.705992 Conn: Sending 29 bytes on channel 0/0, stream_id=0
[libssh2] 1.706024 SFTP: Requiring packet 101 id 1
[libssh2] 1.706075 SFTP: Asking for 101 packet
[libssh2] 1.706087 SFTP: recv packet
Program received signal SIGINT, Interrupt.
0x005457a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
(gdb) bt
#0 0x005457a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
#1 0x0062391d in ___newselect_nocancel () from /lib/tls/libc.so.6
#2 0x00b07d04 in _libssh2_wait_socket (session=0x92a2170) at session.c:526
#3 0x00b0d78c in libssh2_sftp_write (hnd=0x92a7b10,
buffer=0xbff23060
"ìöü;\tY+VF7×ý(¿\203<e|\207ýX\210Fìv,\001+\017Q\224\232J\2208M/ì>Kódø½\025£ä
lÁÊç?h²�...@ð(þæ\027\035\232¶$Û\213ÒðÆ$Wà½à¹\215i&°ã\177\fð»\037Ú`B\206´¦£yèÁp
%Ò\205ØUÝKT\235ѾÌlEñKµ\vÓ¾Z;&\215:N¬9ãa«\226ÒN\\ï\006\001", count=0) at
sftp.c:1517
#4 0x08048f1f in main (argc=2, argv=0xbff2b144) at sftp_write.c:185
(gdb)
> -----Original Message-----
> From: [email protected] [mailto:libssh2-devel-
> [email protected]] On Behalf Of Neil Gierman
> Sent: Thursday, September 17, 2009 1:55 PM
> To: 'libssh2 development'
> Subject: SFTP Failure
>
> I don't know for sure if this is related to Jeremy's issue so I didn't
> want
> to hijack his thread.
>
> I am uploading a 32MB file over SFTP using libssh2_sftp_write, I am not
> specifically setting any blocking mode on the session. I right now have
> a
> 32K buffer and I see the trace below (trace set with
> "LIBSSH2_TRACE_ERROR|LIBSSH2_TRACE_CONN|LIBSSH2_TRACE_SFTP"). I was
> running
> a 64K buffer with similar errors but don't have a trace for that
> session.
> What bothers me is the window adjust and then channel exit. Can you
> tell me
> where to look for the different Exit statuses? Without seeing any
> source
> code that duplicates this I know I am asking for a lot but from the
> trace is
> there something that stands out? I will try to see if I can get one of
> the
> SFTP samples to produce the same results. On the ssh server the only
> thing I
> see is "sftp-server: error: bad message from ###.###.###.### local user
> ******", no other errors. FYI, this is in Windows if that makes a
> difference. Last detail - this same code works with 0.18 although I
> know
> quite a bit has changed since 0.18.
>
> [libssh2] 0.722649 SFTP: Initializing SFTP subsystem
> [libssh2] 0.722649 Conn: Allocated new channel ID#0
> [libssh2] 0.722649 Conn: Opening Channel - win 65536 pack 32768
> [libssh2] 0.723649 Failure Event: -37 - Would block
> [libssh2] 0.723649 Failure Event: -37 - Would block starting up channel
> [libssh2] 0.726650 Conn: Connection Established - ID: 0/0 win: 0/65536
> pack:
> 32768/32768
> [libssh2] 0.726650 Conn: starting request(subsystem) on channel 0/0,
> message=sftp
> [libssh2] 0.727650 Failure Event: -37 - Would block to request SFTP
> subsystem
> [libssh2] 0.746652 Conn: Window adjust received for channel 0/0, adding
> 131072 bytes, new window_size=131072
> [libssh2] 0.746652 Conn: Setting channel 0/0 handle_extended_data mode
> to 1
> [libssh2] 0.746652 SFTP: Sending FXP_INIT packet advertising version 3
> support
> [libssh2] 0.747652 Conn: Writing 9 bytes on channel 0/0, stream #0
> [libssh2] 0.747652 Conn: Sending 9 bytes on channel 0/0, stream_id=0
> [libssh2] 0.747652 SFTP: Requiring packet 2 id 0
> [libssh2] 0.748652 SFTP: Asking for 2 packet
> [libssh2] 0.748652 SFTP: recv packet
> [libssh2] 0.748652 Conn: channel_read() wants 4 bytes from channel 0/0
> stream #0
>
> [libssh2] 0.748652 Failure Event: -37 - Would block waiting for
> response
> from SFTP subsystem
> [libssh2] 0.762653 SFTP: Requiring packet 2 id 0
> [libssh2] 0.762653 SFTP: Asking for 2 packet
> [libssh2] 0.762653 SFTP: recv packet
> [libssh2] 0.762653 Conn: channel_read() wants 4 bytes from channel 0/0
> stream #0
>
> [libssh2] 0.763653 Conn: 9 bytes packet_add() for 0/0/0
> [libssh2] 0.763653 Conn: channel_read() got 4 of data from 0/0/0
> [libssh2] 0.763653 Conn: Adjusting window 39321600 bytes for data on
> channel
> 0/0
>
> [libssh2] 0.763653 Conn: channel_read() filled 4 adjusted 4
> [libssh2] 0.765654 SFTP: Data begin - Packet Length: 5
> [libssh2] 0.767654 Conn: channel_read() got 5 of data from 0/0/0 [ul]
> [libssh2] 0.768654 SFTP: Received packet 2 (len 5)
> [libssh2] 0.770654 SFTP: Asking for 2 packet
> [libssh2] 0.772654 SFTP: Got 2
> [libssh2] 0.774654 SFTP: Enabling SFTP version 3 compatability
> [libssh2] 0.781655 SFTP: Sending directory open request
> [libssh2] 0.783655 Conn: Writing 34 bytes on channel 0/0, stream #0
> [libssh2] 0.784655 Conn: Sending 34 bytes on channel 0/0, stream_id=0
> [libssh2] 0.786656 SFTP: Asking for 102 packet
> [libssh2] 0.788656 SFTP: Asking for 101 packet
> [libssh2] 0.789656 SFTP: recv packet
> [libssh2] 0.791656 Failure Event: -37 - Would block waiting for status
> message
> [libssh2] 0.807658 SFTP: Asking for 102 packet
> [libssh2] 0.808658 SFTP: Asking for 101 packet
> [libssh2] 0.810658 SFTP: recv packet
> [libssh2] 0.812658 Conn: channel_read() wants 4 bytes from channel 0/0
> stream #0
>
> [libssh2] 0.815659 Conn: 17 bytes packet_add() for 0/0/0
> [libssh2] 0.816659 Conn: channel_read() got 4 of data from 0/0/0
> [libssh2] 0.818659 SFTP: Data begin - Packet Length: 13
> [libssh2] 0.820659 Conn: channel_read() got 13 of data from 0/0/0 [ul]
> [libssh2] 0.821659 SFTP: Received packet 102 (len 13)
> [libssh2] 0.823659 SFTP: Asking for 102 packet
> [libssh2] 0.825660 SFTP: Open command successful
> [libssh2] 0.827660 SFTP: Sending file open request
> [libssh2] 0.828660 Conn: Writing 56 bytes on channel 0/0, stream #0
> [libssh2] 0.830660 Conn: Sending 56 bytes on channel 0/0, stream_id=0
> [libssh2] 0.832660 SFTP: Asking for 102 packet
> [libssh2] 0.833660 SFTP: Asking for 101 packet
> [libssh2] 0.835661 SFTP: recv packet
> [libssh2] 0.837661 Conn: 17 bytes packet_add() for 0/0/0
> [libssh2] 0.838661 Conn: channel_read() got 4 of data from 0/0/0
> [libssh2] 0.841661 SFTP: Data begin - Packet Length: 13
> [libssh2] 0.842661 Conn: channel_read() got 13 of data from 0/0/0 [ul]
> [libssh2] 0.844661 SFTP: Received packet 102 (len 13)
> [libssh2] 0.846662 SFTP: Asking for 102 packet
> [libssh2] 0.848662 SFTP: Open command successful
> [libssh2] 5.866164 SFTP: Writing 32768 bytes
> [libssh2] 5.869164 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.870164 Conn: Sending 32768 bytes on channel 0/0,
> stream_id=0
> [libssh2] 5.880165 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.882165 Conn: Sending 32768 bytes on channel 0/0,
> stream_id=0
> [libssh2] 5.892166 Failure Event: -37 - Unable to send channel data
> [libssh2] 5.928170 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.930170 Conn: Sending 32768 bytes on channel 0/0,
> stream_id=0
> [libssh2] 5.940171 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.942171 Conn: Splitting write block due to 32669 byte
> window_size
> on 0/0/0
> [libssh2] 5.945171 Conn: Sending 32669 bytes on channel 0/0,
> stream_id=0
> [libssh2] 5.954172 Conn: Window adjust received for channel 0/0, adding
> 48995 bytes, new window_size=48995
> [libssh2] 5.957173 Conn: Exit status 11 received for channel 0/0
> [libssh2] 5.959173 Conn: 28 bytes packet_add() for 0/0/0
> [libssh2] 5.961173 Conn: Sending 99 bytes on channel 0/0, stream_id=0
> [libssh2] 5.962173 Failure Event: -37 - Unable to send channel data
> [libssh2] 5.964173 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.966174 Conn: EOF received for channel 0/0
> [libssh2] 5.968174 Conn: Close received for channel 0/0
> [libssh2] 5.970174 Conn: Sending 32768 bytes on channel 0/0,
> stream_id=0
> [libssh2] 5.979175 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.981175 Conn: Splitting write block due to 16128 byte
> window_size
> on 0/0/0
> [libssh2] 5.985175 Conn: Sending 16128 bytes on channel 0/0,
> stream_id=0
> [libssh2] 5.994176 Conn: Writing 32768 bytes on channel 0/0, stream #0
> [libssh2] 5.996177 Conn: Writing 32768 bytes on channel 0/0, stream #0
> .....The rest of the trace is filled with these "Writing 32768 bytes"
> on a
> channel that now looks closed
>
> _______________________________________________
> libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-
> devel
_______________________________________________
libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-devel
