Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Serv-U FTP Server sometimes returns "Bad message." when attempting to read a file. #79

Open
incendium opened this issue Jun 7, 2012 · 5 comments
Open

Serv-U FTP Server sometimes returns "Bad message." when attempting to read a file. #79

incendium opened this issue Jun 7, 2012 · 5 comments
Labels
undiagnosed

Comments

@incendium
Copy link
Contributor

Yet another SFTP server that seems to clash with our implementation. :/

Here's the test code used to generate this log:

import java.io.InputStream;

import net.schmizz.sshj.SSHClient;
import net.schmizz.sshj.sftp.SFTPEngine;
import net.schmizz.sshj.sftp.StatefulSFTPClient;
import net.schmizz.sshj.transport.verification.PromiscuousVerifier;

import org.apache.commons.io.IOUtils;

public class SSHTest {
  public static void main(String[] args)
      throws Exception {
    SSHClient client = new SSHClient();
    try {
      client.addHostKeyVerifier(new PromiscuousVerifier());
      client.connect("10.211.55.6", 22);
      client.authPassword("test", "test");

      StatefulSFTPClient sftp = new StatefulSFTPClient(new SFTPEngine(client).init());
      try {
        System.out.println("File Exists: " + sftp.statExistence("test.txt"));

        InputStream input = sftp.open("test.txt").getInputStream();
        IOUtils.copy(input, System.out);
        IOUtils.closeQuietly(input);
      } finally {
        if (sftp != null) {
          sftp.close();
        }
      }
    } finally {
      client.close();
    }
  }
}

SSHJ Logs:

