OpenWrt/LEDE Project

  • Status Unconfirmed
  • Percent Complete
    0%
  • Task Type Bug Report
  • Category Base system
  • Assigned To No-one
  • Operating System All
  • Severity Low
  • Priority Very Low
  • Reported Version Trunk
  • Due in Version Undecided
  • Due Date Undecided
  • Private
Attached to Project: OpenWrt/LEDE Project
Opened by dwmw2 - 22.06.2020

FS#3199 - Outbound SSH failure with dropbear from lantiq (BT HH5a).

About 4 times out of 5 I cannot establish an outbound SSH connection with dropbear.

# ssh zeniv.linux.org.uk

ssh: Connection to root@zeniv.linux.org.uk:22 exited: Bad buf_getbyte

Precisely the same binary running on my wndr3800 works OK.

dwmw2 commented on 22.06.2020 15:34

sshd debug from a failing connection:

Connection from 2001:8b0:10b:1::1234 port 43720 on 2001:8b0:10b:1:21e:67ff:fecb:7a92 port 2222 rdomain ""
debug1: Local version string SSH-2.0-OpenSSH_8.3
debug1: Remote protocol version 2.0, remote software version dropbear
debug1: no match: dropbear
debug2: fd 3 setting O_NONBLOCK
debug3: ssh_sandbox_init: preparing seccomp filter sandbox
debug2: Network child is on pid 4139069
debug3: preauth child monitor started
debug1: SELinux support enabled [preauth]
debug1: ssh_selinux_change_context: setting context from 'unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023' to 'unconfined_u:unconfined_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
debug3: ssh_selinux_change_context: setcon unconfined_u:unconfined_r:sshd_net_t:s0-s0:c0.c1023 from unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 failed with Invalid argument [preauth]
debug3: privsep user:group 74:484 [preauth]
debug1: permanently_set_uid: 74/484 [preauth]
debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth]
debug3: ssh_sandbox_child: attaching seccomp filter program [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-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256 [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-64@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-64@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,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,kexguess2@matt.ucc.asn.au [preauth]
debug2: host key algorithms: ssh-rsa [preauth]
debug2: ciphers ctos: aes128-ctr,aes256-ctr [preauth]
debug2: ciphers stoc: aes128-ctr,aes256-ctr [preauth]
debug2: MACs ctos: hmac-sha1,hmac-sha2-256 [preauth]
debug2: MACs stoc: hmac-sha1,hmac-sha2-256 [preauth]
debug2: compression ctos: none [preauth]
debug2: compression stoc: none [preauth]
debug2: languages ctos:  [preauth]
debug2: languages stoc:  [preauth]
debug2: first_kex_follows 1  [preauth]
debug2: reserved 0  [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ssh-rsa [preauth]
debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha1 compression: none [preauth]
debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha1 compression: none [preauth]
debug1: kex: curve25519-sha256 need=20 dh_need=20 [preauth]
debug3: mm_request_send entering: type 120 [preauth]
debug3: mm_request_receive_expect entering: type 121 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 120
debug3: mm_request_send entering: type 121
debug1: kex: curve25519-sha256 need=20 dh_need=20 [preauth]
debug3: mm_request_send entering: type 120 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 120
debug3: mm_request_send entering: type 121
debug3: mm_request_receive_expect entering: type 121 [preauth]
debug3: mm_request_receive entering [preauth]
debug2: proposal mismatch: my rsa-sha2-512 peer ssh-rsa [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug3: receive packet: type 30 [preauth]
debug2: skipped packet (type 30) [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: KEX signature 0x561f6b4ce8a0(271)
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 out after 4294967296 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug3: receive packet: type 21 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: rekey in after 4294967296 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_depth: config reprocess config len 711
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]
debug3: mm_inform_authrole entering [preauth]
debug3: mm_request_send entering: type 80 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: user_specific_delay: user specific delay 0.000ms [preauth]
debug3: ensure_minimum_time_since: elapsed 2.292ms, delaying 2.993ms (requested 5.285ms) [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 100
debug1: PAM: initializing for "root"
debug1: PAM: setting PAM_RHOST to "2001:8b0:10b:1::1234"
debug1: PAM: setting PAM_TTY to "ssh"
debug2: monitor_read: 100 used once, disabling now
debug3: userauth_finish: failure partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password" [preauth]
debug3: send packet: type 51 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 80
debug3: mm_answer_authrole: role=
debug2: monitor_read: 80 used once, disabling now
debug3: mm_request_send entering: type 122 [preauth]
debug3: mm_request_receive_expect entering: type 123 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 122
debug3: mm_request_send entering: type 123
Connection closed by authenticating user root 2001:8b0:10b:1::1234 port 43720 [preauth]
debug1: do_cleanup [preauth]
debug3: PAM: sshpam_thread_cleanup entering [preauth]
debug3: mm_request_send entering: type 124 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 124
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 4139069
dwmw2 commented on 22.06.2020 15:35

ssh debug from a working connection:

Connection from 2001:8b0:10b:1::1234 port 43718 on 2001:8b0:10b:1:21e:67ff:fecb:7a92 port 2222 rdomain ""
debug1: Local version string SSH-2.0-OpenSSH_8.3
debug1: Remote protocol version 2.0, remote software version dropbear
debug1: no match: dropbear
debug2: fd 3 setting O_NONBLOCK
debug3: ssh_sandbox_init: preparing seccomp filter sandbox
debug2: Network child is on pid 4139017
debug3: preauth child monitor started
debug1: SELinux support enabled [preauth]
debug1: ssh_selinux_change_context: setting context from 'unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023' to 'unconfined_u:unconfined_r:sshd_net_t:s0-s0:c0.c1023' [preauth]
debug3: ssh_selinux_change_context: setcon unconfined_u:unconfined_r:sshd_net_t:s0-s0:c0.c1023 from unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 failed with Invalid argument [preauth]
debug3: privsep user:group 74:484 [preauth]
debug1: permanently_set_uid: 74/484 [preauth]
debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth]
debug3: ssh_sandbox_child: attaching seccomp filter program [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-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256 [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-64@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-64@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,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,kexguess2@matt.ucc.asn.au [preauth]
debug2: host key algorithms: ssh-rsa [preauth]
debug2: ciphers ctos: aes128-ctr,aes256-ctr [preauth]
debug2: ciphers stoc: aes128-ctr,aes256-ctr [preauth]
debug2: MACs ctos: hmac-sha1,hmac-sha2-256 [preauth]
debug2: MACs stoc: hmac-sha1,hmac-sha2-256 [preauth]
debug2: compression ctos: none [preauth]
debug2: compression stoc: none [preauth]
debug2: languages ctos:  [preauth]
debug2: languages stoc:  [preauth]
debug2: first_kex_follows 1  [preauth]
debug2: reserved 0  [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ssh-rsa [preauth]
debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha1 compression: none [preauth]
debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha1 compression: none [preauth]
debug1: kex: curve25519-sha256 need=20 dh_need=20 [preauth]
debug3: mm_request_send entering: type 120 [preauth]
debug3: mm_request_receive_expect entering: type 121 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 120
debug3: mm_request_send entering: type 121
debug1: kex: curve25519-sha256 need=20 dh_need=20 [preauth]
debug3: mm_request_send entering: type 120 [preauth]
debug3: mm_request_receive_expect entering: type 121 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 120
debug3: mm_request_send entering: type 121
debug2: proposal mismatch: my rsa-sha2-512 peer ssh-rsa [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug3: receive packet: type 30 [preauth]
debug2: skipped packet (type 30) [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: KEX signature 0x5641d84a3ba0(271)
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 out after 4294967296 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug3: receive packet: type 21 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: rekey in after 4294967296 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_depth: config reprocess config len 711
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]
debug3: mm_inform_authrole entering [preauth]
debug3: mm_request_send entering: type 80 [preauth]
debug2: input_userauth_request: try method none [preauth]
debug3: user_specific_delay: user specific delay 0.000ms [preauth]
debug3: ensure_minimum_time_since: elapsed 1.783ms, delaying 3.502ms (requested 5.285ms) [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 100
debug1: PAM: initializing for "root"
debug1: PAM: setting PAM_RHOST to "2001:8b0:10b:1::1234"
debug1: PAM: setting PAM_TTY to "ssh"
debug2: monitor_read: 100 used once, disabling now
debug3: userauth_finish: failure partial=0 next methods="publickey,gssapi-keyex,gssapi-with-mic,password" [preauth]
debug3: send packet: type 51 [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 4
debug3: mm_answer_authserv: service=ssh-connection, style=
debug2: monitor_read: 4 used once, disabling now
debug3: mm_request_receive entering
debug3: monitor_read: checking request 80
debug3: mm_answer_authrole: role=
debug2: monitor_read: 80 used once, disabling now

... at this point, the client asks for password ...

debug3: receive packet: type 50 [preauth]
debug1: userauth-request for user root service ssh-connection method password [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method password [preauth]
debug3: mm_auth_password entering [preauth]
debug3: mm_request_send entering: type 12 [preauth]
debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
debug3: mm_request_receive_expect entering: type 13 [preauth]
debug3: mm_request_receive entering [preauth]
debug3: mm_request_receive entering
debug3: monitor_read: checking request 12
debug3: PAM: sshpam_passwd_conv called with 1 messages
debug1: PAM: password authentication accepted for root
debug3: mm_answer_authpassword: sending result 1
debug3: mm_request_send entering: type 13
debug3: mm_request_receive_expect entering: type 102
debug3: mm_request_receive entering
debug1: do_pam_account: called
debug2: do_pam_account: auth information in SSH_AUTH_INFO_0
debug3: PAM: do_pam_account pam_acct_mgmt = 0 (Success)
debug3: mm_request_send entering: type 103
Accepted password for root from 2001:8b0:10b:1::1234 port 43718 ssh2

dwmw2 commented on 22.06.2020 15:38

This is dropbear 2019.78 on OpenWrt 19.07. I don't recall it happening in 18.06.

Loading...

Available keyboard shortcuts

Tasklist

Task Details

Task Editing