Ask a Question

Reg: SFTP issues

0 votes
by (320 points)
retagged by

Hello Team,

We have two issues while we are working with SFTP using Rebex.

Issue 1: While disconnecting the SFTP server through sftpclient.Disconnect() method, I am getting below error.
SFTP Disconnect error

Issue 2: All the SFTP method logs are not user understandable format. But FileZilla is displaying the SFTP logs in an understandable format. Please see the below comparisons between Rebex and FileZilla SFTP logs.

  • FileZilla SFTP logs
    FileZilla SFTP logs
  • Rebex SFTP Connection log
    Rebex SFTP Connection log
  • Rebex SFTP Directory Exists log
    Rebex SFTP Directory Exists log
  • Rebex SFTP File Upload log
    Rebex SFTP File Upload log
  • Rebex SFTP File Download log
    Rebex SFTP File Download log
  • Rebex SFTP File Delete log
    enter image description here

Please kindly clarify the above two issues asap.

Thanks
Naga Suresh D

Applies to: Rebex SFTP

1 Answer

0 votes
by (58.9k points)
edited by

Hello,

issue 1 - the SshException ("connection has been closed by the remote connection end") means that you have actually been disconnected before you even called the sftp.Disconnect method. You can safely ignore this exception in this scenario as it only says you are already in the disconnected state which is what you wanted to achieve nevertheless.

issue 2 - I admit that FileZilla log looks nicer, but Rebex logs are not meant to be used for users of your application directly. We have the logs formatted in such a way that helps Rebex components developers and developer that are using Rebex, to identify issues with using our components. The logs are quite low-level, however you can change the verbosity of the logs. Setting the verbosity to LogLevel.Info would make the logs least verbose.

If you need only a high-level log for users of your app that internally uses Rebex SFTP, you probably need to write a custom log writer or write your custom messages into the Rebex.FileLogWriter via one of the Write methods.

by (320 points)
Hello,

Issue1 - I am using the below lines of code to connect and disconnect the SFTP.

                        sftpClient.Connect(ftpSettings.SecureServerName);
                        sftpClient.Login(ftpSettings.UserName, ftpSettings.Password);
                        sftpClient.Disconnect();

While executing the Disconnect() method, we are getting the SshException ("connection has been closed by the remote connection end") exception. In the above code I just logged-in and immediately disconnected. I don't know why Rebex logs an expection while disconnecting the SFTP server.

Issue2 - I observed that, with out writing a custom log, we are able to get the high-level logs for normal FTP. In SFTP case only we are getting a low-level logs.

Please help me to resolve the above two issues.

Thanks....
by (58.9k points)
edited by
Hi,

