Our Products:   CompleteFTP  edtFTPnet/Free  edtFTPnet/PRO  edtFTPj/Free  edtFTPj/PRO
0 votes
68 views
asked in .NET FTP by (180 points)

We have a customer who is having an intermittent error connecting to an SFTP server. They periodically receive "Protocol negotiation timeout ". Here is the log snippet from the failed attempt:

      DEBUG [SSHSCPClient] 12 Jan 2019 07:18:28.203 : FTPConnection.8 Connecting directly to SFTP server x.y.z.w:22
      INFO [BaseSocket] 12 Jan 2019 07:18:28.203 : FTPConnection.8 Connecting to x.y.z.w:22 with timeout 120000 ms
      DEBUG [BaseSocket] 12 Jan 2019 07:18:28.250 : FTPConnection.8 Successfully connected to x.y.z.w:22
      DEBUG [SSHSCPClient] 12 Jan 2019 07:18:28.250 : FTPConnection.8 Connected successfully to SFTP server x.y.z.w:22
      DEBUG [SSHConnection] 12 Jan 2019 07:18:28.250 : FTPConnection.8 Beginning protocol negotiation
      ERROR [SSHConnection] 12 Jan 2019 07:20:28.261 : FTPConnection.8 Protocol negotiation timeout
      ERROR [SSHFTPClient] 12 Jan 2019 07:20:28.261 : FTPConnection.8 Failed to connect - closing connection
      ERROR [SSHFTPClient] 12 Jan 2019 07:20:28.261 : FTPConnection.8 EnterpriseDT.Net.Ftp.Ssh.SFTPException: Protocol negotiation timeout
      ERROR [SSHFTPClient] 12 Jan 2019 07:20:28.261 : FTPConnection.8 at EnterpriseDT.Net.Ftp.Ssh.SSHFTPClient.Connect()
      INFO [FTPConnection] 12 Jan 2019 07:20:28.261 : FTPConnection.8 OS: 6.1.7601.65536, CLR: 4.0.30319.42000, DLL: 9.1.3.20
      INFO [FTPConnection] 12 Jan 2019 07:20:28.261 : FTPConnection.8 Built: 26-Oct-2017 21:06:13 BST

      Here is the log snippet from a successful connection:

      DEBUG [SSHSCPClient] 12 Jan 2019 07:20:32.956 : Connecting directly to SFTP server x.y.z.w:22
      INFO [BaseSocket] 12 Jan 2019 07:20:32.956 : Connecting to x.y.z.w:22 with timeout 120000 ms
      DEBUG [BaseSocket] 12 Jan 2019 07:20:33.003 : Successfully connected to x.y.z.w:22
      DEBUG [SSHSCPClient] 12 Jan 2019 07:20:33.034 : Connected successfully to SFTP server x.y.z.w:22
      DEBUG [SSHConnection] 12 Jan 2019 07:20:33.034 : Beginning protocol negotiation
      DEBUG [PlainSocket] 12 Jan 2019 07:20:33.050 : FTPConnection.16 RepeatCallback received 23 bytes
      DEBUG [ProtocolNegotiationHandler] 12 Jan 2019 07:20:33.050 : FTPConnection.16 offset=0,length=23
      INFO [ProtocolNegotiationHandler] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Server version = 'SSH-2.0-Maverick_SSHD'
      DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Major string = '2'
      DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Minor string = '0'
      DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Version 2.0
      DEBUG [SSHUtil] 12 Jan 2019 07:20:33.050 : FTPConnection.16 Protocol compatible
      DEBUG [SSHConnection] 12 Jan 2019 07:20:33.050 : Server version=SSH-2.0-Maverick_SSHD
      DEBUG [SSH2Connection] 12 Jan 2019 07:20:33.050 : Timeout=120000
      DEBUG [SSHConnection] 12 Jan 2019 07:20:33.050 : Sending client version=SSH-2.0-edtFTPnet/PRO_9.1.3.20
      DEBUG [SSH2Connection] 12 Jan 2019 07:20:33.050 : Starting key exchange

      The customer says using WinSCP they always get the connection to work when they uncheck "Optimize connection buffer size". Per the WinSCP docs: "The Optimize connection buffer size enables optimization of socket buffer size. It greatly improves transfer speed. Disable it only when experiencing problems."

      Any suggestions for diagnosing/fixing this issue with edtFTPnet/PRO?

      - Paul -

      commented by (152k points)
      First thing to try is 9.3.0, or at a minimum 9.1.4.

      Please log in or register to answer this question.

      Categories

      ...