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

EOF when trying to read/write file using Tectia SSH Server #54

Closed
incendium opened this issue Jan 17, 2012 · 14 comments
Closed

EOF when trying to read/write file using Tectia SSH Server #54

incendium opened this issue Jan 17, 2012 · 14 comments
Labels
server-specific undiagnosed

Comments

@incendium
Copy link
Contributor

We're having issues communicating with Tectia's SSH server using the latest SSHJ client (0.7.0). Here's the test code and a dump of the error 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 SFTPTest {
  public static void main(String[] args)
      throws Exception {
    SSHClient client = new SSHClient();
    client.addHostKeyVerifier(new PromiscuousVerifier());
    client.connect("127.0.0.1", 22);
    client.authPassword("test", "test");

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

    InputStream input = sftp.open("test.txt").getInputStream();
    IOUtils.copy(input, System.out);
    IOUtils.closeQuietly(input);

    sftp.close();
    client.close();
  }
}

stdout:

File Exists: [size=14;mode=[mask=100600];atime=1326843624,mtime=1326843624;]

stderr:

317 [main] INFO net.schmizz.sshj.common.SecurityUtils - Trying to register BouncyCastle as a JCE provider
800 [main] INFO net.schmizz.sshj.common.SecurityUtils - Registration succeeded
853 [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_7
856 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-6.2.3.168 SSH Tectia Server
857 [main] INFO net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
5348 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
5395 [reader] INFO net.schmizz.sshj.transport.kex.DHG14 - Sending SSH_MSG_KEXDH_INIT
5536 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
5537 [reader] INFO net.schmizz.sshj.transport.kex.DHG14 - Received SSH_MSG_KEXDH_REPLY
5582 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
5582 [reader] INFO net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
5586 [main] INFO net.schmizz.sshj.SSHClient - Key exchange took 4.729 seconds
5588 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5707 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5707 [main] INFO net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
5708 [main] INFO net.schmizz.sshj.userauth.UserAuthImpl - Trying `password` auth...
5708 [main] INFO net.schmizz.sshj.userauth.method.AuthPassword - Requesting password for [AccountResource] [email protected]
5725 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5819 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5819 [main] INFO net.schmizz.sshj.userauth.UserAuthImpl - `password` auth successful
5819 [main] INFO net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
5835 [main] INFO net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
5836 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5840 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=65536] >
5840 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request `sftp` subsystem
5840 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `subsystem`
5919 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5929 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5929 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5929 [main] INFO net.schmizz.sshj.sftp.SFTPEngine - Server version 3
5935 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5935 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5937 [main] INFO net.schmizz.sshj.sftp.StatefulSFTPClient - Start dir = /C:/Documents and Settings/test
5939 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5941 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5962 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5963 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5973 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5973 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Got chan request for `exit-status`
5973 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5973 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Got EOF
5973 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
5992 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Got close
5992 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending EOF
5993 [reader] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending close
5993 [reader] INFO net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
5996 [main] ERROR net.schmizz.concurrent.Promise - <<sftp / 4>> woke to: net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
Exception in thread "main" net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
  at net.schmizz.sshj.sftp.PacketReader.readIntoBuffer(PacketReader.java:52)
  at net.schmizz.sshj.sftp.PacketReader.getPacketLength(PacketReader.java:57)
  at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:67)
  at net.schmizz.sshj.sftp.PacketReader.run(PacketReader.java:84)

You can grab the server here - http://www.tectia.com/en/Customers/Evaluate/Client_-_Server.iw3. I have only tested the Windows server (on XP). Setup is relatively straight forward, everything is set up straight out of the box, all you need to do is create a user named test with the password test and drop a file called "test.txt" into their home directory.

Let me know if you need any more info.
@shikhar
Copy link
Contributor

shikhar commented Feb 1, 2012

I'll try and set this up if there's a Mac version of the server.

Meanwhile can you post DEBUG-level logs as well?

@shikhar
Copy link
Contributor

shikhar commented Feb 1, 2012

We're having issues communicating with Tectia's SSH server using the latest SSHJ client (0.7.0).

is the problem only since 0.7.0?

@incendium
Copy link
Contributor Author

No, it was originally discovered with 0.3.1. I just ran the tests with 0.7.0 to make sure it hadn't been fixed in a later version. I'll get on those DEBUG logs.

@incendium
Copy link
Contributor Author

Here's the full dump including DEBUG logs:

2012-02-08 12:50:44,228 [main] INFO  net.schmizz.sshj.common.SecurityUtils - Trying to register BouncyCastle as a JCE provider
2012-02-08 12:50:44,928 [main] INFO  net.schmizz.sshj.common.SecurityUtils - Registration succeeded
2012-02-08 12:50:44,983 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_7
2012-02-08 12:50:44,985 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-6.2.3.168 SSH Tectia Server
2012-02-08 12:50:44,986 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
2012-02-08 12:50:44,987 [main] INFO  net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
2012-02-08 12:50:44,991 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
2012-02-08 12:50:44,992 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
2012-02-08 12:50:49,475 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
2012-02-08 12:50:49,476 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - 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 ]
2012-02-08 12:50:49,522 [reader] INFO  net.schmizz.sshj.transport.kex.DHG14 - Sending SSH_MSG_KEXDH_INIT
2012-02-08 12:50:49,746 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
2012-02-08 12:50:49,746 [reader] INFO  net.schmizz.sshj.transport.kex.DHG14 - Received SSH_MSG_KEXDH_REPLY
2012-02-08 12:50:49,810 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@9d7fbfb
2012-02-08 12:50:49,810 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
2012-02-08 12:50:49,810 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
2012-02-08 12:50:49,815 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
2012-02-08 12:50:49,815 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
2012-02-08 12:50:49,817 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:49,817 [main] INFO  net.schmizz.sshj.SSHClient - Key exchange took 4.83 seconds
2012-02-08 12:50:49,819 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
2012-02-08 12:50:49,819 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
2012-02-08 12:50:49,820 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
2012-02-08 12:50:49,988 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:49,989 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
2012-02-08 12:50:49,989 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
2012-02-08 12:50:49,989 [main] INFO  net.schmizz.sshj.userauth.UserAuthImpl - Trying `password` auth...
2012-02-08 12:50:49,989 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
2012-02-08 12:50:49,990 [main] INFO  net.schmizz.sshj.userauth.method.AuthPassword - Requesting password for [AccountResource] [email protected]
2012-02-08 12:50:49,990 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
2012-02-08 12:50:50,012 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,215 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,215 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `SOME`
2012-02-08 12:50:50,215 [main] INFO  net.schmizz.sshj.userauth.UserAuthImpl - `password` auth successful
2012-02-08 12:50:50,216 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
2012-02-08 12:50:50,225 [main] INFO  net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
2012-02-08 12:50:50,226 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / open>>
2012-02-08 12:50:50,226 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,229 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=65536] >
2012-02-08 12:50:50,229 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / open>> to `SOME`
2012-02-08 12:50:50,229 [main] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request `sftp` subsystem
2012-02-08 12:50:50,230 [main] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `subsystem`
2012-02-08 12:50:50,230 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / chanreq for subsystem>>
2012-02-08 12:50:50,307 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,308 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / chanreq for subsystem>> to `SOME`
2012-02-08 12:50:50,310 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 9 down to 65527
2012-02-08 12:50:50,321 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,321 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2097147
2012-02-08 12:50:50,322 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,322 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 33 down to 2097114
2012-02-08 12:50:50,322 [main] INFO  net.schmizz.sshj.sftp.SFTPEngine - Server version 3
2012-02-08 12:50:50,329 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{1;REALPATH}
2012-02-08 12:50:50,329 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 14 down to 65513
2012-02-08 12:50:50,329 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 1>>
2012-02-08 12:50:50,331 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,331 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2097109
2012-02-08 12:50:50,331 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,332 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 102 down to 2097007
2012-02-08 12:50:50,333 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received NAME packet
2012-02-08 12:50:50,333 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 1>> to `Buffer [rpos=5, wpos=103, size=103]`
2012-02-08 12:50:50,333 [main] INFO  net.schmizz.sshj.sftp.StatefulSFTPClient - Start dir = /C:/Documents and Settings/test
2012-02-08 12:50:50,334 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{2;STAT}
2012-02-08 12:50:50,334 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 53 down to 65460
2012-02-08 12:50:50,334 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 2>>
2012-02-08 12:50:50,335 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,336 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2097002
2012-02-08 12:50:50,336 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,336 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 28 down to 2096974
2012-02-08 12:50:50,337 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received ATTRS packet
2012-02-08 12:50:50,337 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 2>> to `Buffer [rpos=5, wpos=29, size=29]`
2012-02-08 12:50:50,340 [main] INFO  SFTPTest - File Exists: [size=14;mode=[mask=100600];atime=1326843624,mtime=1326843624;]
2012-02-08 12:50:50,340 [main] DEBUG net.schmizz.sshj.sftp.StatefulSFTPClient - Opening `/C:/Documents and Settings/test/test.txt`
2012-02-08 12:50:50,341 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{3;OPEN}
2012-02-08 12:50:50,341 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 61 down to 65399
2012-02-08 12:50:50,341 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 3>>
2012-02-08 12:50:50,342 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,342 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2096969
2012-02-08 12:50:50,342 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,342 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 16 down to 2096953
2012-02-08 12:50:50,342 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received HANDLE packet
2012-02-08 12:50:50,342 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 3>> to `Buffer [rpos=5, wpos=17, size=17]`
2012-02-08 12:50:50,343 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{4;READ}
2012-02-08 12:50:50,343 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 37 down to 65362
2012-02-08 12:50:50,344 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 4>>
2012-02-08 12:50:50,348 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 12:50:50,348 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Got chan request for `exit-status`
2012-02-08 12:50:50,349 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Got EOF
2012-02-08 12:50:50,349 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Got close
Exception in thread "main" net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
    at net.schmizz.sshj.sftp.PacketReader.readIntoBuffer(PacketReader.java:52)
    at net.schmizz.sshj.sftp.PacketReader.getPacketLength(PacketReader.java:57)
    at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:67)
    at net.schmizz.sshj.sftp.PacketReader.run(PacketReader.java:84)
