Where to look next?

[Delisle, John]

Thanks for your suggestion!  It seems to have gone a little further this time, but isn't accepting the key and is failing back on password-based auth.

We're double-checking that the public key was correctly configured with the account, and also trying a DSA key to see if it behaves differently.  

Is there anything you'd suggest we look at or try at this point, and thank you very much for your input.

[root at client ~]# sftp -vvv -oKEXAlgorithms=diffie-hellman-group14-sha1  -oport=32 SOMEUSER at IBM.SFG.SFTP.server  
OpenSSH_7.2p2, OpenSSL 1.0.2h  3 May 2016
debug1: Reading configuration data /etc/ssh/ssh_config
debug2: resolving "IBM.SFG.SFTP.server" port 32
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to IBM.SFG.SFTP.server [1.2.3.4] port 32.
debug1: Connection established.
debug1: permanently_set_uid: 0/0
debug1: identity file /root/.ssh/id_rsa type 1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_rsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_dsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_dsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_ecdsa type -1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_ecdsa-cert type -1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_ed25519 type -1
debug1: key_load_public: No such file or directory
debug1: identity file /root/.ssh/id_ed25519-cert type -1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_7.2
debug1: Remote protocol version 2.0, remote software version Welcome To Ceridian
debug1: no match: Welcome To Ceridian
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to IBM.SFG.SFTP.server:32 as 'SOMEUSER'
debug3: put_host_port: [IBM.SFG.SFTP.server]:32
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /root/.ssh/known_hosts:57
debug3: load_hostkeys: loaded 1 keys from [IBM.SFG.SFTP.server]:32
debug3: order_hostkeyalgs: prefer hostkeyalgs: ssh-rsa-cert-v01 at openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: diffie-hellman-group14-sha1,ext-info-c
debug2: host key algorithms: ssh-rsa-cert-v01 at openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256-cert-v01 at openssh.com,ecdsa-sha2-nistp384-cert-v01 at openssh.com,ecdsa-sha2-nistp521-cert-v01 at openssh.com,ssh-ed25519-cert-v01 at openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519
debug2: ciphers ctos: chacha20-poly1305 at openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm at openssh.com,aes256-gcm at openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: ciphers stoc: chacha20-poly1305 at openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm at openssh.com,aes256-gcm at openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: MACs ctos: umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm at openssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-sha1-etm at openssh.com,umac-64 at openssh.com,umac-128 at openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib at openssh.com,zlib
debug2: compression stoc: none,zlib at openssh.com,zlib
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1,diffie-hellman-group-exchange-sha256,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521
debug2: host key algorithms: ssh-rsa
debug2: ciphers ctos: aes256-cbc,aes192-cbc
debug2: ciphers stoc: aes256-cbc,aes192-cbc
debug2: MACs ctos: hmac-sha1
debug2: MACs stoc: hmac-sha1
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug1: kex: algorithm: diffie-hellman-group14-sha1
debug1: kex: host key algorithm: ssh-rsa
debug1: kex: server->client cipher: aes192-cbc MAC: hmac-sha1 compression: none
debug1: kex: client->server cipher: aes192-cbc MAC: hmac-sha1 compression: none
debug1: sending SSH2_MSG_KEXDH_INIT
debug2: bits set: 1015/2048
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEXDH_REPLY
debug3: receive packet: type 31
debug1: Server host key: ssh-rsa SHA256:0oLfkrEjIEDItjZDXCt+5EJuVSLzjNuO0apIZtrFnXA
debug3: put_host_port: [1.2.3.4]:32
debug3: put_host_port: [IBM.SFG.SFTP.server]:32
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /root/.ssh/known_hosts:57
debug3: load_hostkeys: loaded 1 keys from [IBM.SFG.SFTP.server]:32
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
debug3: record_hostkey: found key type RSA in file /root/.ssh/known_hosts:57
debug3: load_hostkeys: loaded 1 keys from [1.2.3.4]:32
debug1: Host '[IBM.SFG.SFTP.server]:32' is known and matches the RSA host key.
debug1: Found key in /root/.ssh/known_hosts:57
debug2: bits set: 1022/2048
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug2: set_newkeys: mode 0
debug1: rekey after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS received
debug2: key: /root/.ssh/id_rsa (0x5590b459ff30)
debug2: key: /root/.ssh/id_dsa ((nil))
debug2: key: /root/.ssh/id_ecdsa ((nil))
debug2: key: /root/.ssh/id_ed25519 ((nil))
debug3: send packet: type 5
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 53
debug3: input_userauth_banner
Thank You
debug3: receive packet: type 51
debug1: Authentications that can continue: keyboard-interactive,publickey,password
debug3: start over, passed a different list keyboard-interactive,publickey,password
debug3: preferred publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering RSA public key: /root/.ssh/id_rsa
debug3: send_pubkey_test
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: keyboard-interactive,publickey,password
debug1: Trying private key: /root/.ssh/id_dsa
debug3: no such identity: /root/.ssh/id_dsa: No such file or directory
debug1: Trying private key: /root/.ssh/id_ecdsa
debug3: no such identity: /root/.ssh/id_ecdsa: No such file or directory
debug1: Trying private key: /root/.ssh/id_ed25519
debug3: no such identity: /root/.ssh/id_ed25519: No such file or directory
debug2: we did not send a packet, disable method
debug3: authmethod_lookup keyboard-interactive
debug3: remaining preferred: password
debug3: authmethod_is_enabled keyboard-interactive
debug1: Next authentication method: keyboard-interactive
debug2: userauth_kbdint
debug3: send packet: type 50
debug2: we sent a keyboard-interactive packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: keyboard-interactive,publickey,password
debug3: userauth_kbdint: disable: no info_req_seen
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred: 
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
SOMEUSER at IBM.SFG.SFTP.server's password: 
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 2
debug3: Received SSH2_MSG_IGNORE
debug3: receive packet: type 51
debug1: Authentications that can continue: keyboard-interactive,publickey,password
Permission denied, please try again.
SOMEUSER at IBM.SFG.SFTP.server's password: 
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: keyboard-interactive,publickey,password
Permission denied, please try again.
SOMEUSER at IBM.SFG.SFTP.server's password: 
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 1
Received disconnect from 1.2.3.4 port 32:11: Too many bad authentication attempts!
debug1: Authentication succeeded (password).
Authenticated to IBM.SFG.SFTP.server ([1.2.3.4]:32).
debug2: fd 4 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug3: send packet: type 90
debug1: Entering interactive session.
debug1: pledge: network
debug3: send packet: type 1
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 client-session (t3 r-1 i0/0 o0/0 fd 4/5 cc -1)

