search

hierynomus / sshj

ssh, scp and sftp for java
Apache License 2.0
2.48k stars 600 forks source link

connection abort: recv failed when upload file to AWS EC2 #321

Open havid0707 opened 7 years ago

havid0707 commented 7 years ago

Run script successfully on AWS EC2 but failed when upload file use SFTP. I have try version 15-21, all have such problem. Client and Server Version: [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_17_2 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_6.6.1 Code:

final String src = "C:\\winscp555setup.7z";
final String target = "/home/centos";
// final SCPFileTransfer ft = getSSHClient().newSCPFileTransfer();
final SFTPClient sftp = getSSHClient().newSFTPClient();
try {
    // ft.upload(src, target);
    sftp.put(new FileSystemFile(src), target);
} finally {
 sftp.close();
}

I debug the process, the exception point is SFTPFileTransfer.Uploader.prepareFile

seems the server closed the socked after first response but the client still waiting the inputstream.

Any Information? Thanks a lot.

hierynomus commented 7 years ago

Hi @havid0707,

Do you have some debug logs, both from the client and the server side?

havid0707 commented 7 years ago

Thanks @hierynomus Client Code is quite simple: sshClient = new SSHClient(); sshClient.addHostKeyVerifier(new PromiscuousVerifier()); sshClient.connect("XXXXX.compute.amazonaws.com");

PKCS8KeyFile keyFile = new PKCS8KeyFile(); keyFile.init(new File("C://key.pem")); sshClient.auth("user", new AuthPublickey(keyFile));

image

hierynomus commented 7 years ago

Try to turn up logging to debug level, but also interesting the the AWS/Server side logging at debug level.

havid0707 commented 7 years ago

Server Site Debug Log:

Apr 25 02:56:23 ip-172-31-14-210 sshd[2988]: debug1: Forked child 3121.
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: Set /proc/self/oom_score_adj to 0
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: inetd sockets after dupping: 3, 3
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: Connection from 218.255.14.40 port 51037 on 172.31.14.210 port 22
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: Client protocol version 2.0; client software version SSHJ_0_17_2
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: no match: SSHJ_0_17_2
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: Enabling compatibility mode for protocol 2.0
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: Local version string SSH-2.0-OpenSSH_6.6.1
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: SELinux support disabled [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: permanently_set_uid: 74/74 [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: list_hostkey_types: ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: SSH2_MSG_KEXINIT received [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: kex: client->server aes128-ctr hmac-sha1 none [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: kex: server->client aes128-ctr hmac-sha1 none [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: kex: curve25519-sha256@libssh.org need=20 dh_need=20 [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: kex: curve25519-sha256@libssh.org need=20 dh_need=20 [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Apr 25 02:56:23 ip-172-31-14-210 sshd[3121]: debug1: KEX done [preauth]
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: userauth-request for user ec2-user service ssh-connection method publickey [preauth]
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: attempt 0 failures 0 [preauth]
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: reverse mapping checking getaddrinfo for static.reserve.wharfttidc.com [218.255.14.40] failed - POSSIBLE BREAK-IN ATTEMPT!
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: PAM: initializing for "ec2-user"
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: PAM: setting PAM_RHOST to "218.255.14.40"
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: PAM: setting PAM_TTY to "ssh"
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: test whether pkalg/pkblob are acceptable [preauth]
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: temporarily_use_uid: 500/500 (e=0/0)
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: trying public key file /home/ec2-user/.ssh/authorized_keys
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: fd 4 clearing O_NONBLOCK
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: Found matching RSA key: 4c:48:3d:96:52:0f:60:ba:a5:ca:39:8e:6c:d9:e0:9c
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: debug1: restore_uid: 0/0
Apr 25 02:56:24 ip-172-31-14-210 sshd[3121]: Postponed publickey for ec2-user from 218.255.14.40 port 51037 ssh2 [preauth]
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: userauth-request for user ec2-user service ssh-connection method publickey [preauth]
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: attempt 1 failures 0 [preauth]
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: temporarily_use_uid: 500/500 (e=0/0)
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: trying public key file /home/ec2-user/.ssh/authorized_keys
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: fd 4 clearing O_NONBLOCK
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: Found matching RSA key: 4c:48:3d:96:52:0f:60:ba:a5:ca:39:8e:6c:d9:e0:9c
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: restore_uid: 0/0
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: ssh_rsa_verify: signature correct
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: do_pam_account: called
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: Accepted publickey for ec2-user from 218.255.14.40 port 51037 ssh2: RSA 4c:48:3d:96:52:0f:60:ba:a5:ca:39:8e:6c:d9:e0:9c
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: monitor_child_preauth: ec2-user has been authenticated by privileged process
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: monitor_read_log: child log fd closed
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: SELinux support disabled
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: PAM: establishing credentials
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: pam_unix(sshd:session): session opened for user ec2-user by (uid=0)
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: User child is on pid 3123
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: PAM: establishing credentials
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: permanently_set_uid: 500/500
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: Entering interactive session for SSH2.
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: server_init_dispatch_20
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: input_session_request
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: channel 0: new [server-session]
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: session_new: session 0
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: session_open: channel 0
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: session_open: session 0: link with channel 0
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: server_input_channel_open: confirm session
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: session_by_channel: session 0 channel 0
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: session_input_channel_req: session 0 req subsystem
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: debug1: subsystem: exec() /usr/libexec/openssh/sftp-server
Apr 25 02:56:25 ip-172-31-14-210 sshd[3123]: Starting session: subsystem 'sftp' for ec2-user from 218.255.14.40 port 51037
Apr 25 02:56:25 ip-172-31-14-210 sshd[3121]: debug1: session_new: session 0

@hierynomus

havid0707 commented 7 years ago

I dont know how to change client log level. Google and found other guys have the same problem: http://stackoverflow.com/questions/43346755/how-can-i-modify-net-schmizz-sshj-logging-level

hierynomus commented 7 years ago

Create a logback.xml file and configure the logging to produce trace level logs for net.schmizz.sshj and com.hierynomus.sshj.

You can find an example file in the repo in src/test/resources.

havid0707 commented 7 years ago

@hierynomus Thanks for your help. Client Site Log:

17:19:34.285 [main] WARN net.schmizz.sshj.DefaultConfig - Disabling high-strength ciphers: cipher strengths apparently limited by JCE policy
17:19:34.285 [main] DEBUG net.schmizz.sshj.DefaultConfig - Available cipher factories: [net.schmizz.sshj.transport.cipher.AES128CTR$Factory@250b236d, net.schmizz.sshj.transport.cipher.AES128CBC$Factory@61f3fbb8, net.schmizz.sshj.transport.cipher.TripleDESCBC$Factory@7551da2a, net.schmizz.sshj.transport.cipher.BlowfishCBC$Factory@432034a, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, 3des-ctr, twofish128-cbc, twofish128-ctr, arcfour, arcfour128]
17:19:34.418 [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_17_2
17:19:34.466 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_6.6.1
17:19:34.466 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
17:19:34.466 [main] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
17:19:34.486 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
17:19:34.488 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
17:19:34.522 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
17:19:34.524 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=curve25519-sha256@libssh.org; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
17:19:34.709 [reader] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 - Sending SSH_MSG_KEXDH_INIT
17:19:34.762 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
17:19:34.762 [reader] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 - Received SSH_MSG_KEXDH_REPLY
17:19:34.762 [reader] DEBUG net.schmizz.sshj.common.KeyType$3 - Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: [-5, -20, 125, -60, -30, 23, -84, 104, -77, -79, 41, 16, 78, -55, -47, -39, 80, 64, 57, -56, -27, -105, -72, -110, -32, -102, -108, -58, -97, -10, 62, -13]
y: [57, 86, 0, -52, 99, -7, -125, -65, -6, 44, -98, -27, 12, -102, -89, -64, -69, 107, -90, -51, -7, 64, -22, 96, 32, 77, 5, -35, 74, 18, -67, 52]
17:19:34.951 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@37d05e8d
17:19:34.952 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
17:19:34.952 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
17:19:34.962 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
17:19:34.963 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
17:19:34.964 [main] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.497 seconds
17:19:34.996 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
17:19:34.996 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
17:19:34.997 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
17:19:35.089 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
17:19:35.089 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
17:19:35.090 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
17:19:35.090 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Trying `publickey` auth...
17:19:35.090 [main] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] C:\m18key.pem}
17:19:35.128 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
17:19:35.186 [reader] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Asking `publickey` method to handle USERAUTH_60 packet
17:19:35.186 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Key acceptable, sending signed request
17:19:35.187 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] C:\m18key.pem}
17:19:35.268 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
17:19:35.268 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `true`
17:19:35.268 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - `publickey` auth successful
17:19:35.281 [main] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
17:19:35.281 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / open>>
17:19:35.359 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=0] >
17:19:35.359 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / open>> to `SOME`
17:19:35.360 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request `sftp` subsystem
17:19:35.360 [main] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `subsystem`
17:19:35.361 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / chanreq for subsystem>>
17:19:35.411 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Received window adjustment for 2097152 bytes
17:19:35.411 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Increasing by 2097152 up to 2097152
17:19:35.412 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / chanreq for subsystem>> to `SOME`
17:19:35.419 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 9 down to 2097143
17:19:35.471 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 154 down to 2096998
17:19:35.471 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Server version 3
17:19:35.487 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{1;STAT}
17:19:35.488 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 27 down to 2097116
17:19:35.488 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 1>>
17:19:35.538 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Local - Consuming by 33 down to 2096965
17:19:35.539 [sftp reader] DEBUG net.schmizz.sshj.sftp.PacketReader - Received STATUS packet
17:19:35.540 [sftp reader] DEBUG net.schmizz.concurrent.Promise - Setting <<sftp / 1>> to `Buffer [rpos=5, wpos=29, size=29]`
17:19:35.543 [main] DEBUG net.schmizz.sshj.sftp.SFTPFileTransfer - isDir: /home/ec2-user does not exist
17:19:35.544 [main] DEBUG net.schmizz.sshj.xfer.LoggingTransferListener - started transferring file `winscp555setup.7z` (4593510 bytes)
17:19:35.545 [main] DEBUG net.schmizz.sshj.sftp.SFTPEngine - Sending Request{2;STAT}
17:19:35.546 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 27 down to 2097089
17:19:35.546 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<sftp / 2>>
17:19:56.856 [reader] ERROR net.schmizz.sshj.transport.TransportImpl - Dying because - {}
java.net.SocketException: Software caused connection abort: recv failed
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at net.schmizz.sshj.transport.Reader.run(Reader.java:50)
17:19:56.857 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Disconnected - UNKNOWN
17:19:56.859 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
17:19:56.859 [reader] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
17:19:56.860 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Channel #0 got notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
17:19:56.861 [reader] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
17:19:56.861 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / close>> to `SOME`
17:19:56.861 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to null-service
17:19:56.862 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
17:19:56.862 [main] ERROR net.schmizz.concurrent.Promise - <<sftp / 2>> woke to: net.schmizz.sshj.sftp.SFTPException: Software caused connection abort: recv failed
17:19:56.862 [reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping
net.schmizz.sshj.sftp.SFTPException: Software caused connection abort: recv failed
hierynomus commented 7 years ago

@havid0707 Can you try the 0.21.1 version that I've just released to see whether this still occurs? I think the fix in there should fix your issue.

havid0707 commented 7 years ago

@hierynomus the probleam still exists. And I found V20-V21 failed to run final Command cmd = session.exec("bash initlinux.bash"); but V15-V18 success.

exec log

09:29:31.256 [main] WARN net.schmizz.sshj.DefaultConfig - Disabling high-strength ciphers: cipher strengths apparently limited by JCE policy
09:29:31.256 [main] DEBUG net.schmizz.sshj.DefaultConfig - Available cipher factories: [net.schmizz.sshj.transport.cipher.AES128CTR$Factory@34fe326d, net.schmizz.sshj.transport.cipher.AES128CBC$Factory@30a7c98f, net.schmizz.sshj.transport.cipher.TripleDESCBC$Factory@36361ddb, net.schmizz.sshj.transport.cipher.BlowfishCBC$Factory@41fed14f, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, 3des-ctr, twofish128-cbc, twofish128-ctr, arcfour, arcfour128]
09:29:31.353 [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0.21.1
09:29:31.396 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_6.6.1
09:29:31.397 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
09:29:31.397 [main] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
09:29:31.409 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
09:29:31.410 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
09:29:31.459 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
09:29:31.462 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=curve25519-sha256@libssh.org; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
09:29:31.590 [reader] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 - Sending SSH_MSG_KEXDH_INIT
09:29:31.646 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
09:29:31.646 [reader] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 - Received SSH_MSG_KEXDH_REPLY
09:29:31.647 [reader] DEBUG net.schmizz.sshj.common.KeyType$3 - Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: [-5, -20, 125, -60, -30, 23, -84, 104, -77, -79, 41, 16, 78, -55, -47, -39, 80, 64, 57, -56, -27, -105, -72, -110, -32, -102, -108, -58, -97, -10, 62, -13]
y: [57, 86, 0, -52, 99, -7, -125, -65, -6, 44, -98, -27, 12, -102, -89, -64, -69, 107, -90, -51, -7, 64, -22, 96, 32, 77, 5, -35, 74, 18, -67, 52]
09:29:31.960 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@5d10273a
09:29:31.960 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
09:29:31.961 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
09:29:31.970 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
09:29:31.970 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
09:29:31.971 [main] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.574 seconds
09:29:31.994 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
09:29:31.994 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
09:29:31.995 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
09:29:32.104 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
09:29:32.104 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
09:29:32.105 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
09:29:32.105 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Trying `publickey` auth...
09:29:32.105 [main] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] C:\m18key.pem}
09:29:32.134 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
09:29:32.310 [reader] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Asking `publickey` method to handle USERAUTH_60 packet
09:29:32.311 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Key acceptable, sending signed request
09:29:32.311 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] C:\m18key.pem}
09:29:32.486 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
09:29:32.486 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `true`
09:29:32.487 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - `publickey` auth successful
09:29:32.501 [main] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
09:29:32.502 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / open>>
09:29:32.569 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=0] >
09:29:32.569 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / open>> to `SOME`
09:29:32.570 [main] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request to exec `bash initlinux.bash`
09:29:32.570 [main] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `exec`
09:29:32.571 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / chanreq for exec>>
09:29:51.482 [reader] ERROR net.schmizz.sshj.transport.TransportImpl - Dying because - {}
java.net.SocketException: Software caused connection abort: recv failed
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at net.schmizz.sshj.transport.Reader.run(Reader.java:49)
09:29:51.484 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Disconnected - UNKNOWN
09:29:51.486 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
09:29:51.486 [reader] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
09:29:51.488 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Channel #0 got notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
09:29:51.489 [reader] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
09:29:51.489 [main] ERROR net.schmizz.concurrent.Promise - <<chan#0 / chanreq for exec>> woke to: net.schmizz.sshj.connection.ConnectionException: Software caused connection abort: recv failed
09:29:51.489 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / close>> to `SOME`
09:29:51.489 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to null-service
09:29:51.490 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
09:29:51.490 [reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping
net.schmizz.sshj.connection.ConnectionException: Software caused connection abort: recv failed

STFP Log:

09:33:59.016 [main] DEBUG net.schmizz.sshj.DefaultConfig - Available cipher factories: [net.schmizz.sshj.transport.cipher.AES128CTR$Factory@baf1bb3, net.schmizz.sshj.transport.cipher.AES128CBC$Factory@67ec8477, net.schmizz.sshj.transport.cipher.TripleDESCBC$Factory@25d958c6, net.schmizz.sshj.transport.cipher.BlowfishCBC$Factory@4482469c, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, 3des-ctr, twofish128-cbc, twofish128-ctr, arcfour, arcfour128]
09:33:59.094 [main] INFO net.schmizz.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0.21.1
09:33:59.152 [main] INFO net.schmizz.sshj.transport.TransportImpl - Server identity string: SSH-2.0-OpenSSH_6.6.1
09:33:59.153 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
09:33:59.153 [main] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
09:33:59.170 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
09:33:59.172 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
09:33:59.206 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
09:33:59.208 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=curve25519-sha256@libssh.org; sig=ecdsa-sha2-nistp256; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
09:33:59.299 [reader] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 - Sending SSH_MSG_KEXDH_INIT
09:33:59.352 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received kex followup data
09:33:59.353 [reader] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 - Received SSH_MSG_KEXDH_REPLY
09:33:59.354 [reader] DEBUG net.schmizz.sshj.common.KeyType$3 - Key algo: ecdsa-sha2-nistp256, Key curve: nistp256, Key Len: 65, 0x04: 4
x: [-5, -20, 125, -60, -30, 23, -84, 104, -77, -79, 41, 16, 78, -55, -47, -39, 80, 64, 57, -56, -27, -105, -72, -110, -32, -102, -108, -58, -97, -10, 62, -13]
y: [57, 86, 0, -52, 99, -7, -125, -65, -6, 44, -98, -27, 12, -102, -89, -64, -69, 107, -90, -51, -7, 64, -22, 96, 32, 77, 5, -35, 74, 18, -67, 52]
09:33:59.587 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@337ab6a5
09:33:59.587 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
09:33:59.588 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
09:33:59.596 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
09:33:59.596 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
09:33:59.596 [main] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.443 seconds
09:33:59.620 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `null`
09:33:59.620 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth
09:33:59.621 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<service accept>>
09:33:59.727 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<service accept>> to `SOME`
09:33:59.728 [main] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-userauth
09:33:59.729 [main] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `null`
09:33:59.729 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Trying `publickey` auth...
09:33:59.729 [main] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] C:\m18key.pem}
09:33:59.777 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<authenticated>>
09:34:00.099 [reader] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - Asking `publickey` method to handle USERAUTH_60 packet
09:34:00.100 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Key acceptable, sending signed request
09:34:00.100 [reader] DEBUG net.schmizz.sshj.userauth.method.AuthPublickey - Attempting authentication using PKCS8KeyFile{resource=[PrivateKeyFileResource] C:\m18key.pem}
09:34:00.304 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to ssh-connection
09:34:00.304 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<authenticated>> to `true`
09:34:00.305 [main] DEBUG net.schmizz.sshj.userauth.UserAuthImpl - `publickey` auth successful
09:34:00.324 [main] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Attaching `session` channel (#0)
09:34:00.325 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / open>>
09:34:00.390 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Initialized - < session channel: id=0, recipient=0, localWin=[winSize=2097152], remoteWin=[winSize=0] >
09:34:00.390 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / open>> to `SOME`
09:34:00.390 [main] INFO net.schmizz.sshj.connection.channel.direct.SessionChannel - Will request `sftp` subsystem
09:34:00.391 [main] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Sending channel request for `subsystem`
09:34:00.391 [main] DEBUG net.schmizz.concurrent.Promise - Awaiting <<chan#0 / chanreq for subsystem>>
09:34:00.443 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Received window adjustment for 2097152 bytes
09:34:00.443 [reader] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Increasing by 2097152 up to 2097152
09:34:00.444 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / chanreq for subsystem>> to `SOME`
09:34:00.449 [main] DEBUG net.schmizz.sshj.connection.channel.Window$Remote - Consuming by 9 down to 2097143
09:34:19.362 [reader] ERROR net.schmizz.sshj.transport.TransportImpl - Dying because - {}
java.net.SocketException: Software caused connection abort: recv failed
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at net.schmizz.sshj.transport.Reader.run(Reader.java:49)
09:34:19.364 [reader] INFO net.schmizz.sshj.transport.TransportImpl - Disconnected - UNKNOWN
09:34:19.365 [reader] DEBUG net.schmizz.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
09:34:19.366 [reader] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
09:34:19.370 [reader] DEBUG net.schmizz.sshj.connection.channel.direct.SessionChannel - Channel #0 got notified of net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
09:34:19.370 [reader] DEBUG net.schmizz.sshj.connection.ConnectionImpl - Forgetting `session` channel (#0)
09:34:19.370 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<chan#0 / close>> to `SOME`
09:34:19.371 [reader] DEBUG net.schmizz.sshj.transport.TransportImpl - Setting active service to null-service
09:34:19.371 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
09:34:19.371 [reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping
net.schmizz.sshj.common.SSHException: Software caused connection abort: recv failed
havid0707 commented 7 years ago

Conclusion: V20-V21: failed to transfer file and run remote command. V15-18: failed to transfer file but run remote command successfully.

havid0707 commented 7 years ago

@hierynomus any comment?

hierynomus commented 7 years ago

Need to have a deeper look. No idea yet.