#932089 openssh-server: Cannot log into openssh-server on buster/mipsel

Package:
openssh-server
Source:
openssh
Description:
secure shell (SSH) server, for secure access from remote machines
Submitter:
Francois Marier
Date:
2019-10-21 11:00:03 UTC
Severity:
important
#932089#5
Date:
2019-07-14 21:22:21 UTC
From:
To:
In a fairly minimal buster installation on mipsel, I am unable to log into
openssh-server from a Debian unstable client.

Here's the debug log when I start sshd manually:

$ systemctl stop sshd
$ mkdir /run/sshd
$ /usr/sbin/sshd -ddd
debug2: load_server_config: filename /etc/ssh/sshd_config
debug2: load_server_config: done config len = 262
debug2: parse_server_config: config /etc/ssh/sshd_config len 262
debug3: /etc/ssh/sshd_config:32 setting PermitRootLogin yes
debug3: /etc/ssh/sshd_config:56 setting PasswordAuthentication yes
debug3: /etc/ssh/sshd_config:61 setting ChallengeResponseAuthentication no
debug3: /etc/ssh/sshd_config:84 setting UsePAM yes
debug3: /etc/ssh/sshd_config:89 setting X11Forwarding yes
debug3: /etc/ssh/sshd_config:93 setting PrintMotd no
debug3: /etc/ssh/sshd_config:111 setting AcceptEnv LANG LC_* TZ
debug1: sshd version OpenSSH_7.9, OpenSSL 1.1.1c  28 May 2019
debug1: private host key #0: ssh-rsa SHA256:x
debug1: private host key #1: ecdsa-sha2-nistp256 SHA256:x
debug1: private host key #2: ssh-ed25519 SHA256:x
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-ddd'
debug3: oom_adjust_setup
debug1: Set /proc/self/oom_score_adj from 0 to -1000
debug2: fd 3 setting O_NONBLOCK
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.
debug2: fd 4 setting O_NONBLOCK
debug3: sock_set_v6only: set socket 4 IPV6_V6ONLY
debug1: Bind to port 22 on ::.
Server listening on :: port 22.
debug3: fd 5 is not O_NONBLOCK
debug1: Server will not fork when running in debugging mode.
debug3: send_rexec_state: entering fd = 8 config len 262
debug3: ssh_msg_send: type 0
debug3: send_rexec_state: done
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 192.168.1.5 port 44740 on 192.168.1.172 port 22
debug1: Client protocol version 2.0; client software version OpenSSH_8.0p1 Debian-3
debug1: match: OpenSSH_8.0p1 Debian-3 pat OpenSSH* compat 0x04000000
debug1: Local version string SSH-2.0-OpenSSH_7.9p1 Debian-10
debug2: fd 3 setting O_NONBLOCK
debug3: ssh_sandbox_init: preparing seccomp filter sandbox
debug2: Network child is on pid 6055
debug3: preauth child monitor started
debug3: privsep user:group 104:65534 [preauth]
debug1: permanently_set_uid: 104/65534 [preauth]
debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth]
debug3: ssh_sandbox_child: attaching seccomp filter program [preauth]
debug1: ssh_sandbox_child: prctl(PR_SET_SECCOMP): Invalid argument [preauth]
debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
debug3: send packet: type 20 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug3: receive packet: type 20 [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug2: local server KEXINIT proposal [preauth]
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-shh
a256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1 [preauth]
debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-66
4@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-66
4@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
debug2: compression ctos: none,zlib@openssh.com [preauth]
debug2: compression stoc: none,zlib@openssh.com [preauth]
debug2: languages ctos:  [preauth]
debug2: languages stoc:  [preauth]
debug2: first_kex_follows 0  [preauth]
debug2: reserved 0  [preauth]
debug2: peer client KEXINIT proposal [preauth]
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-shh
a256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c [preauth]
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdss
a-sha2-nistp521-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa--
sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-66
4@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-66
4@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
debug2: compression ctos: none,zlib@openssh.com,zlib [preauth]
debug2: compression stoc: none,zlib@openssh.com,zlib [preauth]
debug2: languages ctos:  [preauth]
debug2: languages stoc:  [preauth]
debug2: first_kex_follows 0  [preauth]
debug2: reserved 0  [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ssh-ed25519 [preauth]
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug3: receive packet: type 30 [preauth]
debug3: mm_sshkey_sign entering [preauth]
debug3: mm_request_send entering: type 6 [preauth]
debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
debug3: mm_request_receive_expect entering: type 7 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 6
debug3: mm_answer_sign
debug3: mm_answer_sign: hostkey proof signature 0x55c44540(83)
debug3: mm_request_send entering: type 7
debug2: monitor_read: 6 used once, disabling now
debug3: send packet: type 31 [preauth]
debug3: send packet: type 21 [preauth]
debug2: set_newkeys: mode 1 [preauth]
debug1: rekey after 134217728 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug3: send packet: type 7 [preauth]
debug3: receive packet: type 21 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: rekey after 134217728 blocks [preauth]
debug1: KEX done [preauth]
debug3: receive packet: type 5 [preauth]
debug3: send packet: type 6 [preauth]
debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user root service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug3: mm_getpwnamallow entering [preauth]
debug3: mm_request_send entering: type 8 [preauth]
debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
debug3: mm_request_receive_expect entering: type 9 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 8
debug3: mm_answer_pwnamallow
debug2: parse_server_config: config reprocess config len 262
debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
debug3: mm_request_send entering: type 9
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for root [preauth]
debug3: mm_start_pam entering [preauth]
debug3: mm_request_send entering: type 100 [preauth]
debug3: mm_inform_authserv entering [preauth]
debug3: mm_request_send entering: type 4 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 100
debug1: PAM: initializing for "root"
debug1: PAM: setting PAM_RHOST to "192.168.1.5"
debug1: PAM: setting PAM_TTY to "ssh"
debug2: monitor_read: 100 used once, disabling now
debug3: user_specific_delay: user specific delay 0.000ms [preauth]
debug3: ensure_minimum_time_since: elapsed 7.724ms, delaying 2.422ms (requested 5.073ms) [preauth]
debug3: userauth_finish: failure partial=0 next methods="publickey,password" [preauth]
debug3: send packet: type 51 [preauth]
debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user root service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug1: userauth_pubkey: test pkalg ssh-ed25519 pkblob ED25519 SHA256:x [preauth]
debug3: mm_key_allowed entering [preauth]
debug3: mm_request_send entering: type 22 [preauth]
debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
debug3: mm_request_receive_expect entering: type 23 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=, role=
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 22
debug3: mm_answer_keyallowed entering
debug3: mm_answer_keyallowed: key_from_blob: 0x55c59e70
debug1: temporarily_use_uid: 0/0 (e=0/0)
debug1: trying public key file /root/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: /root/.ssh/authorized_keys:1: matching key found: ED25519 SHA256:x
debug1: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Accepted key ED25519 SHA256:x found at /root/.ssh/authorized_keys:1
debug1: restore_uid: 0/0
debug3: mm_answer_keyallowed: publickey authentication test: ED25519 key is allowed
debug3: mm_request_send entering: type 23
debug3: send packet: type 60 [preauth]
debug2: userauth_pubkey: authenticated 0 pkalg ssh-ed25519 [preauth]
debug3: user_specific_delay: user specific delay 0.000ms [preauth]
debug1: monitor_read_log: child log fd closed
debug3: mm_request_receive entering
debug1: do_cleanup
debug1: PAM: cleanup
debug3: PAM: sshpam_thread_cleanup entering
debug1: Killing privsep child 6055
debug1: audit_event: unhandled event 12

and here's the log on the client side up to the point where sshd exits:

$ ssh -vvvvvvv root@192.168.1.172
OpenSSH_8.0p1 Debian-3, OpenSSL 1.1.1c  28 May 2019
debug1: Reading configuration data /home/francois/.ssh/config
debug3: kex names ok: [curve25519-sha256@libssh.org,ecdh-sha2-nistp521,ecdh-sha2-nistp256,ecdh-sha2-nistp384,diffie-hellman-group-exchange-sha256,diffie-hellman-group1-sha1]
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: Applying options for *
debug2: resolve_canonicalize: hostname 192.168.1.172 is address
debug2: ssh_connect_direct
debug1: Connecting to 192.168.1.172 [192.168.1.172] port 22.
debug1: Connection established.
debug1: identity file /home/francois/.ssh/id_rsa type -1
debug1: identity file /home/francois/.ssh/id_rsa-cert type -1
debug1: identity file /home/francois/.ssh/id_dsa type -1
debug1: identity file /home/francois/.ssh/id_dsa-cert type -1
debug1: identity file /home/francois/.ssh/id_ecdsa type -1
debug1: identity file /home/francois/.ssh/id_ecdsa-cert type -1
debug1: identity file /home/francois/.ssh/id_ed25519 type -1
debug1: identity file /home/francois/.ssh/id_ed25519-cert type -1
debug1: identity file /home/francois/.ssh/id_xmss type -1
debug1: identity file /home/francois/.ssh/id_xmss-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.0p1 Debian-3
debug1: Remote protocol version 2.0, remote software version OpenSSH_7.9p1 Debian-10
debug1: match: OpenSSH_7.9p1 Debian-10 pat OpenSSH* compat 0x04000000
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 192.168.1.172:22 as 'root'
debug3: hostkeys_foreach: reading file "/home/francois/.ssh/known_hosts"
debug3: record_hostkey: found key type ED25519 in file /home/francois/.ssh/known_hosts:309
debug3: load_hostkeys: loaded 1 keys from 192.168.1.172
debug3: order_hostkeyalgs: prefer hostkeyalgs: ssh-ed25519-cert-v01@openssh.com,ssh-ed25519
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: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@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: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1
debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com
debug2: compression stoc: none,zlib@openssh.com
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: Server host key: ssh-ed25519 SHA256:x
debug3: hostkeys_foreach: reading file "/home/francois/.ssh/known_hosts"
debug3: record_hostkey: found key type ED25519 in file /home/francois/.ssh/known_hosts:309
debug3: load_hostkeys: loaded 1 keys from 192.168.1.172
debug1: Host '192.168.1.172' is known and matches the ED25519 host key.
debug1: Found key in /home/francois/.ssh/known_hosts:309
debug3: send packet: type 21
debug2: set_newkeys: mode 1
debug1: rekey out after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: set_newkeys: mode 0
debug1: rekey in after 134217728 blocks
debug1: Will attempt key: francois@akranes ED25519 SHA256:x
debug1: Will attempt key: francois@akranes(foss) ED25519 SHA256:x
debug1: Will attempt key: /home/francois/.ssh/id_rsa
debug1: Will attempt key: /home/francois/.ssh/id_dsa
debug1: Will attempt key: /home/francois/.ssh/id_ecdsa
debug1: Will attempt key: /home/francois/.ssh/id_ed25519
debug1: Will attempt key: /home/francois/.ssh/id_xmss
debug2: pubkey_prepare: done
debug3: send packet: type 5
debug3: receive packet: type 7
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521>
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 51
debug1: Authentications that can continue: publickey,password
debug3: start over, passed a different list publickey,password
debug3: preferred gssapi-with-mic,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 public key: francois@akranes ED25519 SHA256:x
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 60
debug1: Server accepts key: francois@akranes ED25519 SHA256:x
debug3: sign_and_send_pubkey: ED25519 SHA256:x
debug3: sign_and_send_pubkey: signing using ssh-ed25519

Here are the things I've tried (all were unsuccesful):

1. Revert the new OpenSSL default back to pre-buster values as per
https://www.debian.org/releases/buster/amd64/release-notes/ch-information.en.html#openssl-defaults.

2. I tried logging in as a normal user instead of root.

3. Changed the permissions of .ssh to 700 and .ssh/authorized_keys to 644.

4. I installed haveged as per
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=912087#254.

5. I re-generated the host keys as per
https://www.raspberrypi.org/forums/viewtopic.php?t=168310#p1083440.

6. I explicitly disabled the sandbox using `UsePrivilegeSeparation yes` as
per https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=868009.

I have run out of ideas to debug this further but I'm happy to run whatever
test you'd like on my mipsel server.

Francois

#932089#10
Date:
2019-07-14 22:23:35 UTC
From:
To:
(You might find it more convenient to temporarily run sshd on a high
port using the -p option, rather than having to stop the system's sshd
service.)

Judging from this, the crash (or is it a hang?  I'm assuming a crash) is
near the start of ensure_minimum_time_since, probably inside
monotime_ts.  I suspect there's something wrong with the seccomp
sandboxing of the privileged monitor process on mipsel.

Could you try installing the auditd package, and then running this
before starting sshd:

  auditctl -a exit,always -F uid="$(id -u sshd)"

(Replace -a with -d to undo this.)  You should then get a log of
syscalls made by sshd's privileged monitor process in
/var/log/audit/audit.log; I'd like the lines containing the string
'exe="/usr/sbin/sshd"'.

You're right that this would once have been a good test to run to
exclude the possibility of a seccomp sandbox bug.  However, the ability
to configure UsePrivilegeSeparation was withdrawn in OpenSSH 7.5, so
this test is now ineffective.

Thanks,

#932089#15
Date:
2019-07-15 05:26:05 UTC
From:
To:
Yes, I also think it's a crash. It doesn't hang at all.

auditd fails to start after installation (and restart doesn't help):

  $ systemctl status auditd
  ● auditd.service - Security Auditing Service
     Loaded: loaded (/lib/systemd/system/auditd.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Mon 2019-07-15 05:03:21 UTC; 3min 8s ago
       Docs: man:auditd(8)
https://github.com/linux-audit/audit-documentation
    Process: 6841 ExecStart=/sbin/auditd (code=exited, status=1/FAILURE)

  Jul 15 05:03:21 gnubee-n1.gnubee systemd[1]: Starting Security Auditing Service...
  Jul 15 05:03:21 gnubee-n1.gnubee systemd[1]: auditd.service: Control process exited, code=exited, status=1/FAILURE
  Jul 15 05:03:21 gnubee-n1.gnubee systemd[1]: auditd.service: Failed with result 'exit-code'.
  Jul 15 05:03:21 gnubee-n1.gnubee systemd[1]: Failed to start Security Auditing Service.

  $ auditctl -a exit,always -F uid="$(id -u sshd)"
  Error - audit support not in kernel
  Cannot open netlink audit socket

Looks like I might be missing some kernel features. Perhaps sandboxing in
openssh also relies on something that's not compiled in either? Is there an
easy way to check?

By the way, this machine is sadly not using a Debian kernel. It's using
librecmc-ramips-mt7621-gb-pc1-squashfs-sysupgrade_2017-11-28.bin from
https://github.com/gnubee-git/gnubee-git.github.io/blob/master/debian/.

  $ uname -a
  Linux gnubee-n1.gnubee 4.4.87-gnu #0 SMP Wed Nov 22 13:06:13 2017 mips GNU/Linux

Francois

#932089#20
Date:
2019-07-15 09:33:26 UTC
From:
To:
audit was something that would have made this easier to debug, but isn't
required for normal functionality.

Now that you mention it, though, I do see this in your log:

  debug1: ssh_sandbox_child: prctl(PR_SET_SECCOMP): Invalid argument [preauth]

... which suggests that CONFIG_SECCOMP or CONFIG_SECCOMP_FILTER may be
disabled in your kernel.

However, openssh should just fall back to not using seccomp sandboxing
in that case.  It should make it easier to debug though!  Perhaps you
could run sshd under strace and we might be able to see where it goes
wrong there?  (Be careful with the strace output, as it will contain
secrets such as the private host key.)

I hope that the source for this is available somewhere and that it isn't
just a GPL violation?  I couldn't easily find the source.

#932089#25
Date:
2019-07-15 19:15:48 UTC
From:
To:
I ran the following to get an strace from the point where I try to connect
from the client:

$ /usr/sbin/sshd
$ pgrep sshd
7816

$ strace -p 7816
strace: Process 7816 attached
_newselect(5, [3 4], NULL, NULL, NULL)  = 1 (in [3])
accept(3, {sa_family=AF_INET, sin_port=htons(33142), sin_addr=inet_addr("192.168.1.5")}, [128->16]) = 5
fcntl64(5, F_GETFL)                     = 0x2 (flags O_RDWR)
pipe([6, 7])                            = 6
socketpair(AF_UNIX, SOCK_STREAM, 0, [8, 9]) = 0
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x765d2078) = 7821
close(7)                                = 0
write(8, "\0\0\1\v\0", 5)               = 5
write(8, "\0\0\1\6\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n"..., 266) = 266
close(8)                                = 0
close(9)                                = 0
close(5)                                = 0
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
clock_gettime(CLOCK_BOOTTIME, {tv_sec=437223, tv_nsec=281923987}) = 0
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
getpid()                                = 7816
clock_gettime(CLOCK_BOOTTIME, {tv_sec=437223, tv_nsec=283146422}) = 0
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
clock_gettime(CLOCK_BOOTTIME, {tv_sec=437223, tv_nsec=284680271}) = 0
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
time(NULL)                              = 1563216707 (2019-07-15T18:51:47+0000)
_newselect(7, [3 4 6], NULL, NULL, NULL) = 1 (in [6])
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=7821, si_uid=0, si_status=255, si_utime=23, si_stime=3} ---
waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 255}], WNOHANG) = 7821
waitpid(-1, 0x7fac9920, WNOHANG)        = -1 ECHILD (No child processes)
sigreturn({mask=[]})                    = 1
close(6)                                = 0
_newselect(7, [3 4], NULL, NULL, NULLstrace: Process 7816 detached
 <detached ...>

Let me know if you need a full strace from the start of the sshd process.

I wasn't able to find it either, I filed
https://github.com/gnubee-git/gnubee-git.github.io/issues/4.

Francois

#932089#30
Date:
2019-10-21 10:27:13 UTC
From:
To:
Dear all,

we're experiencing exactly the same issues with OpenSSH in
Debian/Buster on mips: our access points run Debian on top of an
OpenWRT kernel (built via DebWRT scripts). Find attached our kernel
config (which also does not provide AUDIT features).

Funny thing is, we're able to authenticate via RSA key but not with
ed25519 key. Most of the time the first connection attempt fails where
subsequent authentications work. The disconnect itself seems to happen
while loading pam config files. On successful authentications, we do get
pam debug messages, but not on failures.

We'd be glad to help with debugging this nasty issue.

best regards,
	Adi Kriegisch