Where to look next?

Thu Sep 22 09:40:44 AEST 2016

On Wed, Sep 21, 2016 at 12:28 PM, Delisle, John
<john.delisle at ceridian.com> wrote:
> 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.

Ask the people on the *server* side to share their logs?

> [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
> _______________________________________________
> openssh-unix-dev mailing list
> openssh-unix-dev at mindrot.org
> https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev