Where to look next?

[Delisle, John]

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.

Thanks!



Complete debug output (obfuscated to remove confidential data):

[root@client ~]# sftp -vvvv -oport=32 SOME...@some.server.we.have
OpenSSH_7.2p2, OpenSSL 1.0.2h 3 May 2016
debug1: Reading configuration data /etc/ssh/ssh_config
debug2: resolving "some.server.we.have" port 32
debug2: ssh_connect_direct: needpriv 0
debug1: Connecting to some.server.we.have [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 some.server.we.have:32 as 'SOMEUSER'
debug3: put_host_port: [some.server.we.have]:32
debug3: hostkeys_foreach: reading file "/root/.ssh/known_hosts"
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: curve255...@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,ext-info-c
debug2: host key algorithms: ecdsa-sha2-nis...@openssh.com,ecdsa-sha2-nis...@openssh.com,ecdsa-sha2-nis...@openssh.com,ssh-ed2551...@openssh.com,ssh-rsa-...@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: chacha20...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes12...@openssh.com,aes25...@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: ciphers stoc: chacha20...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes12...@openssh.com,aes25...@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: MACs ctos: umac-...@openssh.com,umac-1...@openssh.com,hmac-sha...@openssh.com,hmac-sha...@openssh.com,hmac-s...@openssh.com,uma...@openssh.com,umac...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-...@openssh.com,umac-1...@openssh.com,hmac-sha...@openssh.com,hmac-sha...@openssh.com,hmac-s...@openssh.com,uma...@openssh.com,umac...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zl...@openssh.com,zlib
debug2: compression stoc: none,zl...@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: ecdh-sha2-nistp256
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
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!
Disconnected from 1.2.3.4 port 32
Couldn't read packet: Connection reset by peer


John Delisle | Solution Architecture | Ceridian HCM | w: 204.975.5909 / 204.414.1285 |c: 204.294.5529
Ceridian. Makes Work Life Better(tm)

_______________________________________________
openssh-unix-dev mailing list
openssh-...@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev

[Damien Miller]

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

[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@client ~]# sftp -vvv -oKEXAlgorithms=diffie-hellman-group14-sha1 -oport=32 SOME...@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-...@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-...@openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nis...@openssh.com,ecdsa-sha2-nis...@openssh.com,ecdsa-sha2-nis...@openssh.com,ssh-ed2551...@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519

debug2: ciphers ctos: chacha20...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes12...@openssh.com,aes25...@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: ciphers stoc: chacha20...@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes12...@openssh.com,aes25...@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,3des-cbc
debug2: MACs ctos: umac-...@openssh.com,umac-1...@openssh.com,hmac-sha...@openssh.com,hmac-sha...@openssh.com,hmac-s...@openssh.com,uma...@openssh.com,umac...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-...@openssh.com,umac-1...@openssh.com,hmac-sha...@openssh.com,hmac-sha...@openssh.com,hmac-s...@openssh.com,uma...@openssh.com,umac...@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zl...@openssh.com,zlib
debug2: compression stoc: none,zl...@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
SOME...@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.
SOME...@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.
SOME...@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

[Nico Kadel-Garcia]

On Wed, Sep 21, 2016 at 12:28 PM, Delisle, John
<john.d...@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?

[Darren Tucker]

On Thu, Sep 22, 2016 at 2:28 AM, Delisle, John
<john.d...@ceridian.com> wrote:
[...]

> debug1: Remote protocol version 2.0, remote software version Welcome To Ceridian

OpenSSH should probably log it better, but this banner is weird.
According to RFC 4253 section 4.2 the format is:

SSH-protoversion-softwareversion SP comments CR LF

so this server is claiming that its software version is "Welcome" with
a comment of "To Ceridian".

[...]

> debug3: receive packet: type 1
> Received disconnect from 1.2.3.4 port 32:11: Too many bad authentication attempts!

The server sends a disconnect.

> debug1: Authentication succeeded (password).
> Authenticated to IBM.SFG.SFTP.server ([1.2.3.4]:32).

The client thinks the session is authenticated, though. I think
that's actually a bug in the OpenSSH client: ssh_userauth2() calls
ssh_dispatch_run() with DISPATCH_BLOCK blocking on authctxt.success.
It assumes that if it exits then it's authenticated.

ssh_packet_read_poll_seqnr(), however, will return
SSH_ERR_DISCONNECTED in that case, which will cause ssh_dispatch_run()
to return.

I don't think this is relevant to your problem, though.

--
Darren Tucker (dtucker at zip.com.au)
GPG key 11EAA6FA / A86E 3E07 5B19 5880 E860 37F4 9357 ECEF 11EA A6FA (new)
Good judgement comes with experience. Unfortunately, the experience
usually comes from bad judgement.

[Darren Tucker]

On Thu, Sep 22, 2016 at 09:51:11AM +1000, Darren Tucker wrote:
> The client thinks the session is authenticated, though. I think
> that's actually a bug in the OpenSSH client: ssh_userauth2() calls
> ssh_dispatch_run() with DISPATCH_BLOCK blocking on authctxt.success.
> It assumes that if it exits then it's authenticated.
>
> ssh_packet_read_poll_seqnr(), however, will return
> SSH_ERR_DISCONNECTED in that case, which will cause ssh_dispatch_run()
> to return.

This should handle this case.

diff --git a/sshconnect2.c b/sshconnect2.c
index fae8b0f..ae77243 100644
--- a/sshconnect2.c
+++ b/sshconnect2.c
@@ -404,6 +404,8 @@ ssh_userauth2(const char *local_user, const char *server_user, char *host,
pubkey_cleanup(&authctxt);
ssh_dispatch_range(ssh, SSH2_MSG_USERAUTH_MIN, SSH2_MSG_USERAUTH_MAX, NULL);

+ if (!authctxt.success)
+ fatal("Authentication failed.");
debug("Authentication succeeded (%s).", authctxt.method->name);