issue 1) Seeing a log of communication (http://www.rebex.net/kb/logging/) would reveal more information. Please create the log and either post it here, or send to support@rebex.net for analysis. BTW, I can see you are running an older version of Rebex SFTP. Please create the log from the newest version (free trial at http://www.rebex.net/sftp.net/download.aspx) and let me know whether it makes any difference.
by (58.9k points)
As to issue 2 - what do you mean by low-level and high-level? If I use the standard Rebex.FileLogWriter with the default LogLevel (e.g. LogLevel.Info), and the following code

            Ftp ftp = new Ftp();
            ftp.LogWriter = new FileLogWriter(@"C:\temp\ftp-log-standard.txt");
            ftp.Connect("test.rebex.net", SslMode.Explicit);
            ftp.Login("demo", "password");

            ftp.Disconnect();

            Sftp sftp = new Sftp();
            sftp.LogWriter = new Rebex.FileLogWriter(@"C:\temp\sftp-log-standard.txt");

            sftp.Connect("test.rebex.net");
            sftp.Login("demo", "password");
            sftp.Disconnect();

I get these high level logs:

for SFTP:

2015-12-16 18:32:59.909 Opening log file.
2015-12-16 18:32:59.909 Using FileLogWriter version 2.0.5715.0.
2015-12-16 18:32:59.909 INFO Sftp(2)[1] Info: Connecting to test.rebex.net:22 using Sftp 3.0.5715.0.
2015-12-16 18:32:59.925 INFO Sftp(2)[1] SSH: Negotiation started.
2015-12-16 18:33:00.019 INFO Sftp(2)[1] SSH: Negotiation finished.
2015-12-16 18:33:00.019 INFO Sftp(2)[1] Info: Server: SSH-2.0-RebexSSH_1.0.5779.2
2015-12-16 18:33:00.019 INFO Sftp(2)[1] Info: Fingerprint: 33:16:42:58:9b:83:01:0c:1d:cd:a8:a4:6f:d2:aa:85
2015-12-16 18:33:00.019 INFO Sftp(2)[1] Info: Cipher info: SSH 2.0, DiffieHellmanGroupExchangeSHA256, RSA, aes256-ctr/aes256-ctr, hmac-sha2-256/hmac-sha2-256
2015-12-16 18:33:00.114 INFO Sftp(2)[1] Command: SSH_FXP_INIT (4)
2015-12-16 18:33:00.128 INFO Sftp(2)[1] Response: SSH_FXP_VERSION (4, 1 extension)
2015-12-16 18:33:00.128 INFO Sftp(2)[1] Info: Using SFTP v4 on a Windows-like platform.
2015-12-16 18:33:00.128 INFO Sftp(2)[1] Command: SSH_FXP_REALPATH (1, '.')
2015-12-16 18:33:00.128 INFO Sftp(2)[1] Response: SSH_FXP_NAME (1, 1 item)
2015-12-16 18:33:00.128 INFO Sftp(2)[1] Info: Current directory is '/'.

and for FTP I get:

2015-12-16 18:32:59.675 Opening log file.
2015-12-16 18:32:59.675 Using FileLogWriter version 2.0.5715.0.
2015-12-16 18:32:59.690 INFO Ftp(1)[1] Info: Connecting to test.rebex.net:21 using Ftp 4.0.5715.0.
2015-12-16 18:32:59.690 INFO Ftp(1)[1] Info: Using proxy none.
2015-12-16 18:32:59.738 INFO Ftp(1)[1] Response: 220 Microsoft FTP Service
2015-12-16 18:32:59.738 INFO Ftp(1)[1] Command: AUTH TLS
2015-12-16 18:32:59.753 INFO Ftp(1)[1] Response: 234 AUTH command ok. Expecting TLS Negotiation.
2015-12-16 18:32:59.769 INFO Ftp(1)[1] TLS: State StateChange:Negotiating
2015-12-16 18:32:59.863 INFO Ftp(1)[1] TLS: State StateChange:Secured
2015-12-16 18:32:59.863 INFO Ftp(1)[1] TLS: Connection secured using cipher: TLS 1.1, RSA, 256bit AES in CBC mode, SHA1
2015-12-16 18:32:59.863 INFO Ftp(1)[1] Command: USER demo
2015-12-16 18:32:59.863 INFO Ftp(1)[1] Response: 331 Password required for demo.
2015-12-16 18:32:59.863 INFO Ftp(1)[1] Command: PASS ********
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response: 230 User logged in.
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Command: FEAT
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response: 211-Extended features supported:
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  LANG EN*
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  UTF8
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  AUTH TLS;TLS-C;SSL;TLS-P;
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  PBSZ
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  PROT C;P;
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  CCC
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  HOST
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  SIZE
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  MDTM
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response:  REST STREAM
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response: 211 END
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Command: OPTS UTF8 ON
2015-12-16 18:32:59.878 INFO Ftp(1)[1] Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
2015-12-16 18:32:59.894 INFO Ftp(1)[1] Command: QUIT
2015-12-16 18:32:59.894 INFO Ftp(1)[1] Response: 221 Goodbye.
2015-12-16 18:32:59.894 INFO Ftp(1)[1] TLS: Alert Alert:Alert was sent.
2015-12-16 18:32:59.894 INFO Ftp(1)[1] TLS: State StateChange:Closed


What do you find inconvenient?
by (58.9k points)
The FTP and SFTP are different protocols, so they log both different commands and responses, but I do not think that they are any different in their structure. However, if you would like to filter out the "TLS, SSH, Command and Response" areas and only log the info: area, then try this custom "InfoFileLogWriter" that does not log the commands and responses sent from/to the client nor the SSH or TLS details:


        class InfoFileLogWriter : FileLogWriter
        {
            public InfoFileLogWriter(string path) : base(path)
            {
                Level = LogLevel.Info;
            }

            public override void Write(LogLevel level, Type objectType, int objectId, string area, string message, byte[] buffer, int offset, int length)
            {
                // only log messages that have "Info" area (this will exclude the SFTP commands and responses as well as other low-level information from the log).
                if (area == "Info")
                    base.Write(level, objectType, objectId, area, message, buffer, offset, length);
            }

            public override void Write(LogLevel level, Type objectType, int objectId, string area, string message)
            {
                if (area == "Info")
                    base.Write(level, objectType, objectId, area, message);
            }
        }
by (320 points)
Regarding Issue1 - Diconnection error, Please see the below log.


2015-12-17 12:17:42.459 Opening log file.
2015-12-17 12:17:44.104 INFO Sftp(2)[10] Info: Connecting to tf.ftpuat.citonline.com:22 using Sftp 3.0.4546.0.
2015-12-17 12:17:44.952 DEBUG Sftp(2)[10] SSH: Server is 'SSH-2.0-Maverick_SSHD'.
2015-12-17 12:17:44.959 INFO Sftp(2)[10] SSH: Negotiation started.
2015-12-17 12:17:45.143 DEBUG Sftp(2)[10] SSH: Group exchange.
2015-12-17 12:17:45.356 DEBUG Sftp(2)[10] SSH: Negotiating key.
2015-12-17 12:17:45.757 DEBUG Sftp(2)[10] SSH: Validating signature.
2015-12-17 12:17:45.774 INFO Sftp(2)[10] SSH: Negotiation finished.
2015-12-17 12:17:45.774 INFO Sftp(2)[10] Info: Server: SSH-2.0-Maverick_SSHD
2015-12-17 12:17:45.774 INFO Sftp(2)[10] Info: Fingerprint: 66:13:da:74:74:19:4a:cf:2d:6f:ce:95:da:53:e9:3b
2015-12-17 12:17:45.775 INFO Sftp(2)[10] Info: Cipher info: SSH 2.0, DiffieHellmanGroupExchangeSHA1, RSA, aes256-cbc/aes256-cbc, hmac-sha1/hmac-sha1
2015-12-17 12:17:46.519 INFO Sftp(2)[10] SSH: Received banner: ******************************************************** *                                                      * * This system is for the use of authorized users only. * * Usage of this system may be monitored and recorded   * * by system personnel.                                 * *                                                      * * Anyone using this system expressly consents to such  * * monitoring and is advised that if such monitoring    * * reveals possible evidence of criminal activity,      * * system personnel may provide the evidence from such  * * monitoring to law enforcement officials.             * *                                                      * ********************************************************
2015-12-17 12:17:46.726 DEBUG Sftp(2)[10] SSH: Allowed authentication methods: password, publickey.
2015-12-17 12:17:46.729 DEBUG Sftp(2)[10] SSH: Trying password authentication for 'mshbriarrz'.
2015-12-17 12:17:46.941 DEBUG Sftp(2)[10] SSH: Authentication successful.
2015-12-17 12:17:47.164 DEBUG Sftp(2)[10] SSH: Requesting subsystem 'sftp'.
2015-12-17 12:17:48.137 INFO Sftp(2)[10] Command: SSH_FXP_INIT (4)
2015-12-17 12:17:48.350 INFO Sftp(2)[10] Response: SSH_FXP_VERSION (3, 0 extensions)
2015-12-17 12:17:48.352 INFO Sftp(2)[10] Info: Using SFTP v3.
2015-12-17 12:17:48.357 INFO Sftp(2)[10] Command: SSH_FXP_REALPATH (1, '.')
2015-12-17 12:17:48.798 INFO Sftp(2)[10] Response: SSH_FXP_NAME (1, 1 item)
2015-12-17 12:17:48.798 INFO Sftp(2)[10] Info: Current directory is '/'.
2015-12-17 12:17:50.831 ERROR Sftp(2)[10] SSH: Rebex.Net.SshException: Connection has been closed by the remote connection end; disconnected by application. User Disconnected.
   at Rebex.Net.SshSession.1xzy5U(Byte[] , Int32 , Int32 )
   at Rebex.Net.SshSession.i12XcZ(Byte[] , Int32 , Int32 )
   at Rebex.Net.SshSession.1rsOcLZ(1VEj6UZ , Object[] )
   at Rebex.Net.SshChannel.1rsOcLZ(Boolean , 1VEj6UZ , Object[] )
   at Rebex.Net.SshChannel.Close()
2015-12-17 12:17:50.851 ERROR Sftp(2)[10] Info: Error while shutting down the SSH session: Rebex.Net.SshException: Connection has been closed by the remote connection end; disconnected by application. User Disconnected.
   at Rebex.Net.SshSession.1xzy5U(Byte[] , Int32 , Int32 )
   at Rebex.Net.SshSession.i12XcZ(Byte[] , Int32 , Int32 )
   at Rebex.Net.SshSession.1rsOcLZ(1VEj6UZ , Object[] )
   at Rebex.Net.SshChannel.1rsOcLZ(Boolean , 1VEj6UZ , Object[] )
   at Rebex.Net.SshChannel.Close()
   at Rebex.Net.Sftp.10iAwZ()
by (147k points)
Thanks for the log! Does it always fail at this point (after SSH_FXP_REALPATH  command and SSH_FXP_NAME  response), or is it seemingly random?
by (58.9k points)
In the log I can see that there is a 2-minute timeframe before the connection has been closed (after the SSH_FXP_NAME response has been received there is a 2-minute gap). It might be that some device along the network has closed the connection, or even the SFTP server itself. In the log I cannot see that the sftp.Disconnect method actually was called. If you try our SftpWinformClient sample are you able to connect and disconnect to your SFTP server fine with it? The sample program comes as part of Rebex SFTP for .NET (free trial at http://www.rebex.net/sftp.net/download.aspx).
...