2012-02-08 12:50:50,350 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending EOF
2012-02-08 12:50:50,350 [main] ERROR net.schmizz.concurrent.Promise - <<sftp / 4>> woke to: net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
2012-02-08 12:50:50,350 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending close
2012-02-08 12:50:50,350 [reader] INFO  net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
2012-02-08 12:50:50,350 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / close>> to `SOME`

@shikhar
Copy link
Contributor

shikhar commented Feb 8, 2012

Thanks @incendium

It's looking like Tectia doesn't like the READ sftp request sshj sends and just closes the channel.

I think the best indicator of what's up may be Tectia logs. Can you get your hands at those, and correlate if there's a relevant event? http://www.tectia.com/manuals/manager-admin/61/ch07s06s02.html

@incendium
Copy link
Contributor Author

Note: I built the latest version from git to see if any of the recent changes made a difference.

Here is the entire event log chain for a similar request:

2/8/2012 1:38:45PM: [Warning] 114 Servant_warning, "Failed to resolve remote hostname.", Session-Id: 7
2/8/2012 1:38:45PM: [Success Audit] 400 Connect, Policy name: Default-Connection, Src IP: 10.211.55.2, Dst IFace: listener, Dst IP: 10.211.55.7, Src Port: 57472, Dst Port: 22, Ver: SSH-2.0-SSHJ_0_8, Session-Id: 7
2/8/2012 1:38:45PM: [Information] 1002 Algorithm_negotiation_success, "kex_algorithm=diffie-hellman-group14-sha1, hostkey_algorithm=ssh-rsa, cipher=aes128-ctr/aes128-ctr, mac=hmac-sha1/hmac-sha1, compression=none/none", Session-Id: 7
2/8/2012 1:38:45PM: [Information] 1003 KEX_success, Algorithm: diffie-hellman-group14-sha1, Modulus: 2048 bits, Session-Id: 7, Protocol-session-Id: 0E721AAC608EB5E692B59501AEC7D4ABA9C70F3F
2/8/2012 1:38:46PM: [Information] 801 Authentication_block_selected, Username: test, Policy name: Default-Authentication, Session-Id: 7, "file: C:\Program Files\SSH Communications Security\SSH Tectia\SSH Tectia Server\ssh-server-config.xml, line: 36"
2/8/2012 1:38:46PM: [Information] 700 Auth_method_success, Username: test, Auth method: password, Session-Id: 7
2/8/2012 1:38:46PM: [Information] 802 Authentication_block_allow, Username: test, Policy name: Default-Authentication, Session-Id: 7, "file: C:\Program Files\SSH Communications Security\SSH Tectia\SSH Tectia Server\ssh-server-config.xml, line: 36"
2/8/2012 1:38:46PM: [Information] 702 Auth_methods_completed, Username: test, Auth methods: password, Src IP: 10.211.55.2, Src Port: 57472, Ver: SSH-2.0-SSHJ_0_8, Session-Id: 7
2/8/2012 1:38:46PM: [Information] 804 Group_selected, Username: test, Session-Id: 7
2/8/2012 1:38:46PM: [Information] 805 Rule_selected, Username: test, Policy name: <default>, Session-Id: 7, "file: C:\Program Files\SSH Communications Security\SSH Tectia\SSH Tectia Server\ssh-server-config.xml, line: 46"
2/8/2012 1:38:46PM: [Success Audit] 410 Login_success, Username: test, Src IP: 10.211.55.2, Dst IFace: listener, Dst IP: 10.211.55.7, Src Port: 57472, Dst Port: 22, Ver: SSH-2.0-SSHJ_0_8, Session-Id: 7
2/8/2012 1:38:46PM: [Information] 420 Session_channel_open, Username: test, Success, Command: sft-server-g3, Sub ID: 0, Session-Id: 7
2/8/2012 1:38:46PM: [Information] 2000 Sft_server_starting, "2000 Sft_server_starting, Username: test, Session-Id: 7"
2/8/2012 1:38:46PM: [Information] 2002 Sft_server_connected, "2002 Sft_server_connected, Session-Id: 7"
2/8/2012 1:38:46PM: [Information] 2006 Sft_server_fxp_version, "2006 Sft_server_fxp_version, Negotiated version: 3, Session-Id: 7"
2/8/2012 1:38:46PM: [Information] 2033 Sft_server_realpath, "2033 Sft_server_realpath, File name: C:\Documents and Settings\test, Path: /C:/Documents and Settings/test, "Success", Session-Id: 7"
2/8/2012 1:38:46PM: [Information] 2007 Sft_server_open_file, "2007 Sft_server_open_file, File name: C:\Documents and Settings\test\test.txt, File handle: 006E9AA8006ECFB0, "Type: Download", Session-Id: 7"
2/8/2012 1:38:46PM: [Information] 2010 Sft_server_read_file_failed, "2010 Sft_server_read_file_failed, File name: ???, "Error: Handle not found", Session-Id: 7"]
2/8/2012 1:38:47PM: [Information] 421 Session_channel_close, Username: test, Sub ID: 0, Session-Id: 7
2/8/2012 1:38:47PM: [Information] 1300 Channel_inbound_statistics, Username: uninitialized, Session-Id: 7, Channel Id: 0, Packet count: 4, Packet size: 30
2/8/2012 1:38:47PM: [Information] 1301 Channel_outbound_statistics, Username: uninitialized, Session-Id: 7, Channel Id: 0, Packet count: 6, Packet size: 27, Packet size: 512