debug1: fd 0 clearing O_NONBLOCK
debug3: fd 1 is not O_NONBLOCK
Connection to IBM.SFG.SFTP.server closed by remote host.
Transferred: sent 2480, received 1744 bytes, in 0.0 seconds
Bytes per second: sent 6393284.5, received 4495922.7
debug1: Exit status -1
Couldn't read packet: Connection reset by peer




-----Original Message-----
From: Damien Miller [mailto:djm at mindrot.org] 
Sent: Wednesday, September 21, 2016 11:03 AM
To: Delisle, John <john.delisle at ceridian.com>
Cc: openssh-unix-dev at mindrot.org; Babcock, Peter <Peter.Babcock at Ceridian.com>; Olbruck, Eric <Eric.Olbruck at Ceridian.com>
Subject: Re: Where to look next?

On Wed, 21 Sep 2016, Delisle, John wrote:

> Hello,
>
> I'm looking for your insight about the log below. We have an SFTP 
> server (IBM Sterling File Gateway) and we're connecting from an 
> OpenSSH SFTP client but something fails during KEX.
>
> Complete client-side debug output is below, but I believe the relevant 
> part is:
>
> debug1: kex: server->client cipher: aes192-cbc MAC: hmac-sha1 
> compression: none
> debug1: kex: client->server cipher: aes192-cbc MAC: hmac-sha1 
> compression: none
> debug3: send packet: type 30
> debug1: sending SSH2_MSG_KEX_ECDH_INIT
> debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
> debug3: receive packet: type 1
> Received disconnect from 1.2.3.4 port 32:2: Failed to read binary packet data!
>
> Any suggestions about what's failing, and what the cause might be?
> We're trying to figure out where to go in our troubleshooting, and do 
> not understand the meaning of this debug output.

It's failing during key exchange (KEX). You could try explicitly selecting a different key exchange method e.g.

sftp -oKEXAlgorithms=diffie-hellman-group14-sha1 ...

If that works then it's highly likely that the IBM server has implemented the ecdh-sha2-nistp256 method incorrectly.

-d