mkj / dropbear

Dropbear SSH
https://matt.ucc.asn.au/dropbear/dropbear.html
Other
1.71k stars 404 forks source link

OpenSSH Client(but not dbclient) connection times out #292

Closed jameshilliard closed 5 months ago

jameshilliard commented 6 months ago

I'm seeing a connection timeout when trying to connect to dropbear server but only when using the openssh client and not dbclient. It also only seems to happen on some networks for unclear reasons.

Trace with OpenSSH Client that times out:

# /usr/sbin/dropbear -F -R -vvvvv
TRACE5 (1016) 0.000000: enter sign_key_free
TRACE5 (1016) 0.000091: enter rsa_key_free
TRACE5 (1016) 0.000110: leave rsa_key_free: key == NULL
TRACE5 (1016) 0.000133: enter ed25519_key_free
TRACE5 (1016) 0.000150: leave ed25519_key_free: key == NULL
TRACE5 (1016) 0.000169: leave sign_key_free
TRACE4 (1016) 0.000191: leave loadhostkey
TRACE5 (1016) 0.000221: enter sign_key_free
TRACE5 (1016) 0.000246: enter rsa_key_free
TRACE5 (1016) 0.000268: leave rsa_key_free: key == NULL
TRACE5 (1016) 0.000289: enter ed25519_key_free
TRACE5 (1016) 0.000304: leave ed25519_key_free: key == NULL
TRACE5 (1016) 0.000326: leave sign_key_free
TRACE4 (1016) 0.000349: leave loadhostkey
TRACE5 (1016) 0.000416: enter buf_get_priv_key
TRACE5 (1016) 0.000443: enter ed25519_key_free
TRACE5 (1016) 0.000460: leave ed25519_key_free: key == NULL
TRACE4 (1016) 0.000487: enter buf_get_ed25519_priv_key
TRACE4 (1016) 0.000506: leave buf_get_ed25519_priv_key: success
TRACE5 (1016) 0.000528: leave buf_get_priv_key
TRACE5 (1016) 0.000552: enter sign_key_free
TRACE5 (1016) 0.000574: enter rsa_key_free
TRACE5 (1016) 0.000600: leave rsa_key_free: key == NULL
TRACE5 (1016) 0.000618: enter ed25519_key_free
TRACE5 (1016) 0.000643: leave ed25519_key_free: key == NULL
TRACE5 (1016) 0.000669: leave sign_key_free
TRACE4 (1016) 0.000695: leave loadhostkey
TRACE4 (1016) 0.000713: Disabling key type 2
TRACE4 (1016) 0.000741: Disabling key type 3
TRACE4 (1016) 0.000767: Disabling key type 4
TRACE4 (1016) 0.000796: Disabling key type 6
TRACE4 (1016) 0.000817: listensockets: 1 to try
TRACE4 (1016) 0.000847: listening on ':22'
TRACE4 (1016) 0.000866: enter dropbear_listen
TRACE4 (1016) 0.000892: dropbear_listen: all interfaces
TRACE4 (1016) 0.001381: leave dropbear_listen: success, 2 socks bound
TRACE4 (1016) 0.001424: Couldn't set IPV6_TCLASS (Protocol not available)
[1016] Apr 08 22:26:58 Not backgrounding
[1017] Apr 08 22:26:59 Child connection from 10.169.0.1:40014
TRACE5 (1017) 0.000000: enter sign_key_free
TRACE5 (1017) 0.000066: enter rsa_key_free
TRACE5 (1017) 0.000083: leave rsa_key_free: key == NULL
TRACE5 (1017) 0.000112: enter ed25519_key_free
TRACE5 (1017) 0.000133: leave ed25519_key_free: key == NULL
TRACE5 (1017) 0.000152: leave sign_key_free
TRACE4 (1017) 0.000171: leave loadhostkey
TRACE5 (1017) 0.000204: enter sign_key_free
TRACE5 (1017) 0.000225: enter rsa_key_free
TRACE5 (1017) 0.000248: leave rsa_key_free: key == NULL
TRACE5 (1017) 0.000270: enter ed25519_key_free
TRACE5 (1017) 0.000294: leave ed25519_key_free: key == NULL
TRACE5 (1017) 0.000312: leave sign_key_free
TRACE4 (1017) 0.000332: leave loadhostkey
TRACE5 (1017) 0.000393: enter buf_get_priv_key
TRACE5 (1017) 0.000424: enter ed25519_key_free
TRACE5 (1017) 0.000449: leave ed25519_key_free: key == NULL
TRACE4 (1017) 0.000477: enter buf_get_ed25519_priv_key
TRACE4 (1017) 0.000506: leave buf_get_ed25519_priv_key: success
TRACE5 (1017) 0.000529: leave buf_get_priv_key
TRACE5 (1017) 0.000551: enter sign_key_free
TRACE5 (1017) 0.000589: enter rsa_key_free
TRACE5 (1017) 0.000611: leave rsa_key_free: key == NULL
TRACE5 (1017) 0.000624: enter ed25519_key_free
TRACE5 (1017) 0.000643: leave ed25519_key_free: key == NULL
TRACE5 (1017) 0.000665: leave sign_key_free
TRACE4 (1017) 0.000681: leave loadhostkey
TRACE4 (1017) 0.000699: Disabling key type 2
TRACE4 (1017) 0.000726: Disabling key type 3
TRACE4 (1017) 0.000744: Disabling key type 4
TRACE4 (1017) 0.000768: Disabling key type 6
TRACE4 (1017) 0.002975: enter session_init
TRACE4 (1017) 0.003000: setnonblocking: 0
TRACE4 (1017) 0.003020: leave setnonblocking
TRACE4 (1017) 0.003047: setnonblocking: 0
TRACE4 (1017) 0.003082: leave setnonblocking
TRACE4 (1017) 0.003100: update_channel_prio
TRACE4 (1017) 0.003127: update_channel_prio: not any
TRACE4 (1017) 0.003153: Dropbear priority transitioning 0 -> 1
TRACE4 (1017) 0.003189: Couldn't set IPV6_TCLASS (Protocol not available)
TRACE4 (1017) 0.003235: setnonblocking: 3
TRACE4 (1017) 0.003261: leave setnonblocking
TRACE4 (1017) 0.003276: setnonblocking: 4
TRACE4 (1017) 0.003291: leave setnonblocking
TRACE4 (1017) 0.003346: leave session_init
TRACE4 (1017) 0.003412: kexinitialise()
TRACE4 (1017) 0.003443: algolist add 216 'curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,kexguess2@matt.ucc.asn.au,kex-strict-s-v00@openssh.com'
TRACE4 (1017) 0.003476: algolist add 52 'ssh-ed25519,ecdsa-sha2-nistp256,rsa-sha2-256,ssh-rsa'
TRACE4 (1017) 0.003506: algolist add 51 'chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr'
TRACE4 (1017) 0.003532: algolist add 51 'chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr'
TRACE4 (1017) 0.003576: algolist add 23 'hmac-sha1,hmac-sha2-256'
TRACE4 (1017) 0.003604: algolist add 23 'hmac-sha1,hmac-sha2-256'
TRACE4 (1017) 0.003625: algolist add 4 'none'
TRACE4 (1017) 0.003659: algolist add 4 'none'
TRACE5 (1017) 0.003691: enter encrypt_packet()
TRACE5 (1017) 0.003719: encrypt_packet type is 20
TRACE5 (1017) 0.003749: leave writemac
TRACE5 (1017) 0.003780: leave encrypt_packet()
TRACE4 (1017) 0.003807: DATAALLOWED=0
TRACE4 (1017) 0.003837: -> KEXINIT
TRACE5 (1017) 0.003864: update_timeout limit 300, now 1826, last 1826, timeout 28800
TRACE5 (1017) 0.003895: new timeout 300
TRACE5 (1017) 0.003923: update_timeout limit 0, now 1826, last 1826, timeout 300
TRACE4 (1017) 0.003956: maybe_empty_reply_queue - no data allowed
TRACE5 (1017) 0.003988: enter write_packet
TRACE5 (1017) 0.004013: write_packet writev #0 len 26/26
TRACE5 (1017) 0.004039: write_packet writev #1 len 496/496
TRACE4 (1017) 0.004113: empty queue dequeing
TRACE5 (1017) 0.004147: leave write_packet
TRACE5 (1017) 0.004171: update_timeout limit 300, now 1826, last 1826, timeout 28800
TRACE5 (1017) 0.004199: new timeout 300
TRACE5 (1017) 0.004227: update_timeout limit 0, now 1826, last 1826, timeout 300
TRACE4 (1017) 0.004256: enter ident_readln
TRACE4 (1017) 0.004547: leave ident_readln: return 40
TRACE1 (1017) 0.004601: remoteident: SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
TRACE4 (1017) 0.004627: maybe_empty_reply_queue - no data allowed
TRACE5 (1017) 0.004654: update_timeout limit 300, now 1826, last 1826, timeout 28800
TRACE5 (1017) 0.004680: new timeout 300
TRACE5 (1017) 0.004711: update_timeout limit 0, now 1826, last 1826, timeout 300
[1017] Apr 08 22:31:59 Exit before auth from <10.169.0.1:40014>: Timeout before auth
TRACE4 (1017) 300.081190: enter session_cleanup
TRACE4 (1017) 300.081236: enter chancleanup
TRACE4 (1017) 300.081263: leave chancleanup
TRACE4 (1017) 300.081323: leave session_cleanup
TRACE5 (1017) 300.081378: enter sign_key_free
TRACE5 (1017) 300.081407: enter rsa_key_free
TRACE5 (1017) 300.081427: leave rsa_key_free: key == NULL
TRACE5 (1017) 300.081448: enter ed25519_key_free
TRACE5 (1017) 300.081471: leave ed25519_key_free
TRACE5 (1017) 300.081496: leave sign_key_free
^C[1016] Apr 08 22:42:22 Early exit: Terminated by signal
TRACE4 (1016) 924.104510: enter session_cleanup
TRACE4 (1016) 924.104533: leave session_cleanup: !ses.init_done
TRACE5 (1016) 924.104569: enter sign_key_free
TRACE5 (1016) 924.104593: enter rsa_key_free
TRACE5 (1016) 924.104619: leave rsa_key_free: key == NULL
TRACE5 (1016) 924.104654: enter ed25519_key_free
TRACE5 (1016) 924.104682: leave ed25519_key_free
TRACE5 (1016) 924.104711: leave sign_key_free

The associated OpenSSH client connection log which times out:

# ssh -vvvvvv root@10.169.5.126
OpenSSH_8.9p1 Ubuntu-3ubuntu0.6, OpenSSL 3.0.2 15 Mar 2022
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: include /etc/ssh/ssh_config.d/*.conf matched no files
debug1: /etc/ssh/ssh_config line 21: Applying options for *
debug2: resolve_canonicalize: hostname 10.169.5.126 is address
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/root/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/root/.ssh/known_hosts2'
debug3: ssh_connect_direct: entering
debug1: Connecting to 10.169.5.126 [10.169.5.126] port 22.
debug3: set_sock_tos: set socket 3 IP_TOS 0x10
debug1: Connection established.
debug1: identity file /root/.ssh/id_rsa type -1
debug1: identity file /root/.ssh/id_rsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa type -1
debug1: identity file /root/.ssh/id_ecdsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa_sk type -1
debug1: identity file /root/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /root/.ssh/id_ed25519 type -1
debug1: identity file /root/.ssh/id_ed25519-cert type -1
debug1: identity file /root/.ssh/id_ed25519_sk type -1
debug1: identity file /root/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /root/.ssh/id_xmss type -1
debug1: identity file /root/.ssh/id_xmss-cert type -1
debug1: identity file /root/.ssh/id_dsa type -1
debug1: identity file /root/.ssh/id_dsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
debug1: Remote protocol version 2.0, remote software version dropbear_2024.84
debug1: compat_banner: no match: dropbear_2024.84
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 10.169.5.126:22 as 'root'
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug3: order_hostkeyalgs: no algorithms matched; accept original
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,sntrup761x25519-sha512@openssh.com,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c,kex-strict-c-v00@openssh.com
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
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-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,kexguess2@matt.ucc.asn.au,kex-strict-s-v00@openssh.com
debug2: host key algorithms: ssh-ed25519,ecdsa-sha2-nistp256,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr
debug2: MACs ctos: hmac-sha1,hmac-sha2-256
debug2: MACs stoc: hmac-sha1,hmac-sha2-256
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug3: kex_choose_conf: will use strict KEX ordering
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
Connection closed by 10.169.5.126 port 22

Working log with dbclient:

# /usr/sbin/dropbear -F -R -vvvvv
TRACE5 (1133) 0.000000: enter sign_key_free
TRACE5 (1133) 0.000065: enter rsa_key_free
TRACE5 (1133) 0.000085: leave rsa_key_free: key == NULL
TRACE5 (1133) 0.000114: enter ed25519_key_free
TRACE5 (1133) 0.000131: leave ed25519_key_free: key == NULL
TRACE5 (1133) 0.000161: leave sign_key_free
TRACE4 (1133) 0.000181: leave loadhostkey
TRACE5 (1133) 0.000210: enter sign_key_free
TRACE5 (1133) 0.000237: enter rsa_key_free
TRACE5 (1133) 0.000252: leave rsa_key_free: key == NULL
TRACE5 (1133) 0.000267: enter ed25519_key_free
TRACE5 (1133) 0.000291: leave ed25519_key_free: key == NULL
TRACE5 (1133) 0.000314: leave sign_key_free
TRACE4 (1133) 0.000333: leave loadhostkey
TRACE5 (1133) 0.000395: enter buf_get_priv_key
TRACE5 (1133) 0.000421: enter ed25519_key_free
TRACE5 (1133) 0.000437: leave ed25519_key_free: key == NULL
TRACE4 (1133) 0.000453: enter buf_get_ed25519_priv_key
TRACE4 (1133) 0.000480: leave buf_get_ed25519_priv_key: success
TRACE5 (1133) 0.000505: leave buf_get_priv_key
TRACE5 (1133) 0.000536: enter sign_key_free
TRACE5 (1133) 0.000574: enter rsa_key_free
TRACE5 (1133) 0.000597: leave rsa_key_free: key == NULL
TRACE5 (1133) 0.000619: enter ed25519_key_free
TRACE5 (1133) 0.000636: leave ed25519_key_free: key == NULL
TRACE5 (1133) 0.000661: leave sign_key_free
TRACE4 (1133) 0.000689: leave loadhostkey
TRACE4 (1133) 0.000707: Disabling key type 2
TRACE4 (1133) 0.000733: Disabling key type 3
TRACE4 (1133) 0.000756: Disabling key type 4
TRACE4 (1133) 0.000778: Disabling key type 6
TRACE4 (1133) 0.000806: listensockets: 1 to try
TRACE4 (1133) 0.000828: listening on ':22'
TRACE4 (1133) 0.000857: enter dropbear_listen
TRACE4 (1133) 0.000881: dropbear_listen: all interfaces
TRACE4 (1133) 0.001385: leave dropbear_listen: success, 2 socks bound
TRACE4 (1133) 0.001429: Couldn't set IPV6_TCLASS (Protocol not available)
[1133] Apr 08 22:42:53 Not backgrounding
[1137] Apr 08 22:43:45 Child connection from 10.169.0.1:36220
TRACE5 (1137) 0.000000: enter sign_key_free
TRACE5 (1137) 0.000061: enter rsa_key_free
TRACE5 (1137) 0.000080: leave rsa_key_free: key == NULL
TRACE5 (1137) 0.000102: enter ed25519_key_free
TRACE5 (1137) 0.000123: leave ed25519_key_free: key == NULL
TRACE5 (1137) 0.000147: leave sign_key_free
TRACE4 (1137) 0.000167: leave loadhostkey
TRACE5 (1137) 0.000207: enter sign_key_free
TRACE5 (1137) 0.000232: enter rsa_key_free
TRACE5 (1137) 0.000253: leave rsa_key_free: key == NULL
TRACE5 (1137) 0.000276: enter ed25519_key_free
TRACE5 (1137) 0.000298: leave ed25519_key_free: key == NULL
TRACE5 (1137) 0.000322: leave sign_key_free
TRACE4 (1137) 0.000347: leave loadhostkey
TRACE5 (1137) 0.000398: enter buf_get_priv_key
TRACE5 (1137) 0.000427: enter ed25519_key_free
TRACE5 (1137) 0.000441: leave ed25519_key_free: key == NULL
TRACE4 (1137) 0.000476: enter buf_get_ed25519_priv_key
TRACE4 (1137) 0.000504: leave buf_get_ed25519_priv_key: success
TRACE5 (1137) 0.000531: leave buf_get_priv_key
TRACE5 (1137) 0.000556: enter sign_key_free
TRACE5 (1137) 0.000582: enter rsa_key_free
TRACE5 (1137) 0.000606: leave rsa_key_free: key == NULL
TRACE5 (1137) 0.000628: enter ed25519_key_free
TRACE5 (1137) 0.000657: leave ed25519_key_free: key == NULL
TRACE5 (1137) 0.000684: leave sign_key_free
TRACE4 (1137) 0.000706: leave loadhostkey
TRACE4 (1137) 0.000731: Disabling key type 2
TRACE4 (1137) 0.000757: Disabling key type 3
TRACE4 (1137) 0.000786: Disabling key type 4
TRACE4 (1137) 0.000947: Disabling key type 6
TRACE4 (1137) 0.003515: enter session_init
TRACE4 (1137) 0.003541: setnonblocking: 0
TRACE4 (1137) 0.003564: leave setnonblocking
TRACE4 (1137) 0.003590: setnonblocking: 0
TRACE4 (1137) 0.003618: leave setnonblocking
TRACE4 (1137) 0.003645: update_channel_prio
TRACE4 (1137) 0.003673: update_channel_prio: not any
TRACE4 (1137) 0.003696: Dropbear priority transitioning 0 -> 1
TRACE4 (1137) 0.003733: Couldn't set IPV6_TCLASS (Protocol not available)
TRACE4 (1137) 0.003787: setnonblocking: 3
TRACE4 (1137) 0.003835: leave setnonblocking
TRACE4 (1137) 0.003861: setnonblocking: 4
TRACE4 (1137) 0.003889: leave setnonblocking
TRACE4 (1137) 0.003948: leave session_init
TRACE4 (1137) 0.004013: kexinitialise()
TRACE4 (1137) 0.004049: algolist add 216 'curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,kexguess2@matt.ucc.asn.au,kex-strict-s-v00@openssh.com'
TRACE4 (1137) 0.004090: algolist add 52 'ssh-ed25519,ecdsa-sha2-nistp256,rsa-sha2-256,ssh-rsa'
TRACE4 (1137) 0.004114: algolist add 51 'chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr'
TRACE4 (1137) 0.004141: algolist add 51 'chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr'
TRACE4 (1137) 0.004165: algolist add 23 'hmac-sha1,hmac-sha2-256'
TRACE4 (1137) 0.004196: algolist add 23 'hmac-sha1,hmac-sha2-256'
TRACE4 (1137) 0.004227: algolist add 4 'none'
TRACE4 (1137) 0.004257: algolist add 4 'none'
TRACE5 (1137) 0.004285: enter encrypt_packet()
TRACE5 (1137) 0.004363: encrypt_packet type is 20
TRACE5 (1137) 0.004397: leave writemac
TRACE5 (1137) 0.004425: leave encrypt_packet()
TRACE4 (1137) 0.004450: DATAALLOWED=0
TRACE4 (1137) 0.004475: -> KEXINIT
TRACE5 (1137) 0.004496: update_timeout limit 300, now 2831, last 2831, timeout 28800
TRACE5 (1137) 0.004525: new timeout 300
TRACE5 (1137) 0.004553: update_timeout limit 0, now 2831, last 2831, timeout 300
TRACE4 (1137) 0.004595: maybe_empty_reply_queue - no data allowed
TRACE5 (1137) 0.004627: enter write_packet
TRACE5 (1137) 0.004648: write_packet writev #0 len 26/26
TRACE5 (1137) 0.004678: write_packet writev #1 len 496/496
TRACE4 (1137) 0.004751: empty queue dequeing
TRACE5 (1137) 0.004835: leave write_packet
TRACE5 (1137) 0.004868: update_timeout limit 300, now 2831, last 2831, timeout 28800
TRACE5 (1137) 0.004893: new timeout 300
TRACE5 (1137) 0.004915: update_timeout limit 0, now 2831, last 2831, timeout 300
TRACE4 (1137) 0.004949: enter ident_readln
TRACE4 (1137) 0.005146: leave ident_readln: return 25
TRACE1 (1137) 0.005182: remoteident: SSH-2.0-dropbear_2020.81
TRACE4 (1137) 0.005208: maybe_empty_reply_queue - no data allowed
TRACE5 (1137) 0.005234: update_timeout limit 300, now 2831, last 2831, timeout 28800
TRACE5 (1137) 0.005344: new timeout 300
TRACE5 (1137) 0.005367: update_timeout limit 0, now 2831, last 2831, timeout 300
TRACE5 (1137) 0.005398: enter read_packet
TRACE5 (1137) 0.005436: packet size is 600, block 8 mac 0
TRACE5 (1137) 0.005473: enter decrypt_packet
TRACE5 (1137) 0.005500: leave writemac
TRACE5 (1137) 0.005527: leave decrypt_packet
TRACE5 (1137) 0.005550: leave read_packet
TRACE5 (1137) 0.005574: enter process_packet
TRACE4 (1137) 0.005597: process_packet: packet type = 20,  len 592
TRACE4 (1137) 0.005618: got expected packet 20 during kexinit
TRACE4 (1137) 0.005643: <- KEXINIT
TRACE4 (1137) 0.005666: enter recv_msg_kexinit
TRACE3 (1137) 0.005706: buf_match_algo: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,kexguess2@matt.ucc.asn.au,ext-info-c
TRACE4 (1137) 0.005753: kexguess2 1
TRACE3 (1137) 0.005778: kex algo curve25519-sha256
TRACE3 (1137) 0.005822: buf_match_algo: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-256,ssh-rsa,ssh-dss
TRACE2 (1137) 0.005857: hostkey algo ssh-ed25519
TRACE3 (1137) 0.005882: buf_match_algo: chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr
TRACE2 (1137) 0.005919: enc  c2s is chacha20-poly1305@openssh.com
TRACE3 (1137) 0.005999: buf_match_algo: chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr
TRACE2 (1137) 0.006032: enc  s2c is chacha20-poly1305@openssh.com
TRACE3 (1137) 0.006061: buf_match_algo: hmac-sha1,hmac-sha2-256
TRACE2 (1137) 0.006092: hmac c2s is <implicit>
TRACE3 (1137) 0.006117: buf_match_algo: hmac-sha1,hmac-sha2-256
TRACE2 (1137) 0.006139: hmac s2c is <implicit>
TRACE3 (1137) 0.006166: buf_match_algo: zlib@openssh.com,zlib,none
TRACE2 (1137) 0.006191: comp c2s is none
TRACE3 (1137) 0.006216: buf_match_algo: zlib@openssh.com,zlib,none
TRACE2 (1137) 0.006246: comp s2c is none
TRACE4 (1137) 0.006274: them kex firstfollows. allgood 1
TRACE4 (1137) 0.006304: leave recv_msg_kexinit
TRACE5 (1137) 0.006326: leave process_packet
TRACE4 (1137) 0.006355: maybe_empty_reply_queue - no data allowed
TRACE5 (1137) 0.006386: update_timeout limit 300, now 2831, last 2831, timeout 28800
TRACE5 (1137) 0.006415: new timeout 300
TRACE5 (1137) 0.006441: update_timeout limit 0, now 2831, last 2831, timeout 300
TRACE5 (1137) 0.006478: enter read_packet
TRACE5 (1137) 0.006519: packet size is 48, block 8 mac 0
TRACE5 (1137) 0.006556: enter decrypt_packet
TRACE5 (1137) 0.006582: leave writemac
TRACE5 (1137) 0.006605: leave decrypt_packet
TRACE5 (1137) 0.006629: leave read_packet
TRACE5 (1137) 0.006701: enter process_packet
TRACE4 (1137) 0.006726: process_packet: packet type = 30,  len 42
TRACE4 (1137) 0.006749: got expected packet 30 during kexinit
TRACE4 (1137) 0.006780: enter recv_msg_kexdh_init
TRACE4 (1137) 0.006847: enter send_msg_kexdh_reply
TRACE5 (1137) 0.006871: enter buf_put_pub_key
TRACE4 (1137) 0.006900: enter buf_put_ed25519_pub_key
TRACE4 (1137) 0.006931: leave buf_put_ed25519_pub_key
TRACE5 (1137) 0.006961: leave buf_put_pub_key
TRACE5 (1137) 0.018104: enter buf_put_pub_key
TRACE4 (1137) 0.018135: enter buf_put_ed25519_pub_key
TRACE4 (1137) 0.018153: leave buf_put_ed25519_pub_key
TRACE5 (1137) 0.018181: leave buf_put_pub_key
TRACE5 (1137) 0.018201: enter buf_putmpint
TRACE5 (1137) 0.018240: leave buf_putmpint
TRACE4 (1137) 0.018308: buf_put_sign type 5 ssh-ed25519
TRACE4 (1137) 0.018332: enter buf_put_ed25519_sign
TRACE4 (1137) 0.027628: leave buf_put_ed25519_sign
TRACE5 (1137) 0.027654: enter encrypt_packet()
TRACE5 (1137) 0.027671: encrypt_packet type is 31
TRACE5 (1137) 0.027696: leave writemac
TRACE5 (1137) 0.027716: leave encrypt_packet()
TRACE4 (1137) 0.027742: leave send_msg_kexdh_reply
TRACE4 (1137) 0.027763: enter send_msg_newkeys
TRACE5 (1137) 0.027786: enter encrypt_packet()
TRACE5 (1137) 0.027829: encrypt_packet type is 21
TRACE5 (1137) 0.027859: leave writemac
TRACE5 (1137) 0.027885: leave encrypt_packet()
TRACE4 (1137) 0.027952: enter gen_new_keys
TRACE5 (1137) 0.027973: enter buf_putmpint
TRACE5 (1137) 0.027995: leave buf_putmpint
TRACE5 (1137) 0.028039: enter dropbear_chachapoly_start
TRACE5 (1137) 0.028059: leave dropbear_chachapoly_start
TRACE5 (1137) 0.028072: enter dropbear_chachapoly_start
TRACE5 (1137) 0.028089: leave dropbear_chachapoly_start
TRACE4 (1137) 0.028115: leave gen_new_keys
TRACE5 (1137) 0.028137: enter switch_keys
TRACE4 (1137) 0.028166: switch_keys trans
TRACE5 (1137) 0.028190: leave switch_keys
TRACE4 (1137) 0.028218: leave send_msg_newkeys
TRACE4 (1137) 0.028242: enter send_msg_ext_info
TRACE4 (1137) 0.028265: algolist add 154 'ssh-ed25519,sk-ssh-ed25519@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-256,ssh-rsa'
TRACE5 (1137) 0.028304: enter encrypt_packet()
TRACE5 (1137) 0.028333: encrypt_packet type is 7
TRACE5 (1137) 0.028366: enter dropbear_chachapoly_crypt
TRACE5 (1137) 0.028400: leave dropbear_chachapoly_crypt
TRACE5 (1137) 0.028422: leave encrypt_packet()
TRACE4 (1137) 0.028446: leave send_msg_ext_info
TRACE4 (1137) 0.028474: leave recv_msg_kexdh_init
TRACE5 (1137) 0.028500: leave process_packet
TRACE5 (1137) 0.028529: enter write_packet
TRACE5 (1137) 0.028628: write_packet writev #0 len 192/192
TRACE5 (1137) 0.028653: write_packet writev #1 len 16/16
TRACE5 (1137) 0.028684: write_packet writev #2 len 212/212
TRACE4 (1137) 0.028747: empty queue dequeing
TRACE5 (1137) 0.028832: leave write_packet
TRACE5 (1137) 0.028866: update_timeout limit 300, now 2831, last 2831, timeout 28800
TRACE5 (1137) 0.028900: new timeout 300
TRACE5 (1137) 0.028928: update_timeout limit 0, now 2831, last 2831, timeout 300
TRACE5 (1137) 3.619783: enter read_packet
TRACE5 (1137) 3.619888: packet size is 16, block 8 mac 0
TRACE5 (1137) 3.620054: enter decrypt_packet
TRACE5 (1137) 3.620096: leave writemac
TRACE5 (1137) 3.620128: leave decrypt_packet
TRACE5 (1137) 3.620162: leave read_packet
TRACE5 (1137) 3.620217: enter process_packet
TRACE4 (1137) 3.620240: process_packet: packet type = 21,  len 6
TRACE4 (1137) 3.620258: got expected packet 21 during kexinit
TRACE4 (1137) 3.620280: enter recv_msg_newkeys
TRACE5 (1137) 3.620307: enter switch_keys
TRACE4 (1137) 3.620333: switch_keys recv
TRACE4 (1137) 3.620360: switch_keys done
TRACE4 (1137) 3.620385: kexinitialise()
TRACE5 (1137) 3.620405: leave switch_keys
TRACE4 (1137) 3.620426: leave recv_msg_newkeys
TRACE5 (1137) 3.620449: leave process_packet
TRACE5 (1137) 3.620480: update_timeout limit 28800, now 2835, last 2835, timeout 28800
TRACE5 (1137) 3.620502: new timeout 28800
TRACE5 (1137) 3.620528: update_timeout limit 300, now 2835, last 2831, timeout 28800
TRACE5 (1137) 3.620556: new timeout 304
TRACE5 (1137) 3.620586: update_timeout limit 0, now 2835, last 2835, timeout 304
TRACE5 (1137) 3.620618: enter read_packet
TRACE5 (1137) 3.620649: enter dropbear_chachapoly_getlength
TRACE5 (1137) 3.620671: leave dropbear_chachapoly_getlength
TRACE5 (1137) 3.620695: packet size is 44, block 8 mac 16
TRACE5 (1137) 3.620726: enter decrypt_packet
TRACE5 (1137) 3.620753: enter dropbear_chachapoly_crypt
TRACE5 (1137) 3.620784: leave dropbear_chachapoly_crypt
TRACE5 (1137) 3.620826: leave decrypt_packet
TRACE5 (1137) 3.620852: leave read_packet
TRACE5 (1137) 3.620876: enter process_packet
TRACE4 (1137) 3.620905: process_packet: packet type = 5,  len 22
TRACE4 (1137) 3.620935: enter recv_msg_service_request
TRACE4 (1137) 3.620954: accepting service ssh-userauth
TRACE5 (1137) 3.620971: enter encrypt_packet()
TRACE5 (1137) 3.620986: encrypt_packet type is 6
TRACE5 (1137) 3.621019: enter dropbear_chachapoly_crypt
TRACE5 (1137) 3.621058: leave dropbear_chachapoly_crypt
TRACE5 (1137) 3.621080: leave encrypt_packet()
TRACE4 (1137) 3.621110: leave recv_msg_service_request: done ssh-userauth
TRACE5 (1137) 3.621139: leave process_packet
TRACE5 (1137) 3.621169: enter write_packet
TRACE5 (1137) 3.621196: write_packet writev #0 len 44/44
TRACE4 (1137) 3.621266: empty queue dequeing
TRACE5 (1137) 3.621299: leave write_packet
TRACE5 (1137) 3.621320: update_timeout limit 28800, now 2835, last 2835, timeout 28800
TRACE5 (1137) 3.621351: new timeout 28800
TRACE5 (1137) 3.621371: update_timeout limit 300, now 2835, last 2831, timeout 28800
TRACE5 (1137) 3.621395: new timeout 304
TRACE5 (1137) 3.621422: update_timeout limit 0, now 2835, last 2835, timeout 304
TRACE5 (1137) 3.621455: enter read_packet
TRACE5 (1137) 3.621488: enter dropbear_chachapoly_getlength
TRACE5 (1137) 3.621519: leave dropbear_chachapoly_getlength
TRACE5 (1137) 3.621548: packet size is 60, block 8 mac 16
TRACE5 (1137) 3.621582: enter decrypt_packet
TRACE5 (1137) 3.621613: enter dropbear_chachapoly_crypt
TRACE5 (1137) 3.621639: leave dropbear_chachapoly_crypt
TRACE5 (1137) 3.621664: leave decrypt_packet
TRACE5 (1137) 3.621702: leave read_packet
TRACE5 (1137) 3.621728: enter process_packet
TRACE4 (1137) 3.621756: process_packet: packet type = 50,  len 40
TRACE4 (1137) 3.621787: enter recv_msg_userauth_request
TRACE4 (1137) 3.621828: enter checkusername
TRACE4 (1137) 3.622271: shell is /bin/sh
TRACE4 (1137) 3.622347: test shell is '/bin/ash'
TRACE4 (1137) 3.622378: test shell is '/usr/bin/screen'
TRACE4 (1137) 3.622403: test shell is '/bin/sh'
TRACE4 (1137) 3.622432: matching shell
TRACE4 (1137) 3.622460: uid = 0
TRACE4 (1137) 3.622484: leave checkusername
TRACE4 (1137) 3.622512: recv_msg_userauth_request: 'none' request
TRACE4 (1137) 3.622535: enter send_msg_userauth_failure
TRACE4 (1137) 3.622561: auth fail: methods 6, 'publickey,password'
TRACE5 (1137) 3.622591: enter encrypt_packet()
TRACE5 (1137) 3.622614: encrypt_packet type is 51
TRACE5 (1137) 3.622644: enter dropbear_chachapoly_crypt
TRACE5 (1137) 3.622676: leave dropbear_chachapoly_crypt
TRACE5 (1137) 3.622705: leave encrypt_packet()
TRACE4 (1137) 3.622728: leave send_msg_userauth_failure
TRACE5 (1137) 3.622753: leave process_packet
TRACE5 (1137) 3.622776: enter write_packet
TRACE5 (1137) 3.622842: write_packet writev #0 len 52/52
TRACE4 (1137) 3.622912: empty queue dequeing
TRACE5 (1137) 3.622945: leave write_packet
TRACE5 (1137) 3.622978: update_timeout limit 28800, now 2835, last 2835, timeout 28800
TRACE5 (1137) 3.623011: new timeout 28800
TRACE5 (1137) 3.623043: update_timeout limit 300, now 2835, last 2831, timeout 28800
TRACE5 (1137) 3.623068: new timeout 304
TRACE5 (1137) 3.623094: update_timeout limit 0, now 2835, last 2835, timeout 304
TRACE5 (1137) 7.011037: enter read_packet
TRACE5 (1137) 7.011115: enter dropbear_chachapoly_getlength
TRACE5 (1137) 7.011141: leave dropbear_chachapoly_getlength
TRACE5 (1137) 7.011162: packet size is 84, block 8 mac 16
TRACE5 (1137) 7.011198: enter decrypt_packet
TRACE5 (1137) 7.011225: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.011258: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.011282: leave decrypt_packet
TRACE5 (1137) 7.011305: leave read_packet
TRACE5 (1137) 7.011328: enter process_packet
TRACE4 (1137) 7.011349: process_packet: packet type = 50,  len 59
TRACE4 (1137) 7.011376: enter recv_msg_userauth_request
TRACE4 (1137) 7.011404: enter checkusername
TRACE4 (1137) 7.011429: shell is /bin/sh
TRACE4 (1137) 7.011537: test shell is '/bin/ash'
TRACE4 (1137) 7.011562: test shell is '/usr/bin/screen'
TRACE4 (1137) 7.011581: test shell is '/bin/sh'
TRACE4 (1137) 7.011605: matching shell
TRACE4 (1137) 7.011629: uid = 0
TRACE4 (1137) 7.011667: leave checkusername
[1137] Apr 08 22:43:52 Password auth succeeded for 'root' from 10.169.0.1:36220
TRACE4 (1137) 7.023500: enter send_msg_userauth_success
TRACE5 (1137) 7.023516: enter encrypt_packet()
TRACE5 (1137) 7.023531: encrypt_packet type is 52
TRACE5 (1137) 7.023568: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.023601: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.023625: leave encrypt_packet()
TRACE4 (1137) 7.023663: leave send_msg_userauth_success
TRACE5 (1137) 7.023688: leave process_packet
TRACE5 (1137) 7.023708: enter write_packet
TRACE5 (1137) 7.023724: write_packet writev #0 len 36/36
TRACE4 (1137) 7.023821: empty queue dequeing
TRACE5 (1137) 7.023849: leave write_packet
TRACE5 (1137) 7.023865: update_timeout limit 28800, now 2838, last 2835, timeout 28800
TRACE5 (1137) 7.023883: new timeout 28800
TRACE5 (1137) 7.023898: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.023921: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.114857: enter read_packet
TRACE5 (1137) 7.114933: enter dropbear_chachapoly_getlength
TRACE5 (1137) 7.114966: leave dropbear_chachapoly_getlength
TRACE5 (1137) 7.114983: packet size is 52, block 8 mac 16
TRACE5 (1137) 7.115016: enter decrypt_packet
TRACE5 (1137) 7.115033: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.115062: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.115088: leave decrypt_packet
TRACE5 (1137) 7.115107: leave read_packet
TRACE5 (1137) 7.115129: enter process_packet
TRACE4 (1137) 7.115150: process_packet: packet type = 90,  len 29
TRACE4 (1137) 7.115175: enter recv_msg_channel_open
TRACE4 (1137) 7.115204: matched type 'session'
TRACE4 (1137) 7.115227: enter newchannel
TRACE4 (1137) 7.115257: leave newchannel
TRACE4 (1137) 7.115281: new chansess 0x557a67ecd7a0
TRACE4 (1137) 7.115309: update_channel_prio
TRACE4 (1137) 7.115332: enter send_msg_channel_open_confirmation
TRACE5 (1137) 7.115357: enter encrypt_packet()
TRACE5 (1137) 7.115379: encrypt_packet type is 91
TRACE5 (1137) 7.115410: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.115440: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.115471: leave encrypt_packet()
TRACE4 (1137) 7.115494: leave send_msg_channel_open_confirmation
TRACE4 (1137) 7.115519: leave recv_msg_channel_open
TRACE5 (1137) 7.115546: leave process_packet
TRACE5 (1137) 7.115578: enter write_packet
TRACE5 (1137) 7.115601: write_packet writev #0 len 44/44
TRACE4 (1137) 7.115681: empty queue dequeing
TRACE5 (1137) 7.115717: leave write_packet
TRACE5 (1137) 7.115740: update_timeout limit 28800, now 2838, last 2835, timeout 28800
TRACE5 (1137) 7.115769: new timeout 28800
TRACE5 (1137) 7.115820: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.115852: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.208849: enter read_packet
TRACE5 (1137) 7.208925: enter dropbear_chachapoly_getlength
TRACE5 (1137) 7.208953: leave dropbear_chachapoly_getlength
TRACE5 (1137) 7.209007: packet size is 332, block 8 mac 16
TRACE5 (1137) 7.209067: enter decrypt_packet
TRACE5 (1137) 7.209106: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.209188: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.209212: leave decrypt_packet
TRACE5 (1137) 7.209237: leave read_packet
TRACE5 (1137) 7.209253: enter process_packet
TRACE4 (1137) 7.209273: process_packet: packet type = 98,  len 306
TRACE4 (1137) 7.209296: enter recv_msg_channel_request 0x557a67ecd7a0
TRACE4 (1137) 7.209325: enter chansessionrequest
TRACE4 (1137) 7.209344: type is pty-req
TRACE4 (1137) 7.209369: enter sessionpty
TRACE4 (1137) 7.214668: enter get_termmodes
TRACE4 (1137) 7.214707: term mode str 246 p->l 306 p->p 60
TRACE4 (1137) 7.214740: leave get_termmodes
TRACE4 (1137) 7.214768: leave sessionpty
TRACE4 (1137) 7.214791: leave chansessionrequest
TRACE4 (1137) 7.214840: leave recv_msg_channel_request
TRACE5 (1137) 7.214861: leave process_packet
TRACE5 (1137) 7.214894: update_timeout limit 28800, now 2838, last 2835, timeout 28800
TRACE5 (1137) 7.214921: new timeout 28800
TRACE5 (1137) 7.214946: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.214972: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.215010: enter read_packet
TRACE5 (1137) 7.215050: enter dropbear_chachapoly_getlength
TRACE5 (1137) 7.215085: leave dropbear_chachapoly_getlength
TRACE5 (1137) 7.215108: packet size is 44, block 8 mac 16
TRACE5 (1137) 7.215138: enter decrypt_packet
TRACE5 (1137) 7.215164: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.215198: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.215221: leave decrypt_packet
TRACE5 (1137) 7.215244: leave read_packet
TRACE5 (1137) 7.215267: enter process_packet
TRACE4 (1137) 7.215289: process_packet: packet type = 98,  len 20
TRACE4 (1137) 7.215318: enter recv_msg_channel_request 0x557a67ecd7a0
TRACE4 (1137) 7.215349: enter chansessionrequest
TRACE4 (1137) 7.215375: type is shell
TRACE4 (1137) 7.215397: enter sessioncommand 0
TRACE4 (1137) 7.215446: enter ptycommand
TRACE4 (1137) 7.215774: continue ptycommand: parent
TRACE4 (1137) 7.215841: addchildpid 0 pid 1138 for chansess 0x557a67ecd830
TRACE4 (1137) 7.215890: setnonblocking: 6
TRACE4 (1137) 7.215931: leave setnonblocking
TRACE4 (1137) 7.215958: leave ptycommand
TRACE4 (1138) 7.215892: back to normal sigchldTRACE4 (1137) 7.215997: 
leave sessioncommand, ret 0
TRACE4 (1137) 7.216029: leave chansessionrequest
TRACE4 (1137) 7.216050: leave recv_msg_channel_request
TRACE5 (1137) 7.216080: leave process_packet
TRACE5 (1137) 7.216117: update_timeout limit 28800, now 2838, last 2835, timeout 28800
TRACE5 (1137) 7.216154: new timeout 28800
TRACE5 (1137) 7.216170: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.216186: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE4 (1137) 7.216641: send normal readfd
TRACE4 (1137) 7.216672: enter send_msg_channel_data
TRACE4 (1137) 7.216695: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1137) 7.216720: maxlen 16375
TRACE4 (1137) 7.216751: send_msg_channel_data: len 287 fd 6
TRACE5 (1137) 7.216788: enter encrypt_packet()
TRACE5 (1137) 7.216833: encrypt_packet type is 94
TRACE5 (1137) 7.216890: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.216948: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.216983: leave encrypt_packet()
TRACE4 (1137) 7.217010: leave send_msg_channel_data
TRACE5 (1137) 7.217031: check_close: writefd 6, readfd 6, errfd -1, sent_close 0, recv_close 0
TRACE5 (1137) 7.217080: writebuf size 0 extrabuf size 0
TRACE4 (1137) 7.217108: sesscheckclose, pid 1138, exitpid -1
TRACE5 (1137) 7.217135: enter write_packet
TRACE5 (1137) 7.217156: write_packet writev #0 len 324/324
TRACE4 (1137) 7.217236: empty queue dequeing
TRACE5 (1137) 7.217277: leave write_packet
TRACE5 (1137) 7.217297: update_timeout limit 28800, now 2838, last 2835, timeout 28800
TRACE5 (1137) 7.217328: new timeout 28800
TRACE5 (1137) 7.217360: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.217388: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE4 (1137) 7.226350: send normal readfd
TRACE4 (1137) 7.226387: enter send_msg_channel_data
TRACE4 (1137) 7.226402: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1137) 7.226438: maxlen 16375
TRACE4 (1137) 7.226471: send_msg_channel_data: len 2 fd 6
TRACE5 (1137) 7.226493: enter encrypt_packet()
TRACE5 (1137) 7.226519: encrypt_packet type is 94
TRACE5 (1137) 7.226552: enter dropbear_chachapoly_crypt
TRACE5 (1137) 7.226581: leave dropbear_chachapoly_crypt
TRACE5 (1137) 7.226603: leave encrypt_packet()
TRACE4 (1137) 7.226627: leave send_msg_channel_data
TRACE5 (1137) 7.226652: check_close: writefd 6, readfd 6, errfd -1, sent_close 0, recv_close 0
TRACE5 (1137) 7.226671: writebuf size 0 extrabuf size 0
TRACE4 (1137) 7.226693: sesscheckclose, pid 1138, exitpid -1
TRACE5 (1137) 7.226721: enter write_packet
TRACE5 (1137) 7.226744: write_packet writev #0 len 36/36
TRACE4 (1137) 7.226843: empty queue dequeing
TRACE5 (1137) 7.226879: leave write_packet
TRACE5 (1137) 7.226909: update_timeout limit 28800, now 2838, last 2835, timeout 28800
TRACE5 (1137) 7.226940: new timeout 28800
TRACE5 (1137) 7.226972: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 7.227001: update_timeout limit 0, now 2838, last 2838, timeout 28800
TRACE5 (1137) 8.141623: enter read_packet
TRACE5 (1137) 8.141681: enter dropbear_chachapoly_getlength
TRACE5 (1137) 8.141713: leave dropbear_chachapoly_getlength
TRACE5 (1137) 8.141736: packet size is 36, block 8 mac 16
TRACE5 (1137) 8.141772: enter decrypt_packet
TRACE5 (1137) 8.141794: enter dropbear_chachapoly_crypt
TRACE5 (1137) 8.141843: leave dropbear_chachapoly_crypt
TRACE5 (1137) 8.141906: leave decrypt_packet
TRACE5 (1137) 8.141939: leave read_packet
TRACE5 (1137) 8.141970: enter process_packet
TRACE4 (1137) 8.141989: process_packet: packet type = 94,  len 15
TRACE4 (1137) 8.142018: enter recv_msg_channel_data
TRACE4 (1137) 8.142040: length 1
TRACE4 (1137) 8.142064: enter writechannel fd 6
TRACE4 (1137) 8.142091: more 1
TRACE4 (1137) 8.142130: leave writechannel
TRACE4 (1137) 8.142163: leave recv_msg_channel_data
TRACE5 (1137) 8.142185: leave process_packet
TRACE5 (1137) 8.142211: update_timeout limit 28800, now 2839, last 2835, timeout 28800
TRACE5 (1137) 8.142236: new timeout 28800
TRACE5 (1137) 8.142260: update_timeout limit 0, now 2839, last 2839, timeout 28800
TRACE5 (1137) 8.142290: update_timeout limit 0, now 2839, last 2839, timeout 28800
TRACE4 (1137) 8.142325: send normal readfd
TRACE4 (1137) 8.142348: enter send_msg_channel_data
TRACE4 (1137) 8.142367: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1137) 8.142384: maxlen 16375
TRACE4 (1137) 8.142410: send_msg_channel_data: len 2 fd 6
TRACE5 (1137) 8.142441: enter encrypt_packet()
TRACE5 (1137) 8.142466: encrypt_packet type is 94
TRACE5 (1137) 8.142502: enter dropbear_chachapoly_crypt
TRACE4 (1137) 8.142544: enter sigchld handler
TRACE4 (1137) 8.142594: leave sigchld handler
TRACE5 (1137) 8.142529: leave dropbear_chachapoly_crypt
TRACE5 (1137) 8.142656: leave encrypt_packet()
TRACE4 (1137) 8.142681: leave send_msg_channel_data
TRACE5 (1137) 8.142701: check_close: writefd 6, readfd 6, errfd -1, sent_close 0, recv_close 0
TRACE5 (1137) 8.142727: writebuf size 0 extrabuf size 0
TRACE4 (1137) 8.142755: sesscheckclose, pid 1138, exitpid -1
TRACE5 (1137) 8.142787: enter write_packet
TRACE5 (1137) 8.142824: write_packet writev #0 len 36/36
TRACE4 (1137) 8.142894: empty queue dequeing
TRACE5 (1137) 8.142928: leave write_packet
TRACE5 (1137) 8.142958: update_timeout limit 28800, now 2839, last 2835, timeout 28800
TRACE5 (1137) 8.142985: new timeout 28800
TRACE5 (1137) 8.143013: update_timeout limit 0, now 2839, last 2839, timeout 28800
TRACE5 (1137) 8.143041: update_timeout limit 0, now 2839, last 2839, timeout 28800
TRACE4 (1137) 8.143079: signal pipe set
TRACE4 (1137) 8.143162: svr_chansess_checksignal : pid 1138
TRACE4 (1137) 8.143192: found match session
TRACE4 (1137) 8.143213: send normal readfd
TRACE4 (1137) 8.143237: enter send_msg_channel_data
TRACE4 (1137) 8.143263: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1137) 8.143293: maxlen 16375
TRACE4 (1137) 8.143326: CLOSE some fd 6
TRACE4 (1137) 8.143400: leave send_msg_channel_data: len -1 read err 5 or EOF for fd 6
TRACE5 (1137) 8.143437: check_close: writefd -1, readfd -1, errfd -1, sent_close 0, recv_close 0
TRACE5 (1137) 8.143464: writebuf size 0 extrabuf size 0
TRACE4 (1137) 8.143488: sesscheckclose, pid 1138, exitpid 1138
TRACE4 (1137) 8.143514: CLOSE some fd -1
TRACE4 (1137) 8.143536: enter send_msg_channel_eof
TRACE5 (1137) 8.143561: enter encrypt_packet()
TRACE5 (1137) 8.143589: encrypt_packet type is 96
TRACE5 (1137) 8.143615: enter dropbear_chachapoly_crypt
TRACE5 (1137) 8.143649: leave dropbear_chachapoly_crypt
TRACE5 (1137) 8.143673: leave encrypt_packet()
TRACE4 (1137) 8.143701: leave send_msg_channel_eof
TRACE4 (1137) 8.143721: sending close, readfd is closed
TRACE4 (1137) 8.143749: enter send_msg_channel_close 0x557a67ecd7a0
TRACE4 (1137) 8.143769: enter closechansess
TRACE5 (1137) 8.143792: enter encrypt_packet()
TRACE5 (1137) 8.143837: encrypt_packet type is 98
TRACE5 (1137) 8.143869: enter dropbear_chachapoly_crypt
TRACE5 (1137) 8.143902: leave dropbear_chachapoly_crypt
TRACE5 (1137) 8.143926: leave encrypt_packet()
TRACE4 (1137) 8.143954: leave closechansess
TRACE5 (1137) 8.143974: enter encrypt_packet()
TRACE5 (1137) 8.143997: encrypt_packet type is 97
TRACE5 (1137) 8.144023: enter dropbear_chachapoly_crypt
TRACE5 (1137) 8.144048: leave dropbear_chachapoly_crypt
TRACE5 (1137) 8.144077: leave encrypt_packet()
TRACE4 (1137) 8.144107: CLOSE some fd -1
TRACE4 (1137) 8.144133: CLOSE some fd -1
TRACE4 (1137) 8.144155: CLOSE some fd -1
TRACE4 (1137) 8.144181: leave send_msg_channel_close
TRACE5 (1137) 8.144201: enter write_packet
TRACE5 (1137) 8.144229: write_packet writev #0 len 36/36
TRACE5 (1137) 8.144257: write_packet writev #1 len 52/52
TRACE5 (1137) 8.144280: write_packet writev #2 len 36/36
TRACE4 (1137) 8.144338: empty queue dequeing
TRACE5 (1137) 8.144366: leave write_packet
TRACE5 (1137) 8.144388: update_timeout limit 28800, now 2839, last 2835, timeout 28800
TRACE5 (1137) 8.144413: new timeout 28800
TRACE5 (1137) 8.144439: update_timeout limit 0, now 2839, last 2839, timeout 28800
TRACE5 (1137) 8.144463: update_timeout limit 0, now 2839, last 2839, timeout 28800
TRACE5 (1137) 8.254150: enter read_packet
[1137] Apr 08 22:43:53 Exit (root) from <10.169.0.1:36220>: Exited normally
TRACE4 (1137) 8.254418: enter session_cleanup
TRACE4 (1137) 8.254434: enter chancleanup
TRACE4 (1137) 8.254450: channel 0 closing
TRACE4 (1137) 8.254481: enter remove_channel
TRACE4 (1137) 8.254505: channel index is 0
TRACE4 (1137) 8.254539: CLOSE writefd -1
TRACE4 (1137) 8.254565: CLOSE readfd -1
TRACE4 (1137) 8.254587: CLOSE errfd -1
TRACE4 (1137) 8.254616: enter closechansess
TRACE4 (1137) 8.254966: closing pid 1138
TRACE4 (1137) 8.254993: exitpid is 1138
TRACE4 (1137) 8.255009: leave closechansess
TRACE4 (1137) 8.255041: update_channel_prio
TRACE4 (1137) 8.255067: leave update_channel_prio: no socket
TRACE4 (1137) 8.255088: leave remove_channel
TRACE4 (1137) 8.255113: leave chancleanup
TRACE4 (1137) 8.255159: leave session_cleanup
TRACE5 (1137) 8.255185: enter sign_key_free
TRACE5 (1137) 8.255201: enter rsa_key_free
TRACE5 (1137) 8.255216: leave rsa_key_free: key == NULL
TRACE5 (1137) 8.255250: enter ed25519_key_free
TRACE5 (1137) 8.255271: leave ed25519_key_free
TRACE5 (1137) 8.255295: leave sign_key_free
jameshilliard commented 6 months ago

I managed to get OpenSSH client to connect as well by setting -o KexAlgorithms=ecdh-sha2-nistp521:

# /usr/sbin/dropbear -F -R -vvvvv
TRACE5 (1248) 0.000000: enter sign_key_free
TRACE5 (1248) 0.000079: enter rsa_key_free
TRACE5 (1248) 0.000097: leave rsa_key_free: key == NULL
TRACE5 (1248) 0.000121: enter ed25519_key_free
TRACE5 (1248) 0.000143: leave ed25519_key_free: key == NULL
TRACE5 (1248) 0.000167: leave sign_key_free
TRACE4 (1248) 0.000188: leave loadhostkey
TRACE5 (1248) 0.000227: enter sign_key_free
TRACE5 (1248) 0.000252: enter rsa_key_free
TRACE5 (1248) 0.000268: leave rsa_key_free: key == NULL
TRACE5 (1248) 0.000282: enter ed25519_key_free
TRACE5 (1248) 0.000298: leave ed25519_key_free: key == NULL
TRACE5 (1248) 0.000321: leave sign_key_free
TRACE4 (1248) 0.000339: leave loadhostkey
TRACE5 (1248) 0.000414: enter buf_get_priv_key
TRACE5 (1248) 0.000444: enter ed25519_key_free
TRACE5 (1248) 0.000466: leave ed25519_key_free: key == NULL
TRACE4 (1248) 0.000487: enter buf_get_ed25519_priv_key
TRACE4 (1248) 0.000510: leave buf_get_ed25519_priv_key: success
TRACE5 (1248) 0.000536: leave buf_get_priv_key
TRACE5 (1248) 0.000559: enter sign_key_free
TRACE5 (1248) 0.000586: enter rsa_key_free
TRACE5 (1248) 0.000614: leave rsa_key_free: key == NULL
TRACE5 (1248) 0.000637: enter ed25519_key_free
TRACE5 (1248) 0.000656: leave ed25519_key_free: key == NULL
TRACE5 (1248) 0.000677: leave sign_key_free
TRACE4 (1248) 0.000696: leave loadhostkey
TRACE4 (1248) 0.000717: Disabling key type 2
TRACE4 (1248) 0.000743: Disabling key type 3
TRACE4 (1248) 0.000764: Disabling key type 4
TRACE4 (1248) 0.000791: Disabling key type 6
TRACE4 (1248) 0.000811: listensockets: 1 to try
TRACE4 (1248) 0.000837: listening on ':22'
TRACE4 (1248) 0.000867: enter dropbear_listen
TRACE4 (1248) 0.000891: dropbear_listen: all interfaces
TRACE4 (1248) 0.001363: leave dropbear_listen: success, 2 socks bound
TRACE4 (1248) 0.001423: Couldn't set IPV6_TCLASS (Protocol not available)
[1248] Apr 08 22:58:17 Not backgrounding
[1249] Apr 08 22:58:23 Child connection from 10.169.0.1:53564
TRACE5 (1249) 0.000000: enter sign_key_free
TRACE5 (1249) 0.000072: enter rsa_key_free
TRACE5 (1249) 0.000097: leave rsa_key_free: key == NULL
TRACE5 (1249) 0.000116: enter ed25519_key_free
TRACE5 (1249) 0.000137: leave ed25519_key_free: key == NULL
TRACE5 (1249) 0.000162: leave sign_key_free
TRACE4 (1249) 0.000187: leave loadhostkey
TRACE5 (1249) 0.000215: enter sign_key_free
TRACE5 (1249) 0.000237: enter rsa_key_free
TRACE5 (1249) 0.000252: leave rsa_key_free: key == NULL
TRACE5 (1249) 0.000267: enter ed25519_key_free
TRACE5 (1249) 0.000283: leave ed25519_key_free: key == NULL
TRACE5 (1249) 0.000302: leave sign_key_free
TRACE4 (1249) 0.000315: leave loadhostkey
TRACE5 (1249) 0.000369: enter buf_get_priv_key
TRACE5 (1249) 0.000396: enter ed25519_key_free
TRACE5 (1249) 0.000420: leave ed25519_key_free: key == NULL
TRACE4 (1249) 0.000442: enter buf_get_ed25519_priv_key
TRACE4 (1249) 0.000466: leave buf_get_ed25519_priv_key: success
TRACE5 (1249) 0.000490: leave buf_get_priv_key
TRACE5 (1249) 0.000514: enter sign_key_free
TRACE5 (1249) 0.000560: enter rsa_key_free
TRACE5 (1249) 0.000583: leave rsa_key_free: key == NULL
TRACE5 (1249) 0.000603: enter ed25519_key_free
TRACE5 (1249) 0.000626: leave ed25519_key_free: key == NULL
TRACE5 (1249) 0.000653: leave sign_key_free
TRACE4 (1249) 0.000674: leave loadhostkey
TRACE4 (1249) 0.000699: Disabling key type 2
TRACE4 (1249) 0.000727: Disabling key type 3
TRACE4 (1249) 0.000756: Disabling key type 4
TRACE4 (1249) 0.000783: Disabling key type 6
TRACE4 (1249) 0.003237: enter session_init
TRACE4 (1249) 0.003271: setnonblocking: 0
TRACE4 (1249) 0.003293: leave setnonblocking
TRACE4 (1249) 0.003318: setnonblocking: 0
TRACE4 (1249) 0.003346: leave setnonblocking
TRACE4 (1249) 0.003375: update_channel_prio
TRACE4 (1249) 0.003395: update_channel_prio: not any
TRACE4 (1249) 0.003418: Dropbear priority transitioning 0 -> 1
TRACE4 (1249) 0.003456: Couldn't set IPV6_TCLASS (Protocol not available)
TRACE4 (1249) 0.003510: setnonblocking: 3
TRACE4 (1249) 0.003560: leave setnonblocking
TRACE4 (1249) 0.003589: setnonblocking: 4
TRACE4 (1249) 0.003616: leave setnonblocking
TRACE4 (1249) 0.003667: leave session_init
TRACE4 (1249) 0.003744: kexinitialise()
TRACE4 (1249) 0.003778: algolist add 216 'curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,kexguess2@matt.ucc.asn.au,kex-strict-s-v00@openssh.com'
TRACE4 (1249) 0.003816: algolist add 52 'ssh-ed25519,ecdsa-sha2-nistp256,rsa-sha2-256,ssh-rsa'
TRACE4 (1249) 0.003837: algolist add 51 'chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr'
TRACE4 (1249) 0.003864: algolist add 51 'chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr'
TRACE4 (1249) 0.003889: algolist add 23 'hmac-sha1,hmac-sha2-256'
TRACE4 (1249) 0.003912: algolist add 23 'hmac-sha1,hmac-sha2-256'
TRACE4 (1249) 0.003943: algolist add 4 'none'
TRACE4 (1249) 0.003964: algolist add 4 'none'
TRACE5 (1249) 0.003991: enter encrypt_packet()
TRACE5 (1249) 0.004023: encrypt_packet type is 20
TRACE5 (1249) 0.004061: leave writemac
TRACE5 (1249) 0.004093: leave encrypt_packet()
TRACE4 (1249) 0.004120: DATAALLOWED=0
TRACE4 (1249) 0.004137: -> KEXINIT
TRACE5 (1249) 0.004153: update_timeout limit 300, now 3709, last 3709, timeout 28800
TRACE5 (1249) 0.004178: new timeout 300
TRACE5 (1249) 0.004205: update_timeout limit 0, now 3709, last 3709, timeout 300
TRACE4 (1249) 0.004241: maybe_empty_reply_queue - no data allowed
TRACE5 (1249) 0.004269: enter write_packet
TRACE5 (1249) 0.004294: write_packet writev #0 len 26/26
TRACE5 (1249) 0.004316: write_packet writev #1 len 496/496
TRACE4 (1249) 0.004387: empty queue dequeing
TRACE5 (1249) 0.004420: leave write_packet
TRACE5 (1249) 0.004441: update_timeout limit 300, now 3709, last 3709, timeout 28800
TRACE5 (1249) 0.004464: new timeout 300
TRACE5 (1249) 0.004494: update_timeout limit 0, now 3709, last 3709, timeout 300
TRACE4 (1249) 0.004570: enter ident_readln
TRACE4 (1249) 0.004864: leave ident_readln: return 40
TRACE1 (1249) 0.004898: remoteident: SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
TRACE4 (1249) 0.004927: maybe_empty_reply_queue - no data allowed
TRACE5 (1249) 0.004950: update_timeout limit 300, now 3709, last 3709, timeout 28800
TRACE5 (1249) 0.004976: new timeout 300
TRACE5 (1249) 0.005007: update_timeout limit 0, now 3709, last 3709, timeout 300
TRACE5 (1249) 0.106180: enter read_packet
TRACE5 (1249) 0.106257: packet size is 1288, block 8 mac 0
TRACE5 (1249) 0.106349: enter decrypt_packet
TRACE5 (1249) 0.106402: leave writemac
TRACE5 (1249) 0.106461: leave decrypt_packet
TRACE5 (1249) 0.106498: leave read_packet
TRACE5 (1249) 0.106521: enter process_packet
TRACE4 (1249) 0.106568: process_packet: packet type = 20,  len 1282
TRACE4 (1249) 0.106591: got expected packet 20 during kexinit
TRACE4 (1249) 0.106611: <- KEXINIT
TRACE4 (1249) 0.106630: enter recv_msg_kexinit
TRACE3 (1249) 0.106669: buf_match_algo: ecdh-sha2-nistp521,ext-info-c,kex-strict-c-v00@openssh.com
TRACE4 (1249) 0.106695: kexguess2 0
TRACE3 (1249) 0.106721: kex algo ecdh-sha2-nistp521
TRACE3 (1249) 0.106742: buf_match_algo: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
TRACE2 (1249) 0.106792: hostkey algo ssh-ed25519
TRACE3 (1249) 0.106822: buf_match_algo: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
TRACE2 (1249) 0.106854: enc  c2s is chacha20-poly1305@openssh.com
TRACE3 (1249) 0.106880: buf_match_algo: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com
TRACE2 (1249) 0.106912: enc  s2c is chacha20-poly1305@openssh.com
TRACE3 (1249) 0.106944: buf_match_algo: 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
TRACE2 (1249) 0.106977: hmac c2s is <implicit>
TRACE3 (1249) 0.107004: buf_match_algo: 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
TRACE2 (1249) 0.107042: hmac s2c is <implicit>
TRACE3 (1249) 0.107069: buf_match_algo: none,zlib@openssh.com,zlib
TRACE2 (1249) 0.107093: comp c2s is none
TRACE3 (1249) 0.107119: buf_match_algo: none,zlib@openssh.com,zlib
TRACE2 (1249) 0.107147: comp s2c is none
TRACE4 (1249) 0.107179: leave recv_msg_kexinit
TRACE5 (1249) 0.107204: leave process_packet
TRACE4 (1249) 0.107223: maybe_empty_reply_queue - no data allowed
TRACE5 (1249) 0.107250: update_timeout limit 300, now 3710, last 3709, timeout 28800
TRACE5 (1249) 0.107281: new timeout 301
TRACE5 (1249) 0.107304: update_timeout limit 0, now 3710, last 3710, timeout 301
TRACE5 (1249) 0.241724: enter read_packet
TRACE5 (1249) 0.241852: packet size is 152, block 8 mac 0
TRACE5 (1249) 0.241888: enter decrypt_packet
TRACE5 (1249) 0.241920: leave writemac
TRACE5 (1249) 0.241938: leave decrypt_packet
TRACE5 (1249) 0.241952: leave read_packet
TRACE5 (1249) 0.241976: enter process_packet
TRACE4 (1249) 0.242009: process_packet: packet type = 30,  len 143
TRACE4 (1249) 0.242034: got expected packet 30 during kexinit
TRACE4 (1249) 0.242058: enter recv_msg_kexdh_init
TRACE4 (1249) 0.242079: enter send_msg_kexdh_reply
TRACE5 (1249) 0.242128: enter buf_put_pub_key
TRACE4 (1249) 0.242160: enter buf_put_ed25519_pub_key
TRACE4 (1249) 0.242180: leave buf_put_ed25519_pub_key
TRACE5 (1249) 0.242209: leave buf_put_pub_key
TRACE4 (1249) 0.271663: enter buf_get_ecc_raw_pubkey
TRACE5 (1249) 0.301557: enter buf_put_pub_key
TRACE4 (1249) 0.301588: enter buf_put_ed25519_pub_key
TRACE4 (1249) 0.301604: leave buf_put_ed25519_pub_key
TRACE5 (1249) 0.301632: leave buf_put_pub_key
TRACE5 (1249) 0.301682: enter buf_putmpint
TRACE5 (1249) 0.301708: leave buf_putmpint
TRACE4 (1249) 0.301794: buf_put_sign type 5 ssh-ed25519
TRACE4 (1249) 0.301816: enter buf_put_ed25519_sign
TRACE4 (1249) 0.311077: leave buf_put_ed25519_sign
TRACE5 (1249) 0.311103: enter encrypt_packet()
TRACE5 (1249) 0.311122: encrypt_packet type is 31
TRACE5 (1249) 0.311145: leave writemac
TRACE5 (1249) 0.311168: leave encrypt_packet()
TRACE4 (1249) 0.311197: leave send_msg_kexdh_reply
TRACE4 (1249) 0.311218: enter send_msg_newkeys
TRACE5 (1249) 0.311238: enter encrypt_packet()
TRACE5 (1249) 0.311261: encrypt_packet type is 21
TRACE5 (1249) 0.311286: leave writemac
TRACE5 (1249) 0.311307: leave encrypt_packet()
TRACE4 (1249) 0.311329: enter gen_new_keys
TRACE5 (1249) 0.311352: enter buf_putmpint
TRACE5 (1249) 0.311389: leave buf_putmpint
TRACE5 (1249) 0.311425: enter dropbear_chachapoly_start
TRACE5 (1249) 0.311448: leave dropbear_chachapoly_start
TRACE5 (1249) 0.311469: enter dropbear_chachapoly_start
TRACE5 (1249) 0.311496: leave dropbear_chachapoly_start
TRACE4 (1249) 0.311519: leave gen_new_keys
TRACE5 (1249) 0.311560: enter switch_keys
TRACE4 (1249) 0.311579: switch_keys trans
TRACE5 (1249) 0.311603: leave switch_keys
TRACE4 (1249) 0.311623: leave send_msg_newkeys
TRACE4 (1249) 0.311641: enter send_msg_ext_info
TRACE4 (1249) 0.311668: algolist add 154 'ssh-ed25519,sk-ssh-ed25519@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-256,ssh-rsa'
TRACE5 (1249) 0.311704: enter encrypt_packet()
TRACE5 (1249) 0.311723: encrypt_packet type is 7
TRACE5 (1249) 0.311747: enter dropbear_chachapoly_crypt
TRACE5 (1249) 0.311782: leave dropbear_chachapoly_crypt
TRACE5 (1249) 0.311811: leave encrypt_packet()
TRACE4 (1249) 0.311840: leave send_msg_ext_info
TRACE4 (1249) 0.311863: leave recv_msg_kexdh_init
TRACE5 (1249) 0.311886: leave process_packet
TRACE5 (1249) 0.311911: enter write_packet
TRACE5 (1249) 0.311934: write_packet writev #0 len 296/296
TRACE5 (1249) 0.311961: write_packet writev #1 len 16/16
TRACE5 (1249) 0.311984: write_packet writev #2 len 212/212
TRACE4 (1249) 0.312053: empty queue dequeing
TRACE5 (1249) 0.312082: leave write_packet
TRACE5 (1249) 0.312107: update_timeout limit 300, now 3710, last 3709, timeout 28800
TRACE5 (1249) 0.312138: new timeout 301
TRACE5 (1249) 0.312164: update_timeout limit 0, now 3710, last 3710, timeout 301
TRACE5 (1249) 0.429783: enter read_packet
TRACE5 (1249) 0.429937: packet size is 16, block 8 mac 0
TRACE5 (1249) 0.429965: enter decrypt_packet
TRACE5 (1249) 0.429993: leave writemac
TRACE5 (1249) 0.430022: leave decrypt_packet
TRACE5 (1249) 0.430039: leave read_packet
TRACE5 (1249) 0.430063: enter process_packet
TRACE4 (1249) 0.430089: process_packet: packet type = 21,  len 6
TRACE4 (1249) 0.430111: got expected packet 21 during kexinit
TRACE4 (1249) 0.430139: enter recv_msg_newkeys
TRACE5 (1249) 0.430161: enter switch_keys
TRACE4 (1249) 0.430181: switch_keys recv
TRACE4 (1249) 0.430204: switch_keys done
TRACE4 (1249) 0.430227: kexinitialise()
TRACE5 (1249) 0.430254: leave switch_keys
TRACE4 (1249) 0.430278: leave recv_msg_newkeys
TRACE5 (1249) 0.430301: leave process_packet
TRACE5 (1249) 0.430329: update_timeout limit 28800, now 3710, last 3710, timeout 28800
TRACE5 (1249) 0.430356: new timeout 28800
TRACE5 (1249) 0.430382: update_timeout limit 300, now 3710, last 3709, timeout 28800
TRACE5 (1249) 0.430408: new timeout 301
TRACE5 (1249) 0.430429: update_timeout limit 0, now 3710, last 3710, timeout 301
TRACE5 (1249) 0.522954: enter read_packet
TRACE5 (1249) 0.523117: enter dropbear_chachapoly_getlength
TRACE5 (1249) 0.523148: leave dropbear_chachapoly_getlength
TRACE5 (1249) 0.523164: packet size is 44, block 8 mac 16
TRACE5 (1249) 0.523195: enter decrypt_packet
TRACE5 (1249) 0.523216: enter dropbear_chachapoly_crypt
TRACE5 (1249) 0.523246: leave dropbear_chachapoly_crypt
TRACE5 (1249) 0.523270: leave decrypt_packet
TRACE5 (1249) 0.523292: leave read_packet
TRACE5 (1249) 0.523309: enter process_packet
TRACE4 (1249) 0.523328: process_packet: packet type = 5,  len 22
TRACE4 (1249) 0.523360: enter recv_msg_service_request
TRACE4 (1249) 0.523381: accepting service ssh-userauth
TRACE5 (1249) 0.523408: enter encrypt_packet()
TRACE5 (1249) 0.523430: encrypt_packet type is 6
TRACE5 (1249) 0.523460: enter dropbear_chachapoly_crypt
TRACE5 (1249) 0.523489: leave dropbear_chachapoly_crypt
TRACE5 (1249) 0.523515: leave encrypt_packet()
TRACE4 (1249) 0.523562: leave recv_msg_service_request: done ssh-userauth
TRACE5 (1249) 0.523585: leave process_packet
TRACE5 (1249) 0.523610: enter write_packet
TRACE5 (1249) 0.523634: write_packet writev #0 len 44/44
TRACE4 (1249) 0.523698: empty queue dequeing
TRACE5 (1249) 0.523731: leave write_packet
TRACE5 (1249) 0.523759: update_timeout limit 28800, now 3710, last 3710, timeout 28800
TRACE5 (1249) 0.523789: new timeout 28800
TRACE5 (1249) 0.523812: update_timeout limit 300, now 3710, last 3709, timeout 28800
TRACE5 (1249) 0.523840: new timeout 301
TRACE5 (1249) 0.523867: update_timeout limit 0, now 3710, last 3710, timeout 301
TRACE5 (1249) 0.619654: enter read_packet
TRACE5 (1249) 0.619739: enter dropbear_chachapoly_getlength
TRACE5 (1249) 0.619770: leave dropbear_chachapoly_getlength
TRACE5 (1249) 0.619784: packet size is 60, block 8 mac 16
TRACE5 (1249) 0.619819: enter decrypt_packet
TRACE5 (1249) 0.619852: enter dropbear_chachapoly_crypt
TRACE5 (1249) 0.619897: leave dropbear_chachapoly_crypt
TRACE5 (1249) 0.619916: leave decrypt_packet
TRACE5 (1249) 0.619941: leave read_packet
TRACE5 (1249) 0.619968: enter process_packet
TRACE4 (1249) 0.619988: process_packet: packet type = 50,  len 40
TRACE4 (1249) 0.620010: enter recv_msg_userauth_request
TRACE4 (1249) 0.620049: enter checkusername
TRACE4 (1249) 0.620493: shell is /bin/sh
TRACE4 (1249) 0.620608: test shell is '/bin/ash'
TRACE4 (1249) 0.620634: test shell is '/usr/bin/screen'
TRACE4 (1249) 0.620654: test shell is '/bin/sh'
TRACE4 (1249) 0.620673: matching shell
TRACE4 (1249) 0.620688: uid = 0
TRACE4 (1249) 0.620704: leave checkusername
TRACE4 (1249) 0.620722: recv_msg_userauth_request: 'none' request
TRACE4 (1249) 0.620740: enter send_msg_userauth_failure
TRACE4 (1249) 0.620761: auth fail: methods 6, 'publickey,password'
TRACE5 (1249) 0.620782: enter encrypt_packet()
TRACE5 (1249) 0.620799: encrypt_packet type is 51
TRACE5 (1249) 0.620822: enter dropbear_chachapoly_crypt
TRACE5 (1249) 0.620846: leave dropbear_chachapoly_crypt
TRACE5 (1249) 0.620861: leave encrypt_packet()
TRACE4 (1249) 0.620880: leave send_msg_userauth_failure
TRACE5 (1249) 0.620898: leave process_packet
TRACE5 (1249) 0.620919: enter write_packet
TRACE5 (1249) 0.620938: write_packet writev #0 len 52/52
TRACE4 (1249) 0.621043: empty queue dequeing
TRACE5 (1249) 0.621077: leave write_packet
TRACE5 (1249) 0.621095: update_timeout limit 28800, now 3710, last 3710, timeout 28800
TRACE5 (1249) 0.621123: new timeout 28800
TRACE5 (1249) 0.621160: update_timeout limit 300, now 3710, last 3709, timeout 28800
TRACE5 (1249) 0.621193: new timeout 301
TRACE5 (1249) 0.621214: update_timeout limit 0, now 3710, last 3710, timeout 301
TRACE5 (1249) 6.115814: enter read_packet
TRACE5 (1249) 6.115888: enter dropbear_chachapoly_getlength
TRACE5 (1249) 6.115924: leave dropbear_chachapoly_getlength
TRACE5 (1249) 6.115942: packet size is 148, block 8 mac 16
TRACE5 (1249) 6.115979: enter decrypt_packet
TRACE5 (1249) 6.116007: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.116031: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.116054: leave decrypt_packet
TRACE5 (1249) 6.116078: leave read_packet
TRACE5 (1249) 6.116096: enter process_packet
TRACE4 (1249) 6.116132: process_packet: packet type = 50,  len 59
TRACE4 (1249) 6.116156: enter recv_msg_userauth_request
TRACE4 (1249) 6.116176: enter checkusername
TRACE4 (1249) 6.116205: shell is /bin/sh
TRACE4 (1249) 6.116310: test shell is '/bin/ash'
TRACE4 (1249) 6.116335: test shell is '/usr/bin/screen'
TRACE4 (1249) 6.116350: test shell is '/bin/sh'
TRACE4 (1249) 6.116369: matching shell
TRACE4 (1249) 6.116384: uid = 0
TRACE4 (1249) 6.116407: leave checkusername
[1249] Apr 08 22:58:29 Password auth succeeded for 'root' from 10.169.0.1:53564
TRACE4 (1249) 6.128230: enter send_msg_userauth_success
TRACE5 (1249) 6.128249: enter encrypt_packet()
TRACE5 (1249) 6.128262: encrypt_packet type is 52
TRACE5 (1249) 6.128300: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.128330: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.128353: leave encrypt_packet()
TRACE4 (1249) 6.128386: leave send_msg_userauth_success
TRACE5 (1249) 6.128418: leave process_packet
TRACE5 (1249) 6.128453: enter write_packet
TRACE5 (1249) 6.128486: write_packet writev #0 len 36/36
TRACE4 (1249) 6.128577: empty queue dequeing
TRACE5 (1249) 6.128604: leave write_packet
TRACE5 (1249) 6.128639: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.128664: new timeout 28800
TRACE5 (1249) 6.128693: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.128731: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.227693: enter read_packet
TRACE5 (1249) 6.227763: enter dropbear_chachapoly_getlength
TRACE5 (1249) 6.227794: leave dropbear_chachapoly_getlength
TRACE5 (1249) 6.227881: packet size is 52, block 8 mac 16
TRACE5 (1249) 6.227926: enter decrypt_packet
TRACE5 (1249) 6.227960: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.228038: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.228053: leave decrypt_packet
TRACE5 (1249) 6.228078: leave read_packet
TRACE5 (1249) 6.228098: enter process_packet
TRACE4 (1249) 6.228118: process_packet: packet type = 90,  len 29
TRACE4 (1249) 6.228135: enter recv_msg_channel_open
TRACE4 (1249) 6.228155: matched type 'session'
TRACE4 (1249) 6.228182: enter newchannel
TRACE4 (1249) 6.228206: leave newchannel
TRACE4 (1249) 6.228227: new chansess 0x5644ef25a600
TRACE4 (1249) 6.228250: update_channel_prio
TRACE4 (1249) 6.228276: enter send_msg_channel_open_confirmation
TRACE5 (1249) 6.228300: enter encrypt_packet()
TRACE5 (1249) 6.228329: encrypt_packet type is 91
TRACE5 (1249) 6.228361: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.228390: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.228418: leave encrypt_packet()
TRACE4 (1249) 6.228444: leave send_msg_channel_open_confirmation
TRACE4 (1249) 6.228468: leave recv_msg_channel_open
TRACE5 (1249) 6.228493: leave process_packet
TRACE5 (1249) 6.228522: enter write_packet
TRACE5 (1249) 6.228568: write_packet writev #0 len 44/44
TRACE4 (1249) 6.228641: empty queue dequeing
TRACE5 (1249) 6.228673: leave write_packet
TRACE5 (1249) 6.228706: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.228735: new timeout 28800
TRACE5 (1249) 6.228755: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.228781: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.320915: enter read_packet
TRACE5 (1249) 6.320992: enter dropbear_chachapoly_getlength
TRACE5 (1249) 6.321022: leave dropbear_chachapoly_getlength
TRACE5 (1249) 6.321070: packet size is 348, block 8 mac 16
TRACE5 (1249) 6.321128: enter decrypt_packet
TRACE5 (1249) 6.321164: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.321245: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.321264: leave decrypt_packet
TRACE5 (1249) 6.321282: leave read_packet
TRACE5 (1249) 6.321306: enter process_packet
TRACE4 (1249) 6.321325: process_packet: packet type = 98,  len 321
TRACE4 (1249) 6.321349: enter recv_msg_channel_request 0x5644ef25a600
TRACE4 (1249) 6.321375: enter chansessionrequest
TRACE4 (1249) 6.321397: type is pty-req
TRACE4 (1249) 6.321422: enter sessionpty
TRACE4 (1249) 6.326926: enter get_termmodes
TRACE4 (1249) 6.326971: term mode str 261 p->l 321 p->p 60
TRACE4 (1249) 6.326996: leave get_termmodes
TRACE4 (1249) 6.327018: leave sessionpty
TRACE4 (1249) 6.327043: enter send_msg_channel_success
TRACE5 (1249) 6.327065: enter encrypt_packet()
TRACE5 (1249) 6.327091: encrypt_packet type is 99
TRACE5 (1249) 6.327123: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.327154: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.327173: leave encrypt_packet()
TRACE4 (1249) 6.327198: leave send_msg_channel_success
TRACE4 (1249) 6.327220: leave chansessionrequest
TRACE4 (1249) 6.327238: leave recv_msg_channel_request
TRACE5 (1249) 6.327263: leave process_packet
TRACE5 (1249) 6.327289: enter write_packet
TRACE5 (1249) 6.327310: write_packet writev #0 len 36/36
TRACE4 (1249) 6.327371: empty queue dequeing
TRACE5 (1249) 6.327404: leave write_packet
TRACE5 (1249) 6.327435: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.327465: new timeout 28800
TRACE5 (1249) 6.327491: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.327515: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.327568: enter read_packet
TRACE5 (1249) 6.327603: enter dropbear_chachapoly_getlength
TRACE5 (1249) 6.327635: leave dropbear_chachapoly_getlength
TRACE5 (1249) 6.327662: packet size is 60, block 8 mac 16
TRACE5 (1249) 6.327695: enter decrypt_packet
TRACE5 (1249) 6.327726: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.327751: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.327777: leave decrypt_packet
TRACE5 (1249) 6.327805: leave read_packet
TRACE5 (1249) 6.327827: enter process_packet
TRACE4 (1249) 6.327846: process_packet: packet type = 98,  len 37
TRACE4 (1249) 6.327876: enter recv_msg_channel_request 0x5644ef25a600
TRACE4 (1249) 6.327899: enter chansessionrequest
TRACE4 (1249) 6.327927: type is env
TRACE4 (1249) 6.327957: leave chansessionrequest
TRACE4 (1249) 6.327986: leave recv_msg_channel_request
TRACE5 (1249) 6.328011: leave process_packet
TRACE5 (1249) 6.328033: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.328053: new timeout 28800
TRACE5 (1249) 6.328073: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.328107: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.328141: enter read_packet
TRACE5 (1249) 6.328179: enter dropbear_chachapoly_getlength
TRACE5 (1249) 6.328210: leave dropbear_chachapoly_getlength
TRACE5 (1249) 6.328234: packet size is 44, block 8 mac 16
TRACE5 (1249) 6.328268: enter decrypt_packet
TRACE5 (1249) 6.328293: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.328323: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.328357: leave decrypt_packet
TRACE5 (1249) 6.328378: leave read_packet
TRACE5 (1249) 6.328404: enter process_packet
TRACE4 (1249) 6.328427: process_packet: packet type = 98,  len 20
TRACE4 (1249) 6.328452: enter recv_msg_channel_request 0x5644ef25a600
TRACE4 (1249) 6.328476: enter chansessionrequest
TRACE4 (1249) 6.328504: type is shell
TRACE4 (1249) 6.328569: enter sessioncommand 0
TRACE4 (1249) 6.328609: enter ptycommand
TRACE4 (1249) 6.328928: continue ptycommand: parent
TRACE4 (1249) 6.328994: addchildpid 0 pid 1250 for chansess 0x5644ef25a690
TRACE4 (1249) 6.329034: setnonblocking: 6
TRACE4 (1249) 6.329061: leave setnonblocking
TRACE4 (1249) 6.329077: leave ptycommand
TRACE4 (1250) 6.329036: TRACE4 (1249) 6.329118: leave sessioncommand, ret 0back to normal sigchld
TRACE4 (1249) 6.329147: 
enter send_msg_channel_success
TRACE5 (1249) 6.329165: enter encrypt_packet()
TRACE5 (1249) 6.329180: encrypt_packet type is 99
TRACE5 (1249) 6.329201: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.329243: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.329263: leave encrypt_packet()
TRACE4 (1249) 6.329277: leave send_msg_channel_success
TRACE4 (1249) 6.329301: leave chansessionrequest
TRACE4 (1249) 6.329318: leave recv_msg_channel_request
TRACE5 (1249) 6.329332: leave process_packet
TRACE5 (1249) 6.329347: enter write_packet
TRACE5 (1249) 6.329361: write_packet writev #0 len 36/36
TRACE4 (1249) 6.329419: empty queue dequeing
TRACE5 (1249) 6.329452: leave write_packet
TRACE5 (1249) 6.329469: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.329487: new timeout 28800
TRACE5 (1249) 6.329501: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.329518: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE4 (1249) 6.329812: send normal readfd
TRACE4 (1249) 6.329841: enter send_msg_channel_data
TRACE4 (1249) 6.329868: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1249) 6.329903: maxlen 16375
TRACE4 (1249) 6.329945: send_msg_channel_data: len 287 fd 6
TRACE5 (1249) 6.330030: enter encrypt_packet()
TRACE5 (1249) 6.330058: encrypt_packet type is 94
TRACE5 (1249) 6.330095: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.330141: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.330169: leave encrypt_packet()
TRACE4 (1249) 6.330189: leave send_msg_channel_data
TRACE5 (1249) 6.330211: check_close: writefd 6, readfd 6, errfd -1, sent_close 0, recv_close 0
TRACE5 (1249) 6.330240: writebuf size 0 extrabuf size 0
TRACE4 (1249) 6.330265: sesscheckclose, pid 1250, exitpid -1
TRACE5 (1249) 6.330293: enter write_packet
TRACE5 (1249) 6.330310: write_packet writev #0 len 324/324
TRACE4 (1249) 6.330378: empty queue dequeing
TRACE5 (1249) 6.330413: leave write_packet
TRACE5 (1249) 6.330451: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.330481: new timeout 28800
TRACE5 (1249) 6.330511: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.330572: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE4 (1249) 6.339123: send normal readfd
TRACE4 (1249) 6.339159: enter send_msg_channel_data
TRACE4 (1249) 6.339172: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1249) 6.339198: maxlen 16375
TRACE4 (1249) 6.339229: send_msg_channel_data: len 2 fd 6
TRACE5 (1249) 6.339252: enter encrypt_packet()
TRACE5 (1249) 6.339281: encrypt_packet type is 94
TRACE5 (1249) 6.339308: enter dropbear_chachapoly_crypt
TRACE5 (1249) 6.339338: leave dropbear_chachapoly_crypt
TRACE5 (1249) 6.339360: leave encrypt_packet()
TRACE4 (1249) 6.339385: leave send_msg_channel_data
TRACE5 (1249) 6.339406: check_close: writefd 6, readfd 6, errfd -1, sent_close 0, recv_close 0
TRACE5 (1249) 6.339431: writebuf size 0 extrabuf size 0
TRACE4 (1249) 6.339455: sesscheckclose, pid 1250, exitpid -1
TRACE5 (1249) 6.339478: enter write_packet
TRACE5 (1249) 6.339498: write_packet writev #0 len 36/36
TRACE4 (1249) 6.339591: empty queue dequeing
TRACE5 (1249) 6.339621: leave write_packet
TRACE5 (1249) 6.339647: update_timeout limit 28800, now 3716, last 3710, timeout 28800
TRACE5 (1249) 6.339674: new timeout 28800
TRACE5 (1249) 6.339702: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 6.339728: update_timeout limit 0, now 3716, last 3716, timeout 28800
TRACE5 (1249) 8.539675: enter read_packet
TRACE5 (1249) 8.539756: enter dropbear_chachapoly_getlength
TRACE5 (1249) 8.539788: leave dropbear_chachapoly_getlength
TRACE5 (1249) 8.539843: packet size is 36, block 8 mac 16
TRACE5 (1249) 8.539897: enter decrypt_packet
TRACE5 (1249) 8.539921: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.539948: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.539970: leave decrypt_packet
TRACE5 (1249) 8.539991: leave read_packet
TRACE5 (1249) 8.540022: enter process_packet
TRACE4 (1249) 8.540043: process_packet: packet type = 94,  len 15
TRACE4 (1249) 8.540085: enter recv_msg_channel_data
TRACE4 (1249) 8.540117: length 1
TRACE4 (1249) 8.540142: enter writechannel fd 6
TRACE4 (1249) 8.540165: more 1
TRACE4 (1249) 8.540207: leave writechannel
TRACE4 (1249) 8.540242: leave recv_msg_channel_data
TRACE5 (1249) 8.540259: leave process_packet
TRACE5 (1249) 8.540279: update_timeout limit 28800, now 3718, last 3710, timeout 28800
TRACE5 (1249) 8.540298: new timeout 28800
TRACE5 (1249) 8.540314: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE5 (1249) 8.540331: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE4 (1249) 8.540753: enter sigchld handler
TRACE4 (1249) 8.540797: leave sigchld handler
TRACE4 (1249) 8.540821: send normal readfd
TRACE4 (1249) 8.540848: enter send_msg_channel_data
TRACE4 (1249) 8.540864: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1249) 8.540881: maxlen 16375
TRACE4 (1249) 8.540900: send_msg_channel_data: len 2 fd 6
TRACE5 (1249) 8.540918: enter encrypt_packet()
TRACE5 (1249) 8.540932: encrypt_packet type is 94
TRACE5 (1249) 8.540956: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.540976: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.540992: leave encrypt_packet()
TRACE4 (1249) 8.541007: leave send_msg_channel_data
TRACE5 (1249) 8.541019: check_close: writefd 6, readfd 6, errfd -1, sent_close 0, recv_close 0
TRACE5 (1249) 8.541036: writebuf size 0 extrabuf size 0
TRACE4 (1249) 8.541052: sesscheckclose, pid 1250, exitpid -1
TRACE5 (1249) 8.541070: enter write_packet
TRACE5 (1249) 8.541087: write_packet writev #0 len 36/36
TRACE4 (1249) 8.541146: empty queue dequeing
TRACE5 (1249) 8.541166: leave write_packet
TRACE5 (1249) 8.541182: update_timeout limit 28800, now 3718, last 3710, timeout 28800
TRACE5 (1249) 8.541197: new timeout 28800
TRACE5 (1249) 8.541213: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE5 (1249) 8.541229: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE4 (1249) 8.541258: signal pipe set
TRACE4 (1249) 8.541325: svr_chansess_checksignal : pid 1250
TRACE4 (1249) 8.541347: found match session
TRACE4 (1249) 8.541366: send normal readfd
TRACE4 (1249) 8.541384: enter send_msg_channel_data
TRACE4 (1249) 8.541398: enter send_msg_channel_data isextended 0 fd 6
TRACE4 (1249) 8.541411: maxlen 16375
TRACE4 (1249) 8.541438: CLOSE some fd 6
TRACE4 (1249) 8.541554: leave send_msg_channel_data: len -1 read err 5 or EOF for fd 6
TRACE5 (1249) 8.541587: check_close: writefd -1, readfd -1, errfd -1, sent_close 0, recv_close 0
TRACE5 (1249) 8.541604: writebuf size 0 extrabuf size 0
TRACE4 (1249) 8.541640: sesscheckclose, pid 1250, exitpid 1250
TRACE4 (1249) 8.541658: CLOSE some fd -1
TRACE4 (1249) 8.541675: enter send_msg_channel_eof
TRACE5 (1249) 8.541708: enter encrypt_packet()
TRACE5 (1249) 8.541734: encrypt_packet type is 96
TRACE5 (1249) 8.541757: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.541789: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.541825: leave encrypt_packet()
TRACE4 (1249) 8.541841: leave send_msg_channel_eof
TRACE4 (1249) 8.541866: sending close, readfd is closed
TRACE4 (1249) 8.541898: enter send_msg_channel_close 0x5644ef25a600
TRACE4 (1249) 8.541916: enter closechansess
TRACE5 (1249) 8.541937: enter encrypt_packet()
TRACE5 (1249) 8.541964: encrypt_packet type is 98
TRACE5 (1249) 8.541990: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.542017: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.542041: leave encrypt_packet()
TRACE4 (1249) 8.542074: leave closechansess
TRACE5 (1249) 8.542099: enter encrypt_packet()
TRACE5 (1249) 8.542131: encrypt_packet type is 97
TRACE5 (1249) 8.542165: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.542192: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.542226: leave encrypt_packet()
TRACE4 (1249) 8.542257: CLOSE some fd -1
TRACE4 (1249) 8.542290: CLOSE some fd -1
TRACE4 (1249) 8.542314: CLOSE some fd -1
TRACE4 (1249) 8.542333: leave send_msg_channel_close
TRACE5 (1249) 8.542361: enter write_packet
TRACE5 (1249) 8.542396: write_packet writev #0 len 36/36
TRACE5 (1249) 8.542422: write_packet writev #1 len 52/52
TRACE5 (1249) 8.542444: write_packet writev #2 len 36/36
TRACE4 (1249) 8.542503: empty queue dequeing
TRACE5 (1249) 8.542555: leave write_packet
TRACE5 (1249) 8.542581: update_timeout limit 28800, now 3718, last 3710, timeout 28800
TRACE5 (1249) 8.542613: new timeout 28800
TRACE5 (1249) 8.542633: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE5 (1249) 8.542660: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE5 (1249) 8.652930: enter read_packet
TRACE5 (1249) 8.652996: enter dropbear_chachapoly_getlength
TRACE5 (1249) 8.653022: leave dropbear_chachapoly_getlength
TRACE5 (1249) 8.653040: packet size is 36, block 8 mac 16
TRACE5 (1249) 8.653071: enter decrypt_packet
TRACE5 (1249) 8.653099: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.653138: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.653158: leave decrypt_packet
TRACE5 (1249) 8.653186: leave read_packet
TRACE5 (1249) 8.653207: enter process_packet
TRACE4 (1249) 8.653230: process_packet: packet type = 97,  len 10
TRACE4 (1249) 8.653254: enter recv_msg_channel_close
TRACE5 (1249) 8.653279: check_close: writefd -1, readfd -1, errfd -1, sent_close 1, recv_close 1
TRACE5 (1249) 8.653305: writebuf size 0 extrabuf size 0
TRACE4 (1249) 8.653331: enter remove_channel
TRACE4 (1249) 8.653352: channel index is 0
TRACE4 (1249) 8.653377: CLOSE writefd -1
TRACE4 (1249) 8.653402: CLOSE readfd -1
TRACE4 (1249) 8.653423: CLOSE errfd -1
TRACE4 (1249) 8.653449: enter closechansess
TRACE4 (1249) 8.653830: closing pid 1250
TRACE4 (1249) 8.653857: exitpid is 1250
TRACE4 (1249) 8.653880: leave closechansess
TRACE4 (1249) 8.653899: update_channel_prio
TRACE4 (1249) 8.653925: update_channel_prio: not any
TRACE4 (1249) 8.653950: leave remove_channel
TRACE4 (1249) 8.653970: leave recv_msg_channel_close
TRACE5 (1249) 8.653999: leave process_packet
TRACE5 (1249) 8.654024: update_timeout limit 28800, now 3718, last 3710, timeout 28800
TRACE5 (1249) 8.654051: new timeout 28800
TRACE5 (1249) 8.654078: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE5 (1249) 8.654103: update_timeout limit 0, now 3718, last 3718, timeout 28800
TRACE5 (1249) 8.654136: enter read_packet
TRACE5 (1249) 8.654174: enter dropbear_chachapoly_getlength
TRACE5 (1249) 8.654214: leave dropbear_chachapoly_getlength
TRACE5 (1249) 8.654236: packet size is 60, block 8 mac 16
TRACE5 (1249) 8.654289: enter decrypt_packet
TRACE5 (1249) 8.654315: enter dropbear_chachapoly_crypt
TRACE5 (1249) 8.654338: leave dropbear_chachapoly_crypt
TRACE5 (1249) 8.654364: leave decrypt_packet
TRACE5 (1249) 8.654386: leave read_packet
TRACE5 (1249) 8.654409: enter process_packet
TRACE4 (1249) 8.654434: process_packet: packet type = 1,  len 38
[1249] Apr 08 22:58:32 Exit (root) from <10.169.0.1:53564>: Disconnect received
TRACE4 (1249) 8.654574: enter session_cleanup
TRACE4 (1249) 8.654594: enter chancleanup
TRACE4 (1249) 8.654620: leave chancleanup
TRACE4 (1249) 8.654676: leave session_cleanup
TRACE5 (1249) 8.654706: enter sign_key_free
TRACE5 (1249) 8.654734: enter rsa_key_free
TRACE5 (1249) 8.654758: leave rsa_key_free: key == NULL
TRACE5 (1249) 8.654805: enter ed25519_key_free
TRACE5 (1249) 8.654836: leave ed25519_key_free
TRACE5 (1249) 8.654871: leave sign_key_free
^C[1248] Apr 08 22:58:36 Early exit: Terminated by signal
TRACE4 (1248) 18.902340: enter session_cleanup
TRACE4 (1248) 18.902367: leave session_cleanup: !ses.init_done
TRACE5 (1248) 18.902397: enter sign_key_free
TRACE5 (1248) 18.902412: enter rsa_key_free
TRACE5 (1248) 18.902441: leave rsa_key_free: key == NULL
TRACE5 (1248) 18.902499: enter ed25519_key_free
TRACE5 (1248) 18.902548: leave ed25519_key_free
TRACE5 (1248) 18.902572: leave sign_key_free
# ssh -o KexAlgorithms=ecdh-sha2-nistp521 -vvvvvv root@10.169.5.126
OpenSSH_8.9p1 Ubuntu-3ubuntu0.6, OpenSSL 3.0.2 15 Mar 2022
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 19: include /etc/ssh/ssh_config.d/*.conf matched no files
debug1: /etc/ssh/ssh_config line 21: Applying options for *
debug2: resolve_canonicalize: hostname 10.169.5.126 is address
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/root/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/root/.ssh/known_hosts2'
debug3: ssh_connect_direct: entering
debug1: Connecting to 10.169.5.126 [10.169.5.126] port 22.
debug3: set_sock_tos: set socket 3 IP_TOS 0x10
debug1: Connection established.
debug1: identity file /root/.ssh/id_rsa type -1
debug1: identity file /root/.ssh/id_rsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa type -1
debug1: identity file /root/.ssh/id_ecdsa-cert type -1
debug1: identity file /root/.ssh/id_ecdsa_sk type -1
debug1: identity file /root/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /root/.ssh/id_ed25519 type -1
debug1: identity file /root/.ssh/id_ed25519-cert type -1
debug1: identity file /root/.ssh/id_ed25519_sk type -1
debug1: identity file /root/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /root/.ssh/id_xmss type -1
debug1: identity file /root/.ssh/id_xmss-cert type -1
debug1: identity file /root/.ssh/id_dsa type -1
debug1: identity file /root/.ssh/id_dsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.6
debug1: Remote protocol version 2.0, remote software version dropbear_2024.84
debug1: compat_banner: no match: dropbear_2024.84
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to 10.169.5.126:22 as 'root'
debug3: record_hostkey: found key type ED25519 in file /root/.ssh/known_hosts:210
debug3: load_hostkeys_file: loaded 1 keys from 10.169.5.126
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug3: order_hostkeyalgs: have matching best-preference key type ssh-ed25519-cert-v01@openssh.com, using HostkeyAlgorithms verbatim
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: ecdh-sha2-nistp521,ext-info-c,kex-strict-c-v00@openssh.com
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256
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-nistp521,ecdh-sha2-nistp384,ecdh-sha2-nistp256,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,kexguess2@matt.ucc.asn.au,kex-strict-s-v00@openssh.com
debug2: host key algorithms: ssh-ed25519,ecdsa-sha2-nistp256,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes256-ctr
debug2: MACs ctos: hmac-sha1,hmac-sha2-256
debug2: MACs stoc: hmac-sha1,hmac-sha2-256
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos: 
debug2: languages stoc: 
debug2: first_kex_follows 0 
debug2: reserved 0 
debug3: kex_choose_conf: will use strict KEX ordering
debug1: kex: algorithm: ecdh-sha2-nistp521
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: SSH2_MSG_KEX_ECDH_REPLY received
debug1: Server host key: ssh-ed25519 SHA256:$REDACTED
debug3: record_hostkey: found key type ED25519 in file /root/.ssh/known_hosts:210
debug3: load_hostkeys_file: loaded 1 keys from 10.169.5.126
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: Host '10.169.5.126' is known and matches the ED25519 host key.
debug1: Found key in /root/.ssh/known_hosts:210
debug3: send packet: type 21
debug1: ssh_packet_send2_wrapped: resetting send seqnr 3
debug2: ssh_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: ssh_packet_read_poll2: resetting read seqnr 3
debug1: SSH2_MSG_NEWKEYS received
debug2: ssh_set_newkeys: mode 0
debug1: rekey in after 134217728 blocks
debug1: Will attempt key: /root/.ssh/id_rsa 
debug1: Will attempt key: /root/.ssh/id_ecdsa 
debug1: Will attempt key: /root/.ssh/id_ecdsa_sk 
debug1: Will attempt key: /root/.ssh/id_ed25519 
debug1: Will attempt key: /root/.ssh/id_ed25519_sk 
debug1: Will attempt key: /root/.ssh/id_xmss 
debug1: Will attempt key: /root/.ssh/id_dsa 
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,sk-ssh-ed25519@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-256,ssh-rsa>
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: Trying private key: /root/.ssh/id_rsa
debug3: no such identity: /root/.ssh/id_rsa: 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_ecdsa_sk
debug3: no such identity: /root/.ssh/id_ecdsa_sk: 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
debug1: Trying private key: /root/.ssh/id_ed25519_sk
debug3: no such identity: /root/.ssh/id_ed25519_sk: No such file or directory
debug1: Trying private key: /root/.ssh/id_xmss
debug3: no such identity: /root/.ssh/id_xmss: No such file or directory
debug1: Trying private key: /root/.ssh/id_dsa
debug3: no such identity: /root/.ssh/id_dsa: No such file or directory
debug2: we did not send a packet, disable method
debug3: authmethod_lookup password
debug3: remaining preferred: ,password
debug3: authmethod_is_enabled password
debug1: Next authentication method: password
root@10.169.5.126's password: 
debug3: send packet: type 50
debug2: we sent a password packet, wait for reply
debug3: receive packet: type 52
Authenticated to 10.169.5.126 ([10.169.5.126]:22) using "password".
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: filesystem
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 0: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: set_sock_tos: set socket 3 IP_TOS 0x10
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1
debug3: send packet: type 98
debug1: Sending environment.
debug3: Ignored env SHELL
debug3: Ignored env PWD
debug3: Ignored env LOGNAME
debug3: Ignored env XDG_SESSION_TYPE
debug3: Ignored env MOTD_SHOWN
debug3: Ignored env HOME
debug1: channel 0: setting env LANG = "C.UTF-8"
debug2: channel 0: request env confirm 0
debug3: send packet: type 98
debug3: Ignored env LS_COLORS
debug3: Ignored env SSH_CONNECTION
debug3: Ignored env LESSCLOSE
debug3: Ignored env XDG_SESSION_CLASS
debug3: Ignored env TERM
debug3: Ignored env LESSOPEN
debug3: Ignored env USER
debug3: Ignored env SHLVL
debug3: Ignored env XDG_SESSION_ID
debug3: Ignored env XDG_RUNTIME_DIR
debug3: Ignored env SSH_CLIENT
debug3: Ignored env XDG_DATA_DIRS
debug3: Ignored env PATH
debug3: Ignored env DBUS_SESSION_BUS_ADDRESS
debug3: Ignored env SSH_TTY
debug3: Ignored env _
debug3: Ignored env OLDPWD
debug2: channel 0: request shell confirm 1
debug3: send packet: type 98
debug2: channel_input_open_confirmation: channel 0: callback done
debug2: channel 0: open confirm rwindow 24576 rmax 32759
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: PTY allocation request accepted on channel 0
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 0
debug2: shell request accepted on channel 0
TRACE5 (1250) 6.329707: enter sign_key_free
TRACE5 (1250) 6.329738: enter rsa_key_free
TRACE5 (1250) 6.329751: leave rsa_key_free: key == NULL
TRACE5 (1250) 6.329772: enter ed25519_key_free
TRACE5 (1250) 6.329805: leave ed25519_key_free
TRACE5 (1250) 6.329825: leave sign_key_free
# 
debug3: receive packet: type 96
debug2: channel 0: rcvd eof
debug2: channel 0: output open -> drain
debug2: channel 0: obuf empty
debug2: chan_shutdown_write: channel 0: (i0 o1 sock -1 wfd 5 efd 6 [write])
debug2: channel 0: output drain -> closed
debug3: receive packet: type 98
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug3: receive packet: type 97
debug2: channel 0: rcvd close
debug2: chan_shutdown_read: channel 0: (i0 o3 sock -1 wfd 4 efd 6 [write])
debug2: channel 0: input open -> closed
debug3: channel 0: will not send data after close
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug3: send packet: type 97
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i3/0 o3/0 e[write]/0 fd -1/-1/6 sock -1 cc -1 io 0x00/0x00)

debug3: send packet: type 1
Connection to 10.169.5.126 closed.
Transferred: sent 2184, received 1580 bytes, in 2.4 seconds
Bytes per second: sent 898.3, received 649.9
debug1: Exit status 0
mkj commented 6 months ago

I can't reproduce it here with OpenSSH 9.3, but it could be something specific to the setup you have there.

Did it work OK with any previous versions of Dropbear? Are there any interesting firewalls/routing between the two hosts? Wondering if it could be a MTU issue or similar. If you can get a pcap from tcpdump (ideally both sides) that might give a clue.

jameshilliard commented 6 months ago

it could be something specific to the setup you have there.

I do suspect that is the case, only difference between systems that it happens on and systems it doesn't is the local network they are on. The ssh connection attempts are all being made via wireguard tunnels from the same system and ssh works fine on most but some it has this issue on some it seems. It doesn't appear other services are effected(telnet works fine as does http).

Did it work OK with any previous versions of Dropbear?

I think I might have seen it happen on previous versions.

Are there any interesting firewalls/routing between the two hosts?

Basically just simple wireguard tunnels all configured the same way.

Wondering if it could be a MTU issue or similar.

I was reading some stuff about MTU issues with ssh which is how I found the workaround for getting the openssh client to connect, I'm a bit confused how that could break ssh but not other protocols however. Is there a good way to tell if MTU is wrong or something?

If you can get a pcap from tcpdump (ideally both sides) that might give a clue.

Yeah, I'll see what I can get there.

jameshilliard commented 6 months ago

client.pcapng.gz server.pcapng.gz

jameshilliard commented 6 months ago

Wondering if it could be a MTU issue or similar.

Hmm, so it does seem likely to be related to the MTU, I'm unable to ping with more than 1402 data bytes on the normal WAN interface and 1332 data bytes over the wireguard interface on the system that isn't working. When trying to ping the system over wireguard via packets with between 1332 and 1392 bytes the ping fails without a message too long error(which appears for packets with more than 1392 data bytes) presumably breaking Path MTU Discovery.

mkj commented 6 months ago

Something in the path must be changing the packets. The client sents a 1588 byte packet, but the server seems to miss receiving a packet (wireshark sequence number analysis), then receives a 220 byte packet containing the last portion of that 1588 byte packet. I'm not sure what could cause that kind of tcp level fragmentation, maybe a NAT device of some sort?

8   0.219766    10.169.0.1  10.169.5.126    SSHv2   1588 Client: Key Exchange Init

vs

8   0.222143    10.169.0.1  10.169.5.126    TCP 220 [TCP Previous segment not captured] 53246 → 22 [PSH, ACK] Seq=1410 Ack=523 Win=64384 Len=168 TSval=3868692005 TSecr=3068156864 [TCP segment of a reassembled PDU]