And the corresponding SSHJ logs:

2012-02-08 13:38:41,022 [main] INFO  net.schmizz.sshj.common.SecurityUtils - Trying to register BouncyCastle as a JCE provider
2012-02-08 13:38:41,556 [main] INFO  net.schmizz.sshj.common.SecurityUtils - Registration succeeded
2012-02-08 13:38:41,635 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_8
2012-02-08 13:38:41,637 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-6.2.3.168 SSH Tectia Server
2012-02-08 13:38:41,637 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
2012-02-08 13:38:41,638 [main] INFO  net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
2012-02-08 13:38:41,642 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
2012-02-08 13:38:41,643 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
2012-02-08 13:38:46,417 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
2012-02-08 13:38:46,418 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - 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 ]
2012-02-08 13:38:46,474 [reader] INFO  net.schmizz.sshj.transport.kex.DHG14 - Sending SSH_MSG_KEXDH_INIT
2012-02-08 13:38:46,619 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
2012-02-08 13:38:46,619 [reader] INFO  net.schmizz.sshj.transport.kex.DHG14 - Received SSH_MSG_KEXDH_REPLY
2012-02-08 13:38:46,668 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@254e8cee
2012-02-08 13:38:46,668 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
2012-02-08 13:38:46,668 [reader] INFO  net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
2012-02-08 13:38:46,672 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
2012-02-08 13:38:46,672 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
2012-02-08 13:38:46,672 [main] INFO  net.schmizz.sshj.SSHClient - Key exchange took 5.035 seconds
2012-02-08 13:38:46,675 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:46,675 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
2012-02-08 13:38:46,675 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
2012-02-08 13:38:46,676 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
2012-02-08 13:38:46,790 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:46,790 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
2012-02-08 13:38:46,790 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
2012-02-08 13:38:46,791 [main] INFO  net.schmizz.sshj.userauth.UserAuthImpl - Trying `password` auth...
2012-02-08 13:38:46,791 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
2012-02-08 13:38:46,791 [main] INFO  net.schmizz.sshj.userauth.method.AuthPassword - Requesting password for [AccountResource] [email protected]
2012-02-08 13:38:46,792 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
2012-02-08 13:38:46,888 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,575 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,575 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `SOME`
2012-02-08 13:38:47,575 [main] INFO  net.schmizz.sshj.userauth.UserAuthImpl - `password` auth successful
2012-02-08 13:38:47,575 [main] INFO  net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
2012-02-08 13:38:47,584 [main] INFO  net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
2012-02-08 13:38:47,584 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / open>>
2012-02-08 13:38:47,587 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,590 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=65536] >
2012-02-08 13:38:47,590 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / open>> to `SOME`
2012-02-08 13:38:47,590 [main] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request `sftp` subsystem
2012-02-08 13:38:47,591 [main] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `subsystem`
2012-02-08 13:38:47,591 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / chanreq for subsystem>>
2012-02-08 13:38:47,672 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,672 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / chanreq for subsystem>> to `SOME`
2012-02-08 13:38:47,675 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 9 down to 65527
2012-02-08 13:38:47,687 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,687 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2097147
2012-02-08 13:38:47,687 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,687 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 33 down to 2097114
2012-02-08 13:38:47,688 [main] INFO  net.schmizz.sshj.sftp.SFTPEngine - Server version 3
2012-02-08 13:38:47,694 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{1;REALPATH}
2012-02-08 13:38:47,695 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 14 down to 65513
2012-02-08 13:38:47,695 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 1>>
2012-02-08 13:38:47,696 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,696 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2097109
2012-02-08 13:38:47,696 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,696 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 102 down to 2097007
2012-02-08 13:38:47,697 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received NAME packet
2012-02-08 13:38:47,697 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 1>> to `Buffer [rpos=5, wpos=103, size=103]`
2012-02-08 13:38:47,697 [main] INFO  net.schmizz.sshj.sftp.StatefulSFTPClient - Start dir = /C:/Documents and Settings/test
2012-02-08 13:38:47,700 [main] DEBUG net.schmizz.sshj.sftp.StatefulSFTPClient - Opening `/C:/Documents and Settings/test/test.txt`
2012-02-08 13:38:47,701 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{2;OPEN}
2012-02-08 13:38:47,701 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 61 down to 65452
2012-02-08 13:38:47,701 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 2>>
2012-02-08 13:38:47,702 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,703 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 5 down to 2097002
2012-02-08 13:38:47,703 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,703 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 16 down to 2096986
2012-02-08 13:38:47,703 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received HANDLE packet
2012-02-08 13:38:47,703 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 2>> to `Buffer [rpos=5, wpos=17, size=17]`
2012-02-08 13:38:47,704 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{3;READ}
2012-02-08 13:38:47,705 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 37 down to 65415
2012-02-08 13:38:47,705 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 3>>
2012-02-08 13:38:47,708 [reader] INFO  net.schmizz.sshj.transport.TransportImpl - Received SSH_MSG_IGNORE
2012-02-08 13:38:47,709 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Got chan request for `exit-status`
2012-02-08 13:38:47,709 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Got EOF
2012-02-08 13:38:47,711 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Got close
2012-02-08 13:38:47,712 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending EOF
2012-02-08 13:38:47,712 [reader] INFO  net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending close
2012-02-08 13:38:47,712 [reader] INFO  net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
2012-02-08 13:38:47,712 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / close>> to `SOME`
2012-02-08 13:38:47,712 [main] ERROR net.schmizz.concurrent.Promise - <<sftp / 3>> woke to: net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
Exception in thread "main" net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
    at net.schmizz.sshj.sftp.PacketReader.readIntoBuffer(PacketReader.java:52)
    at net.schmizz.sshj.sftp.PacketReader.getPacketLength(PacketReader.java:57)
    at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:67)
    at net.schmizz.sshj.sftp.PacketReader.run(PacketReader.java:84)

