sftp connection takes 6 seconds

Question

Can anyone shed any insight on why it would take 6 seconds to establish a connection? File upload/download is very quick, but the initial connection is very slow. We are using No Server Validation. This is a Windows Server 2003 environment. Not sure what the sftp stack is, unfortunately.

By comparison, when we use putty to establish a connection, it is virtually immediate.

Answer 1

If you can post a log file set to the Debug level that should tell us what the slow part is pretty quickly.

Answer 2

Sorry, didn't know about that feature. Here is the log:

DEBUG [LicenseProperties] 12 Jan 2009 10:09:20.630 : Looking for subkey Software\Enterprise Distributed Technologies\edtFTPnet PRO (fallback )
DEBUG [LicenseProperties] 12 Jan 2009 10:09:20.630 : Found license subkey Software\Enterprise Distributed Technologies\edtFTPnet PRO
DEBUG [LicenseProperties] 12 Jan 2009 10:09:20.630 : Looking for subkey Software\Enterprise Distributed Technologies\edtFTPnet PRO (fallback )
DEBUG [LicenseProperties] 12 Jan 2009 10:09:20.630 : Found license subkey Software\Enterprise Distributed Technologies\edtFTPnet PRO
INFO [LicenseProperties] 12 Jan 2009 10:09:20.660 : Licence expiry date: 2/12/2009
INFO [LicenseProperties] 12 Jan 2009 10:09:20.660 : Trial license
DEBUG [FTPConnection] 12 Jan 2009 10:09:20.670 : Set LocalDirectory='D:\My Documents\Visual Studio 2008\Projects\sftp\WindowsFormsApplication1\bin\Debug'
INFO [LicenseProperties] 12 Jan 2009 10:09:20.670 : Licence expiry date: 2/12/2009
INFO [LicenseProperties] 12 Jan 2009 10:09:20.670 : Trial license
DEBUG [SSHFTPClient] 12 Jan 2009 10:09:20.670 : Setting up fallback kbi prompt based on supplied password
DEBUG [HostNameResolver] 12 Jan 2009 10:09:20.841 : 192.168.153.156 resolved to 192.168.153.156
DEBUG [SSHFTPClient] 12 Jan 2009 10:09:20.841 : Connecting directly to SFTP server 192.168.153.156:22
DEBUG [SSHFTPClient] 12 Jan 2009 10:09:20.871 : Connected successfully to SFTP server 192.168.153.156:22
DEBUG [SSHConnection] 12 Jan 2009 10:09:20.871 : Beginning protocol negotiation
DEBUG [PlainSocket] 12 Jan 2009 10:09:21.051 : RepeatCallback received 20 bytes
DEBUG [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : offset=0,length=20
DEBUG [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : pos=19
INFO [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : Server version = 'SSH-2.0-OpenSSH_4.6'
DEBUG [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : Major string = '2'
DEBUG [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : Minor string = '0'
DEBUG [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : Version 2.0
DEBUG [ProtocolNegotiationHandler] 12 Jan 2009 10:09:21.051 : Protocol compatible
DEBUG [SSHConnection] 12 Jan 2009 10:09:21.051 : Server version=SSH-2.0-OpenSSH_4.6
DEBUG [SSH2Connection] 12 Jan 2009 10:09:21.051 : Timeout=120000
DEBUG [SSHConnection] 12 Jan 2009 10:09:21.061 : Sending client version=SSH-2.0-edtFTPnet/PRO-6.0.0.20
DEBUG [SSH2Connection] 12 Jan 2009 10:09:21.061 : Starting key exchange
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.061 : Sending SSH_MSG_KEXINIT
DEBUG [PlainSocket] 12 Jan 2009 10:09:21.121 : RepeatCallback received 744 bytes
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:21.252 : ConstructPacket: _cipher=null,len=740
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:21.252 : Writeoffset=744,Readoffset=744
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.252 : Client hostkey algorithms=ssh-dss,ssh-rsa
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Client ciphers=aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Client ciphers=aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,3des-cbc
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Client MACs=hmac-sha1,hmac-md5
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Client MACs=hmac-sha1,hmac-md5
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Client compression algorithms=none,zlib
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Client compression algorithms=none,zlib
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.262 : Sent SSH_MSG_KEXINIT
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.472 : Reading SSH_MSG_KEXINIT reply
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Processing SSH_MSG_KEXINIT reply
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Kex alg=diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Hostkey alg=ssh-rsa,ssh-dss
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Cipher CS=aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Cipher C->S= AES128
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Cipher SC=aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : Cipher S->C= AES128
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.482 : MAC CS=hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : MAC C->S= HMACSHA1
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : MAC SC=hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : MAC S->C= HMACSHA1
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : Comp CS=none,zlib@openssh.com
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : Comp C->S=None
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : Comp SC=none,zlib@openssh.com
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : Comp S->C=None
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : Processed SSH_MSG_KEXINIT reply
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.693 : Sending SSH_MSG_KEXDH_INIT
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.753 : Sent SSH_MSG_KEXDH_INIT
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.753 : Reading SSH_MSG_KEXDH_INIT reply
DEBUG [SSH2Connection] 12 Jan 2009 10:09:21.753 : Waiting for packet
DEBUG [PlainSocket] 12 Jan 2009 10:09:21.783 : RepeatCallback received 656 bytes
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:21.954 : ConstructPacket: _cipher=null,len=636
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:21.954 : ConstructPacket: _cipher=null,len=12
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:21.954 : Writeoffset=656,Readoffset=656
DEBUG [SSH2Connection] 12 Jan 2009 10:09:21.954 : Packet arrived
DEBUG [KeyExchanger] 12 Jan 2009 10:09:21.954 : Processing SSH_MSG_KEXDH_INIT reply
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.084 : Processed SSH_MSG_KEXDH_INIT reply successfully
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.084 : Sending SSH_MSG_NEWKEYS
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.084 : Sent SSH_MSG_NEWKEYS
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.114 : Established ciphers
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.114 : Established MACs
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.114 : Reading SSH_MSG_NEWKEYS reply
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.114 : Processing SSH_MSG_NEWKEYS reply
DEBUG [KeyExchanger] 12 Jan 2009 10:09:22.244 : Processed SSH_MSG_NEWKEYS reply
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.244 : Key exchange complete
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.244 : Sent SSH_MSG_SERVICE_REQUEST 'ssh-userauth'
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.244 : Waiting for packet
DEBUG [PlainSocket] 12 Jan 2009 10:09:22.335 : RepeatCallback received 52 bytes
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:22.335 : Writeoffset=52,Readoffset=52
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Packet arrived
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Starting user authentication
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Password authentication
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Sent SSH_MSG_USERAUTH_REQUEST
DEBUG [SSH2Connection] 12 Jan 2009 10:

Answer 3

Also, I found out we are using Cygwin 1.5.24, again on Windows Server 2003

Answer 4

Here's where it is slow:

DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Password authentication
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Sent SSH_MSG_USERAUTH_REQUEST
DEBUG [SSH2Connection] 12 Jan 2009 10:09:22.335 : Waiting for packet
DEBUG [PlainSocket] 12 Jan 2009 10:09:26.896 : RepeatCallback received 36 bytes
DEBUG [SSH2PacketBuilder] 12 Jan 2009 10:09:26.896 : Writeoffset=36,Readoffset=36

So the auth request was sent to the server, and it took 4.5 s to respond.

What kind of authentication is puTTY doing? If it is doing publickey authentication instead of password, that might explain the difference in response time. I think puTTY should have a log file, so that should tell you.

Answer 5

Here is the puTTY log, if you see anything interesting. I connected, entered user id, entered password, and logged out.

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2009.01.13 12:57:35 =~=~=~=~=~=~=~=~=~=~=~=
Event Log: Writing new session log (SSH packets mode) to file: putty.log
Event Log: Looking up host "192.168.153.156"
Event Log: Connecting to 192.168.153.156 port 22
Event Log: Server version: SSH-2.0-OpenSSH_4.6
Event Log: We claim version: SSH-2.0-PuTTY_Release_0.60
Outgoing packet type 20 / 0x14 (SSH2_MSG_KEXINIT)
00000000 95 e8 70 bb 64 f1 f4 e9 ea 80 b2 6b ad 8d a9 cb ..p.d......k....
00000010 00 00 00 7e 64 69 66 66 69 65 2d 68 65 6c 6c 6d ...~diffie-hellm
00000020 61 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 an-group-exchang
00000030 65 2d 73 68 61 32 35 36 2c 64 69 66 66 69 65 2d e-sha256,diffie-
00000040 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 2d 65 78 hellman-group-ex
00000050 63 68 61 6e 67 65 2d 73 68 61 31 2c 64 69 66 66 change-sha1,diff
00000060 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 ie-hellman-group
00000070 31 34 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 14-sha1,diffie-h
00000080 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 2d 73 68 ellman-group1-sh
00000090 61 31 00 00 00 0f 73 73 68 2d 72 73 61 2c 73 73 a1....ssh-rsa,ss
000000a0 68 2d 64 73 73 00 00 00 9f 61 65 73 32 35 36 2d h-dss....aes256-
000000b0 63 74 72 2c 61 65 73 32 35 36 2d 63 62 63 2c 72 ctr,aes256-cbc,r
000000c0 69 6a 6e 64 61 65 6c 2d 63 62 63 40 6c 79 73 61 ijndael-cbc@lysa
000000d0 74 6f 72 2e 6c 69 75 2e 73 65 2c 61 65 73 31 39 tor.liu.se,aes19
000000e0 32 2d 63 74 72 2c 61 65 73 31 39 32 2d 63 62 63 2-ctr,aes192-cbc
000000f0 2c 61 65 73 31 32 38 2d 63 74 72 2c 61 65 73 31 ,aes128-ctr,aes1
00000100 32 38 2d 63 62 63 2c 62 6c 6f 77 66 69 73 68 2d 28-cbc,blowfish-
00000110 63 74 72 2c 62 6c 6f 77 66 69 73 68 2d 63 62 63 ctr,blowfish-cbc
00000120 2c 33 64 65 73 2d 63 74 72 2c 33 64 65 73 2d 63 ,3des-ctr,3des-c
00000130 62 63 2c 61 72 63 66 6f 75 72 32 35 36 2c 61 72 bc,arcfour256,ar
00000140 63 66 6f 75 72 31 32 38 00 00 00 9f 61 65 73 32 cfour128....aes2
00000150 35 36 2d 63 74 72 2c 61 65 73 32 35 36 2d 63 62 56-ctr,aes256-cb
00000160 63 2c 72 69 6a 6e 64 61 65 6c 2d 63 62 63 40 6c c,rijndael-cbc@l
00000170 79 73 61 74 6f 72 2e 6c 69 75 2e 73 65 2c 61 65 ysator.liu.se,ae
00000180 73 31 39 32 2d 63 74 72 2c 61 65 73 31 39 32 2d s192-ctr,aes192-
00000190 63 62 63 2c 61 65 73 31 32 38 2d 63 74 72 2c 61 cbc,aes128-ctr,a
000001a0 65 73 31 32 38 2d 63 62 63 2c 62 6c 6f 77 66 69 es128-cbc,blowfi
000001b0 73 68 2d 63 74 72 2c 62 6c 6f 77 66 69 73 68 2d sh-ctr,blowfish-
000001c0 63 62 63 2c 33 64 65 73 2d 63 74 72 2c 33 64 65 cbc,3des-ctr,3de
000001d0 73 2d 63 62 63 2c 61 72 63 66 6f 75 72 32 35 36 s-cbc,arcfour256
000001e0 2c 61 72 63 66 6f 75 72 31 32 38 00 00 00 1f 68 ,arcfour128....h
000001f0 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 2d 73 68 mac-sha1,hmac-sh
00000200 61 31 2d 39 36 2c 68 6d 61 63 2d 6d 64 35 00 00 a1-96,hmac-md5..
00000210 00 1f 68 6d 61 63 2d 73 68 61 31 2c 68 6d 61 63 ..hmac-sha1,hmac
00000220 2d 73 68 61 31 2d 39 36 2c 68 6d 61 63 2d 6d 64 -sha1-96,hmac-md
00000230 35 00 00 00 09 6e 6f 6e 65 2c 7a 6c 69 62 00 00 5....none,zlib..
00000240 00 09 6e 6f 6e 65 2c 7a 6c 69 62 00 00 00 00 00 ..none,zlib.....
00000250 00 00 00 00 00 00 00 00 ........
Event Log: Using SSH protocol version 2
Incoming packet type 20 / 0x14 (SSH2_MSG_KEXINIT)
00000000 80 dc 11 79 61 ba 7b b6 77 2c b2 06 c6 7b 4b 54 ...ya.{.w,...{KT
00000010 00 00 00 7e 64 69 66 66 69 65 2d 68 65 6c 6c 6d ...~diffie-hellm
00000020 61 6e 2d 67 72 6f 75 70 2d 65 78 63 68 61 6e 67 an-group-exchang
00000030 65 2d 73 68 61 32 35 36 2c 64 69 66 66 69 65 2d e-sha256,diffie-
00000040 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 2d 65 78 hellman-group-ex
00000050 63 68 61 6e 67 65 2d 73 68 61 31 2c 64 69 66 66 change-sha1,diff
00000060 69 65 2d 68 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 ie-hellman-group
00000070 31 34 2d 73 68 61 31 2c 64 69 66 66 69 65 2d 68 14-sha1,diffie-h
00000080 65 6c 6c 6d 61 6e 2d 67 72 6f 75 70 31 2d 73 68 ellman-group1-sh
00000090 61 31 00 00 00 0f 73 73 68 2d 72 73 61 2c 73 73 a1....ssh-rsa,ss
000000a0 68 2d 64 73 73 00 00 00 9d 61 65 73 31 32 38 2d h-dss....aes128-
000000b0 63 62 63 2c 33 64 65 73 2d 63 62 63 2c 62 6c 6f cbc,3des-cbc,blo
000000c0 77 66 69 73 68 2d 63 62 63 2c 63 61 73 74 31 32 wfish-cbc,cast12
000000d0 38 2d 63 62 63 2c 61 72 63 66 6f 75 72 31 32 38 8-cbc,arcfour128
000000e0 2c 61 72 63 66 6f 75 72 32 35 36 2c 61 72 63 66 ,arcfour256,arcf
000000f0 6f 75 72 2c 61 65 73 31 39 32 2d 63 62 63 2c 61 our,aes192-cbc,a
00000100 65 73 32 35 36 2d 63 62 63 2c 72 69 6a 6e 64 61 es256-cbc,rijnda
00000110 65 6c 2d 63 62 63 40 6c 79 73 61 74 6f 72 2e 6c el-cbc@lysator.l
00000120 69 75 2e 73 65 2c 61 65 73 31 32 38 2d 63 74 72 iu.se,aes128-ctr
00000130 2c 61 65 73 31 39 32 2d 63 74 72 2c 61 65 73 32 ,aes192-ctr,aes2
00000140 35 36 2d 63 74 72 00 00 00 9d 61 65 73 31 32 38 56-ctr....aes128
00000150 2d 63 62 63 2c 33 64 65 73 2d 63 62 63 2c 62 6c -cbc,3des-cbc,bl
00000160 6f 77 66 69 73 68 2d 63 62 63 2c 63 61 73 74 31 owfish-cbc,cast1
00000170 32 38 2d 63 62 63 2c 61 72 63 66 6f 75 72 31 32 28-cbc,arcfour12
00000180 38 2c 61 72 63 66 6f 75 72 32 35 36 2c 61 72 63 8,arcfour256,arc
00000190 66 6f 75 72 2c 61 65 73 31 39 32 2d 63 62 63 2c four,aes192-cbc,
000001a0 61 65 73 32 35 36 2d 63 62 63 2c 72 69 6a 6e 64 aes256-cbc,rijnd
000001b0 61 65 6c 2d 63 62 63 40 6c 79 73 61 74 6f 72 2e ael-cbc@lysator.
000001c0 6c 69 75 2e 73 65 2c 61 65 73 31 32 38 2d 63 74 liu.se,aes128-ct
000001d0 72 2c 61 65 73 31 39 32 2d 63 74 72 2c 61 65 73 r,aes192-ctr,aes
000001e0 32 35 36 2d 63 74 72 00 00 00 55 68 6d 61 63 2d 256-ctr...Uhmac-
000001f0 6d 64 35 2c 68 6d 61 63 2d 73 68 61 31 2c 68 6d md5,hmac-sha1,hm
00000200 61 63 2d 72 69 70 65 6d 64 31 36 30 2c 68 6d 61 ac-ripemd160,hma
00000210 63 2d 72 69 70 65 6d 64 31 36 30 40 6f 70 65 6e c-ripemd160@open
00000220 73 73 68 2e 63 6f 6d 2c 68 6d 61 63 2d 73 68 61 ssh.com,hmac-sha
00000230 31 2d 39 36 2c 68 6d 61 63 2d 6d 64 35 2d 39 36 1-96,hmac-md5-96
00000240 00 00 00 55 68 6d 61 63 2d 6d 64 35 2c 68 6d 61 ...Uhmac-md5,hma
00000250 63 2d 73 68 61 31 2c 68 6d 61 63 2d 72 69 70 65 c-sha1,hmac-ripe
00000260 6d 64 31 36 30 2c 68 6d 61 63 2d 72 69 70 65 6d md160,hmac-ripem
00000270 64 31 36 30 40 6f 70 65 6e 73 73 68 2e 63 6f 6d d160@openssh.com
00000280 2c 68 6d 61 63 2d 73 68 61 31 2d 39 36 2c 68 6d ,hmac-sha1-96,hm
00000290 61 63 2d 6d 64 35 2d 39 36 00 00 00 15 6e 6f 6e ac-md5-96....non
000002a0 65 2c 7a 6c 69 62 40 6f 70 65 6e 73 73 68 2e 63 e,zlib@openssh.c
000002b0 6f 6d 00 00 00 15 6e 6f 6e 65 2c 7a 6c 69 62 40 om....none,zlib@
000002c0 6f 70 65 6e 73 73 68 2e 63 6f 6d 00 00 00 00 00 openssh.com.....
000002d0 00 00 00 00 00 00 00 00 ........
Event Log: Doing Diffie-Hellman group exchange
Outgoing packet type 30 / 0x1e (SSH2_MSG_KEX_DH_GEX_REQUEST)
00000000 00 00 10 00 ....
Incoming packet type 31 / 0x1f (SSH2_MSG_KEX

Answer 6

I've gone through the logs - unfortunately your putty log doesn't have timestamps so it is difficult to see where timing delays are there.

The only difference I can see is initially putty tries "none" authentication which enables the list of valid types to be returned - I'm wondering if that somehow makes authentication faster.

Any way we can access your server via a test account? Otherwise I might have to try the same approach & get you to try a patched DLL.