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

[incendium]

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] test@127.0.0.1
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]

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]

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]

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]

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] test@10.211.55.7
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]

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]

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] test@10.211.55.7
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]

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]

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

[peter-svensson]

Hi,

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

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]

+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