> -----Original Message-----
> From: libssh2-devel-bounces_at_cool.haxx.se
> [mailto:libssh2-devel-bounces_at_cool.haxx.se] On Behalf Of Peter Stuge
> Sent: Wednesday, February 17, 2010 6:04 PM
> To: libssh2-devel_at_cool.haxx.se
> Subject: Re: libssh2 takes long time to connect to CoreFTP's
> SFTP service
>
> Hello,
>
> Please note that version 1.2 is very old now, and several
> serious problems have been fixed in later versions. I
> strongly recommend upgrading to the latest version, which is 1.2.4.
Sure. I've downloaded 1.2.4 release and compiled it successfully with debug option enabled.
> I don't have a Windows system, and I think it is more
> appropriate for you to instead supply debug logs to those you
> ask for help.
No problem.
> Please upgrade to libssh2-1.2.4 and repeat the test with full
> debugging enabled. Use libssh2_trace(~0); Note that this only
> has an effect when the library is built with debug support
> enabled, which may not be the case if you install a package
> that someone else has built. It would be best if you built
> your own version of the library, to make sure that debugging
> is enabled, and to be able to test any changes that we
> suggest in order to fix the problem.
The log file is quite big, about 82KB in size. So I can only zip it and attach to the mail. The log is captured with the command "./sftpdir 13.xxx.xxx.xxx <user> <pass> /". And before this command and after it, I typed "date" command to indicate time difference.
From the log, it can be seen that the biggest time gap happens at around:
======================================================
[libssh2] 1.229831 SFTP: Data begin - Packet Length: 24
[libssh2] 1.229837 Socket: Error recving 16384 bytes to 0x8b01648+0: 11
[libssh2] 1.229843 Conn: channel_read() got 24 of data from 0/0/0 [ul]
[libssh2] 1.229848 SFTP: Received packet 101 (len 24)
[libssh2] 1.229854 SFTP: Asking for 101 packet
[libssh2] 1.229859 SFTP: Got 101
[libssh2] 1.229869 Conn: Freeing channel 0/0 resources
[libssh2] 1.229874 Conn: Closing channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 61 00 00 00 00 : a....
[libssh2] 1.229901 Socket: Sent 36/36 bytes at 0x8b014c0
=> libssh2_transport_write send() (36 bytes)
0000: AE FB 90 17 48 44 6D 9D 50 B5 4E 57 33 12 AE BF : ....HDm.P.NW3...
0010: 2D 7D 07 B4 CC C3 58 F6 B4 11 9A E2 2F 41 58 4C : -}....X...../AXL
0020: 98 77 2A 6B : .w*k
[libssh2] 1.229925 Socket: Error recving 16384 bytes to 0x8b01648+0: 11
[libssh2] 605.366124 Socket: Recved 68/16384 bytes to 0x8b01648+0
=> libssh2_transport_read() raw (68 bytes)
0000: 58 2A 02 22 99 31 38 39 9E 9B F5 12 1D DE 52 43 : X*.".189......RC
0010: A8 6F 17 49 F3 A1 FB 42 6F 05 58 6E EC 15 8E 5F : .o.I...Bo.Xn..._
0020: 9F 2A C0 5B 34 21 42 7F 1D 92 E0 2A 37 E4 CB 38 : .*.[4!B....*7..8
0030: 30 84 5C 4D E3 8E 64 FB A0 19 F4 E9 4D 18 D9 D4 : 0.\M..d.....M...
0040: 3E AA EA 32 : >..2
=> libssh2_transport_read() plain (26 bytes)
0000: 01 00 00 00 02 00 00 00 0D 44 69 73 63 6F 6E 6E : .........Disconn
0010: 65 63 74 69 6E 67 00 00 00 00 : ecting....
[libssh2] 605.366201 Transport: Packet type 1 received, length=26
[libssh2] 605.366207 Transport: Disconnect(2): Disconnecting()
[libssh2] 605.366212 Failure Event: -13 - socket disconnect
[libssh2] 605.366223 Transport: Disconnecting: reason=11, desc=Normal Shutdown,
Thank you for playing, lang=
=> libssh2_transport_write plain (51 bytes)
0000: 01 00 00 00 0B 00 00 00 26 4E 6F 72 6D 61 6C 20 : ........&Normal
0010: 53 68 75 74 64 6F 77 6E 2C 20 54 68 61 6E 6B 20 : Shutdown, Thank
0020: 79 6F 75 20 66 6F 72 20 70 6C 61 79 69 6E 67 00 : you for playing.
0030: 00 00 00 : ...
[libssh2] 605.366279 Socket: Sent 84/84 bytes at 0x8b01468
=> libssh2_transport_write send() (84 bytes)
0000: 97 84 9E 76 4A A9 C4 93 91 DA DB C4 9D F1 F3 9D : ...vJ...........
0010: C1 30 E0 E6 5D BF 27 45 AE 88 07 D6 26 B0 3D 00 : .0..].'E....&.=.
0020: 9F 0B B7 C2 C1 99 A2 3E 66 42 60 1E A5 3B DA 71 : .......>fB`..;.q
0030: 80 8E B9 4E EE 0B A5 A0 81 3D D4 57 16 45 7B DE : ...N.....=.W.E{.
0040: D5 55 ED 69 47 F3 DD C3 81 81 9C 22 5C 4F EC 9C : .U.iG......"\O..
0050: 4D DE 66 33 : M.f3
[libssh2] 605.366316 Transport: Freeing session resource
all done
======================================================
Please note the jump from 1.229925 to 605.366201.
> It seems that the problem happens during disconnect rather
> than during connect. It could also be interesting to test the
> SFTP client from PuTTY which is called PSFTP.exe. In any case
> this long delay is a problem and we should at least
> investigate why it happens and of course fix it if we can.
From the log, it seems that you are right, Peter! The delay happens in disconnecting from the server. CoreFTP allows me to observer server's log, which also indicates the problem:
======================================================
[#1] [20100217 18:27:58] [13.198.98.190] user 'qxu' sent
[#1] [20100217 18:27:58] [13.198.98.190] USER-PASS (qxu) success
[#1] [20100217 18:27:58] [13.198.98.190] LIST success - /
[#1] [20100217 18:38:02] [13.198.98.190] disconnected (qxu)
======================================================
More than 10 minutes are spent on disconnecting from the server. Very strange.
Another word: FileZilla is using PSFTP.exe to do SFTP transactions, and it is fast. Hope this helps.
Thanks a lot,
Xu Qiang
_______________________________________________
libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-devel