@shikhar
Copy link
Contributor

shikhar commented Feb 8, 2012

and here's the error...

2/8/2012 1:38:46PM: [Information] 2010 Sft_server_read_file_failed, "2010 Sft_server_read_file_failed, File name: ???, "Error: Handle not found", Session-Id: 7"]

hmm

@shikhar
Copy link
Contributor

shikhar commented May 20, 2012

As there hasn't been any other such report, I have to chalk it down to some idiosyncrasy of the Tectia implementation. Sorry...

@shikhar shikhar closed this as completed May 20, 2012
@peter-svensson
Copy link

Hi,

We've got the exact same problem with Tectia server, any ideas how to get this working?

@ghost
Copy link

ghost commented Sep 5, 2012

I also encountered the same problem with the Tectia Server.

I agree, that probably the server does something weird to cause this, but on the other hand, other tools seems to work just fine with the server. I don't have access to the server, so can't fix anything there :(
Would be nice to get this working

@ahgittin
Copy link
Contributor

+1

please reopen

we are also encountering this problem using sshj against tectia server

there is a free tectia download at: http://www.ssh.com/index.php/evaluation-downloads/ssh-clientserver-evaluation.html

@ahgittin ahgittin mentioned this issue Jan 24, 2013
Open
@ahgittin ahgittin mentioned this issue Jun 24, 2014
Open
@shikhar shikhar reopened this Jul 2, 2014
@bact1
Copy link

bact1 commented Sep 8, 2014

Please, reopen the issue, as it seems to be a SSHJ problem.

Apparently it seems that the Tectia SSH server creates a handle for the OpenDIR operation and gives it to the SSHJ client.
When doing ReadDir, SSHJ client sends back that handle modified to the Tectia SSH server, so the Tectia SSH server is not able to fulfill the operation.

The SSH File Transfer Protocol clearly states:
http://tools.ietf.org/html/draft-ietf-secsh-filexfer-01

"The SSH_FXP_HANDLE response has the following format:
uint32 id
string handle
where 'id' is the request identifier, and `handle' is an arbitrary string that identifies an open file or directory on the server. The handle is opaque to the client; the client MUST NOT attempt to interpret or modify it in any way. The length of the handle string MUST NOT exceed 256 data bytes."

Checking at the SSHJ code (sshj-0.8.1.zip) it seems that the code assumes the incoming string is UTF-8, and the code does some conversions that will fail if applied against a binary string. Tectia SSH Server sends binary strings, so, SSHJ does some conversion resulting in a modified handle when requesting for ReadDir…

I have taken the liberty to modify the SSHJ code a bit, just by changing the type of the “handle” as “byte[]” and using readBytes/writeBytes function and it seems to correct the problem.

To my eyes, Tectia SSH Server works as specified, and SSHJ is violating clearly the protocol. Please, correct me if I am wrong.

@dkocher
Copy link
Contributor

dkocher commented Sep 8, 2014

Thanks for looking into this. Would you like to provide a patch?

@dkocher dkocher mentioned this issue Sep 10, 2014
Merged
@hierynomus hierynomus mentioned this issue Sep 18, 2014
Open
@hierynomus
Copy link
Owner

This should be fixed with the merged patch of #150. Closing

@arobertn arobertn mentioned this issue Apr 5, 2016
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
server-specific undiagnosed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@dkocher @shikhar @incendium @hierynomus @peter-svensson @ahgittin @bact1