06-07-2012 16:27:55.170 [main] n.s.sshj.common.SecurityUtils  INFO: Trying to register BouncyCastle as a JCE provider
06-07-2012 16:27:55.932 [main] n.s.sshj.common.SecurityUtils  INFO: Registration succeeded
06-07-2012 16:27:56.067 [main] n.s.sshj.transport.TransportImpl  INFO: Client identity string: SSH-2.0-SSHJ_0_8
06-07-2012 16:27:56.117 [main] n.s.sshj.transport.TransportImpl  INFO: Server identity string: SSH-2.0-Serv-U_12.0.0.2
06-07-2012 16:27:56.146 [reader] n.s.sshj.transport.KeyExchanger  INFO: Received SSH_MSG_KEXINIT
06-07-2012 16:27:56.150 [main] n.s.sshj.transport.KeyExchanger  INFO: Sending SSH_MSG_KEXINIT
06-07-2012 16:27:56.171 [reader] n.s.sshj.transport.KeyExchanger DEBUG: Negotiated algorithms: [ kex=diffie-hellman-group14-sha1; sig=ssh-rsa; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
06-07-2012 16:27:56.254 [reader] n.s.sshj.transport.kex.DHG14  INFO: Sending SSH_MSG_KEXDH_INIT
06-07-2012 16:27:56.349 [reader] n.s.sshj.transport.KeyExchanger  INFO: Received kex followup data
06-07-2012 16:27:56.349 [reader] n.s.sshj.transport.kex.DHG14  INFO: Received SSH_MSG_KEXDH_REPLY
06-07-2012 16:27:56.471 [reader] n.s.sshj.transport.KeyExchanger DEBUG: Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@16e1eea8
06-07-2012 16:27:56.472 [reader] n.s.sshj.transport.KeyExchanger  INFO: Sending SSH_MSG_NEWKEYS
06-07-2012 16:27:56.474 [reader] n.s.sshj.transport.KeyExchanger  INFO: Received SSH_MSG_NEWKEYS
06-07-2012 16:27:56.483 [main] n.s.sshj.SSHClient  INFO: Key exchange took 0.364 seconds
06-07-2012 16:27:56.486 [main] n.s.sshj.transport.TransportImpl DEBUG: Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
06-07-2012 16:27:56.667 [main] n.s.sshj.transport.TransportImpl  INFO: Setting active service to ssh-userauth
06-07-2012 16:27:56.667 [main] n.s.sshj.userauth.UserAuthImpl  INFO: Trying `password` auth...
06-07-2012 16:27:56.668 [main] n.s.sshj.userauth.method.AuthPassword  INFO: Requesting password for [AccountResource] [email protected]
06-07-2012 16:27:56.685 [main] n.s.sshj.userauth.UserAuthImpl  INFO: `password` auth successful
06-07-2012 16:27:56.685 [main] n.s.sshj.transport.TransportImpl  INFO: Setting active service to ssh-connection
06-07-2012 16:27:56.699 [main] n.s.sshj.connection.ConnectionImpl  INFO: Attaching `session` channel (#0)
06-07-2012 16:27:56.706 [reader] n.s.sshj.connection.channel.direct.SessionChannel  INFO: Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2147483647] >
06-07-2012 16:27:56.706 [main] n.s.sshj.connection.channel.direct.SessionChannel  INFO: Will request `sftp` subsystem
06-07-2012 16:27:56.706 [main] n.s.sshj.connection.channel.direct.SessionChannel  INFO: Sending channel request for `subsystem`
06-07-2012 16:27:56.749 [main] n.s.sshj.connection.channel.Window$Remote DEBUG: Consuming by 9 down to 2147483638
06-07-2012 16:27:56.761 [reader] n.s.sshj.connection.channel.Window$Local DEBUG: Consuming by 9 down to 2097143
06-07-2012 16:27:56.770 [main] n.s.sshj.sftp.SFTPEngine  INFO: Server version 3
06-07-2012 16:27:56.774 [main] n.s.sshj.sftp.SFTPEngine DEBUG: Sending Request{1;REALPATH}
06-07-2012 16:27:56.774 [main] n.s.sshj.connection.channel.Window$Remote DEBUG: Consuming by 14 down to 2147483624
06-07-2012 16:27:56.806 [sftp reader] n.s.sshj.sftp.PacketReader DEBUG: Received NAME packet
06-07-2012 16:27:56.806 [reader] n.s.sshj.connection.channel.Window$Local DEBUG: Consuming by 27 down to 2097116
06-07-2012 16:27:56.806 [main] n.s.sshj.sftp.StatefulSFTPClient  INFO: Start dir = /
06-07-2012 16:27:56.806 [main] n.s.sshj.sftp.SFTPEngine DEBUG: Sending Request{2;STAT}
06-07-2012 16:27:56.807 [main] n.s.sshj.connection.channel.Window$Remote DEBUG: Consuming by 22 down to 2147483602
06-07-2012 16:27:56.820 [reader] n.s.sshj.connection.channel.Window$Local DEBUG: Consuming by 41 down to 2097075
06-07-2012 16:27:56.821 [sftp reader] n.s.sshj.sftp.PacketReader DEBUG: Received ATTRS packet
06-07-2012 16:27:56.825 [main] n.s.sshj.sftp.StatefulSFTPClient DEBUG: Opening `/test.txt`
06-07-2012 16:27:56.826 [main] n.s.sshj.sftp.SFTPEngine DEBUG: Sending Request{3;OPEN}
06-07-2012 16:27:56.826 [main] n.s.sshj.connection.channel.Window$Remote DEBUG: Consuming by 30 down to 2147483572
06-07-2012 16:27:56.852 [sftp reader] n.s.sshj.sftp.PacketReader DEBUG: Received HANDLE packet
06-07-2012 16:27:56.852 [reader] n.s.sshj.connection.channel.Window$Local DEBUG: Consuming by 17 down to 2097058
06-07-2012 16:27:56.858 [main] n.s.sshj.sftp.SFTPEngine DEBUG: Sending Request{4;READ}
06-07-2012 16:27:56.858 [main] n.s.sshj.connection.channel.Window$Remote DEBUG: Consuming by 31 down to 2147483541
06-07-2012 16:27:56.875 [reader] n.s.sshj.connection.channel.Window$Local DEBUG: Consuming by 35 down to 2097023
06-07-2012 16:27:56.875 [sftp reader] n.s.sshj.sftp.PacketReader DEBUG: Received STATUS packet
06-07-2012 16:27:56.878 [main] n.s.sshj.connection.channel.direct.SessionChannel  INFO: Sending close
06-07-2012 16:27:56.902 [reader] n.s.sshj.connection.channel.direct.SessionChannel  INFO: Got close
06-07-2012 16:27:56.926 [reader] n.s.sshj.connection.ConnectionImpl  INFO: Forgetting `session` channel (#0)
06-07-2012 16:27:56.926 [main] n.s.sshj.transport.TransportImpl DEBUG: Default disconnect listener - BY_APPLICATION
06-07-2012 16:27:56.927 [main] n.s.sshj.connection.ConnectionImpl DEBUG: Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected
06-07-2012 16:27:56.927 [main] n.s.sshj.transport.TransportImpl DEBUG: Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]
06-07-2012 16:27:56.936 [reader] n.s.sshj.transport.Reader DEBUG: Stopping
Exception in thread "main" net.schmizz.sshj.sftp.SFTPException: Bad message.
  at net.schmizz.sshj.sftp.Response.error(Response.java:113)
  at net.schmizz.sshj.sftp.Response.ensureStatusIs(Response.java:106)
  at net.schmizz.sshj.sftp.RemoteFile.read(RemoteFile.java:66)
  at net.schmizz.sshj.sftp.RemoteFile$RemoteFileInputStream.read(RemoteFile.java:179)
  at java.io.InputStream.read(InputStream.java:82)
  at org.apache.commons.io.IOUtils.copyLarge(IOUtils.java:1383)
  at org.apache.commons.io.IOUtils.copy(IOUtils.java:1357)
  at SSHTest.main(SSHTest.java:26)

stdout:

File Exists: [size=176;uid=176,gid=0;mode=[mask=100666];atime=1339099826,mtime=1339088332;]

Server Logs:

[02] Thu 07Jun12 16:27:56 - (000014) User "test" logged in
[31] Thu 07Jun12 16:27:56 - (000014) SSH2_MSG_USERAUTH_SUCCESS: successful login
[30] Thu 07Jun12 16:27:56 - (000014) SSH_FXP_INIT: client version 3 (SSHJ_0_8)
[31] Thu 07Jun12 16:27:56 - (000014) SSH_FXP_VERSION: server version 3
[30] Thu 07Jun12 16:27:56 - (000014) {0x00000001} SSH_FXP_REALPATH: path: "."
[31] Thu 07Jun12 16:27:56 - (000014) {0x00000001} SSH_FXP_NAME: path: "/"
[30] Thu 07Jun12 16:27:56 - (000014) {0x00000002} SSH_FXP_STAT: path: "/test.txt"
[31] Thu 07Jun12 16:27:56 - (000014) {0x00000002} SSH_FXP_ATTRS
[30] Thu 07Jun12 16:27:56 - (000014) {0x00000003} SSH_FXP_OPEN: path: "/test.txt"
[31] Thu 07Jun12 16:27:56 - (000014) {0x00000003} SSH_FXP_HANDLE: file handle: 0x000003e8
[30] Thu 07Jun12 16:27:56 - (000014) {0x00000004} SSH_FXP_READ
[31] Thu 07Jun12 16:27:56 - (000014) {0x00000004} SSH_FX_BAD_MESSAGE: Bad message.
[31] Thu 07Jun12 16:27:56 - (000014) SSH_MSG_DISCONNECT: client has requested a disconnect.  Reason code: 11
[02] Thu 07Jun12 16:27:56 - (000014) Closed session
[02] Thu 07Jun12 16:27:56 - (000014) User "test" logged out

Trial version is available at http://www.serv-u.com/dn.asp. Very basic setup, just added domain for testing, added user test/test and set up an empty directory. Test file was filled with "this is a test" about 5 times. First few attempts to read the file actually worked, subsequent attempts sometimes worked, sometimes didn't work (results were sporadic).
@LampeAtRhinoSoft
Copy link

Hello - I work for RhinoSoft, makers of Serv-U, though I'm not the programmer who works with this particular code.

If you think you've found a bug in the Serv-U SFTP implementation, could you please file a ticket here:
http://www.rhinosoft.com/emailsupport.asp?prod=su&emailtype=tech ?

@incendium
Copy link
Contributor Author

I received this response from RhinoSoft support:

We have been testing this out and I believe there may be a bug in SSHJ that is causing the error. Please see the attached logs. The test file is 4620 bytes, so the data is downloaded by SSHJ in two sections, a 4096 byte chunk and a 524 byte chunk. If you see the SSHJ log, you'll see that in the middle of getting data from Serv-U it logs "Sending" close while it is still getting data to the console.

SSHJ Logs:

run:
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/C:/Users/tparikka/Documents/NetBeansProjects/sshj_test/src/slf4j-simple-1.6.6.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [file:/C:/Users/tparikka/Documents/NetBeansProjects/sshj_test/build/classes/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.SimpleLoggerFactory]
2 [main] INFO net.schmizz.sshj.common.SecurityUtils - BouncyCastle not registered, using the default JCE provider
258 [main] WARN net.schmizz.sshj.DefaultConfig - Disabling high-strength ciphers: cipher strengths apparently limited by JCE policy
278 [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_8
744 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-Serv-U_12.0.0.3 FIPS
745 [main] INFO net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
750 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
784 [reader] INFO net.schmizz.sshj.transport.kex.DHG1 - Sending SSH_MSG_KEXDH_INIT
787 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
787 [reader] INFO net.schmizz.sshj.transport.kex.DHG1 - Received SSH_MSG_KEXDH_REPLY
800 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
801 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
805 [main] INFO net.schmizz.sshj.SSHClient - Key exchange took 0.06 seconds
809 [main] INFO net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
810 [main] INFO net.schmizz.sshj.userauth.UserAuthImpl - Trying `password` auth...
810 [main] INFO net.schmizz.sshj.userauth.method.AuthPassword - Requesting password for [AccountResource] [email protected]
813 [main] INFO net.schmizz.sshj.userauth.UserAuthImpl - `password` auth successful
813 [main] INFO net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
821 [main] INFO net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
823 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=2147483647] >
824 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request `sftp` subsystem
824 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `subsystem`
828 [main] INFO net.schmizz.sshj.sftp.SFTPEngine - Server version 3
835 [main] INFO net.schmizz.sshj.sftp.StatefulSFTPClient - Start dir = /
File Exists: [size=4620;uid=4620,gid=0;mode=[mask=100666];atime=1322776752,mtime=1341524348;]
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
921 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending close
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
asdfa
933 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Got close
933 [reader] INFO net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
BUILD SUCCESSFUL (total time: 1 second)

Serv-U Logs:

[31] Thu 05Jul12 16:37:15 - (000004) {0x00000003} SSH_FXP_HANDLE: file handle: 0x00000620
[32] Thu 05Jul12 16:37:15 - (000004) {0x00000004} SSH_FXP_READ: handle: 0x00000620; position: 0; 4096 bytes
[32] Thu 05Jul12 16:37:15 - (000004) {0x00000005} SSH_FXP_READ: handle: 0x00000620; position: 4; 4096 bytes
[31] Thu 05Jul12 16:38:51 - (000005) {0x00000003} SSH_FXP_HANDLE: file handle: 0x00000600
[32] Thu 05Jul12 16:38:51 - (000005) {0x00000004} SSH_FXP_READ: handle: 0x00000600; position: 0; 4096 bytes
[32] Thu 05Jul12 16:38:51 - (000005) {0x00000005} SSH_FXP_READ: handle: 0x00000600; position: 5; 4096 bytes
[02] Thu 05Jul12 16:39:12 - (000006) Connected to 192.168.5.50 (local address 192.168.5.50, port 22)
[03] Thu 05Jul12 16:39:12 - (000006) IP-Name: mydomain1.com (192.168.5.50)
[30] Thu 05Jul12 16:39:12 - (000006) SSH2_MSG_USERAUTH_REQUEST: user: test; service: ssh-connection; type: password
[02] Thu 05Jul12 16:39:12 - (000006) User "test" logged in
[31] Thu 05Jul12 16:39:12 - (000006) SSH2_MSG_USERAUTH_SUCCESS: successful login
[30] Thu 05Jul12 16:39:12 - (000006) SSH_FXP_INIT: client version 3 (SSHJ_0_8)
[31] Thu 05Jul12 16:39:12 - (000006) SSH_FXP_VERSION: server version 3
[30] Thu 05Jul12 16:39:12 - (000006) {0x00000001} SSH_FXP_REALPATH: path: "."
[31] Thu 05Jul12 16:39:12 - (000006) {0x00000001} SSH_FXP_NAME: path: "/"
[30] Thu 05Jul12 16:39:12 - (000006) {0x00000002} SSH_FXP_STAT: path: "/test.txt"
[31] Thu 05Jul12 16:39:12 - (000006) {0x00000002} SSH_FXP_ATTRS
[30] Thu 05Jul12 16:39:12 - (000006) {0x00000003} SSH_FXP_OPEN: path: "/test.txt"
[31] Thu 05Jul12 16:39:12 - (000006) {0x00000003} SSH_FXP_HANDLE: file handle: 0x00000600
[32] Thu 05Jul12 16:39:12 - (000006) {0x00000004} SSH_FXP_READ: handle: 0x00000600; position: 0; 4096 bytes
[10] Thu 05Jul12 16:39:12 - (000006) Sending file "D:\temp\ftproot\test.txt"
[33] Thu 05Jul12 16:39:12 - (000006) {0x00000004} SSH_FXP_DATA: 4096 bytes
[32] Thu 05Jul12 16:39:12 - (000006) {0x00000005} SSH_FXP_READ: handle: 0x00000600; position: 4096; 4096 bytes
[33] Thu 05Jul12 16:39:12 - (000006) {0x00000005} SSH_FXP_DATA: 524 bytes
[32] Thu 05Jul12 16:39:12 - (000006) {0x00000006} SSH_FXP_READ: handle: 0x00000600; position: 4620; 4096 bytes
[31] Thu 05Jul12 16:39:12 - (000006) {0x00000006} SSH_FX_EOF: End of file.
[10] Thu 05Jul12 16:39:12 - (000006) Error sending file "D:\temp\ftproot\test.txt", aborting (4,620 Bytes)
[31] Thu 05Jul12 16:39:12 - (000006) SSH_MSG_DISCONNECT: client has requested a disconnect.  Reason code: 11
[02] Thu 05Jul12 16:39:12 - (000006) Closed session
[02] Thu 05Jul12 16:39:12 - (000006) User "test" logged out

@hierynomus
Copy link
Owner

Actually this could very well be related to #119 and #54.
The fact that it works a few times then sporadically fails could be the fact that SSH/j sends bad file handles.

@hierynomus
Copy link
Owner

@incendium Could you verify the latest snapshot against the ssh server and see whether this still occurs?

@rcprcp
Copy link

rcprcp commented May 10, 2019

Hi Team,
I think we are encountering this issue as well, and i am wondering if there is an update to @hierynomus 's question above? Thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
undiagnosed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@incendium @hierynomus @LampeAtRhinoSoft @rcprcp