Attachment 3636 Details for Bug 3507 – Working example sshd log for comparison

Working example sshd log for comparison

sshd-working.log (text/plain), 16.84 KB, created by Darren Tucker on 2022-12-08 12:39:19 AEDT

(hide)

Description:

Filename:

MIME Type:

Creator: Darren Tucker

Created: 2022-12-08 12:39:19 AEDT

Size: 16.84 KB

patch

obsolete

>$ sudo /opt/openssh-9.1p1/sbin/sshd -ddd -p 2022
>debug2: load_server_config: filename /opt/openssh-9.1p1/etc/sshd_config
>debug2: load_server_config: done config len = 166
>debug2: parse_server_config_depth: config /opt/openssh-9.1p1/etc/sshd_config len 166
>debug3: /opt/openssh-9.1p1/etc/sshd_config:1 setting HostbasedAuthentication yes
>debug3: /opt/openssh-9.1p1/etc/sshd_config:2 setting HostbasedUsesNameFromPacketOnly yes
>debug3: /opt/openssh-9.1p1/etc/sshd_config:3 setting AuthorizedKeysFile /dev/null
>debug1: sshd version OpenSSH_9.1, OpenSSL 3.0.5 5 Jul 2022
>debug1: private host key #0: ssh-rsa SHA256:1FY5vg01dI2AWBK27OhD3XSKMgKwMz8vMj3cMIQPiDQ
>debug1: private host key #1: ecdsa-sha2-nistp256 SHA256:umyxwtUf74bvjgCEjVR7qfS7klP6mKdCEpV82LA4vp4
>debug1: private host key #2: ssh-ed25519 SHA256:XzVjZOP7hMCfCIR+VB/5ba8h3R28Vbo57ZWQSd+e61w
>debug1: rexec_argv[0]='/opt/openssh-9.1p1/sbin/sshd'
>debug1: rexec_argv[1]='-ddd'
>debug1: rexec_argv[2]='-p'
>debug1: rexec_argv[3]='2022'
>debug3: oom_adjust_setup
>debug1: Set /proc/self/oom_score_adj from 0 to -1000
>debug2: fd 3 setting O_NONBLOCK
>debug1: Bind to port 2022 on 0.0.0.0.
>Server listening on 0.0.0.0 port 2022.
>debug2: fd 4 setting O_NONBLOCK
>debug3: sock_set_v6only: set socket 4 IPV6_V6ONLY
>debug1: Bind to port 2022 on ::.
>Server listening on :: port 2022.
>debug3: fd 5 is not O_NONBLOCK
>debug1: Server will not fork when running in debugging mode.
>debug3: send_rexec_state: entering fd = 8 config len 166
>debug3: ssh_msg_send: type 0
>debug3: send_rexec_state: done
>debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
>debug3: recv_rexec_state: entering fd = 5
>debug3: ssh_msg_recv entering
>debug3: recv_rexec_state: done
>debug2: parse_server_config_depth: config rexec len 166
>debug3: rexec:1 setting HostbasedAuthentication yes
>debug3: rexec:2 setting HostbasedUsesNameFromPacketOnly yes
>debug3: rexec:3 setting AuthorizedKeysFile /dev/null
>debug1: sshd version OpenSSH_9.1, OpenSSL 3.0.5 5 Jul 2022
>debug1: private host key #0: ssh-rsa SHA256:1FY5vg01dI2AWBK27OhD3XSKMgKwMz8vMj3cMIQPiDQ
>debug1: private host key #1: ecdsa-sha2-nistp256 SHA256:umyxwtUf74bvjgCEjVR7qfS7klP6mKdCEpV82LA4vp4
>debug1: private host key #2: ssh-ed25519 SHA256:XzVjZOP7hMCfCIR+VB/5ba8h3R28Vbo57ZWQSd+e61w
>debug1: inetd sockets after dupping: 3, 3
>Connection from 192.168.32.1 port 49370 on 192.168.32.1 port 2022 rdomain ""
>debug1: Local version string SSH-2.0-OpenSSH_9.1
>debug1: Remote protocol version 2.0, remote software version OpenSSH_9.1
>debug1: compat_banner: match: OpenSSH_9.1 pat OpenSSH* compat 0x04000000
>debug2: fd 3 setting O_NONBLOCK
>debug3: ssh_sandbox_init: preparing seccomp filter sandbox
>debug2: Network child is on pid 2002148
>debug3: preauth child monitor started
>debug3: privsep user:group 509:509 [preauth]
>debug1: permanently_set_uid: 509/509 [preauth]
>debug3: ssh_sandbox_child_debugging: installing SIGSYS handler [preauth]
>debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth]
>debug3: ssh_sandbox_child: attaching seccomp filter program [preauth]
>debug3: append_hostkey_type: ssh-rsa key not permitted by HostkeyAlgorithms [preauth]
>debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
>debug3: send packet: type 20 [preauth]
>debug1: SSH2_MSG_KEXINIT sent [preauth]
>debug3: receive packet: type 20 [preauth]
>debug1: SSH2_MSG_KEXINIT received [preauth]
>debug2: local server KEXINIT proposal [preauth]
>debug2: KEX algorithms: sntrup761x25519-sha512@openssh.com,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256 [preauth]
>debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
>debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
>debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
>debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
>debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
>debug2: compression ctos: none,zlib@openssh.com [preauth]
>debug2: compression stoc: none,zlib@openssh.com [preauth]
>debug2: languages ctos:  [preauth]
>debug2: languages stoc:  [preauth]
>debug2: first_kex_follows 0  [preauth]
>debug2: reserved 0  [preauth]
>debug2: peer client KEXINIT proposal [preauth]
>debug2: KEX algorithms: sntrup761x25519-sha512@openssh.com,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-c [preauth]
>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 [preauth]
>debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
>debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
>debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
>debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
>debug2: compression ctos: none,zlib@openssh.com,zlib [preauth]
>debug2: compression stoc: none,zlib@openssh.com,zlib [preauth]
>debug2: languages ctos:  [preauth]
>debug2: languages stoc:  [preauth]
>debug2: first_kex_follows 0  [preauth]
>debug2: reserved 0  [preauth]
>debug1: kex: algorithm: sntrup761x25519-sha512@openssh.com [preauth]
>debug1: kex: host key algorithm: ssh-ed25519 [preauth]
>debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
>debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth]
>debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
>debug3: receive packet: type 30 [preauth]
>debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
>debug3: mm_sshkey_sign: entering [preauth]
>debug3: mm_request_send: entering, type 6 [preauth]
>debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
>debug3: mm_request_receive_expect: entering, type 7 [preauth]
>debug3: mm_request_receive: entering [preauth]
>debug3: mm_request_receive: entering
>debug3: monitor_read: checking request 6
>debug3: mm_answer_sign: entering
>debug3: mm_answer_sign: ssh-ed25519 KEX signature len=83
>debug3: mm_request_send: entering, type 7
>debug2: monitor_read: 6 used once, disabling now
>debug3: send packet: type 31 [preauth]
>debug3: send packet: type 21 [preauth]
>debug2: ssh_set_newkeys: mode 1 [preauth]
>debug1: rekey out after 134217728 blocks [preauth]
>debug1: SSH2_MSG_NEWKEYS sent [preauth]
>debug1: Sending SSH2_MSG_EXT_INFO [preauth]
>debug3: send packet: type 7 [preauth]
>debug1: expecting SSH2_MSG_NEWKEYS [preauth]
>debug3: receive packet: type 21 [preauth]
>debug1: SSH2_MSG_NEWKEYS received [preauth]
>debug2: ssh_set_newkeys: mode 0 [preauth]
>debug1: rekey in after 134217728 blocks [preauth]
>debug1: KEX done [preauth]
>debug3: receive packet: type 5 [preauth]
>debug3: send packet: type 6 [preauth]
>debug3: receive packet: type 50 [preauth]
>debug1: userauth-request for user dtucker service ssh-connection method none [preauth]
>debug1: attempt 0 failures 0 [preauth]
>debug3: mm_getpwnamallow: entering [preauth]
>debug3: mm_request_send: entering, type 8 [preauth]
>debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
>debug3: mm_request_receive_expect: entering, type 9 [preauth]
>debug3: mm_request_receive: entering [preauth]
>debug3: mm_request_receive: entering
>debug3: monitor_read: checking request 8
>debug3: mm_answer_pwnamallow: entering
>debug2: parse_server_config_depth: config reprocess config len 166
>debug3: auth_shadow_acctexpired: today 19334 sp_expire -1 days left -19335
>debug3: account expiration disabled
>debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
>debug3: mm_request_send: entering, type 9
>debug2: monitor_read: 8 used once, disabling now
>debug2: input_userauth_request: setting up authctxt for dtucker [preauth]
>debug3: mm_inform_authserv: entering [preauth]
>debug3: mm_request_send: entering, type 4 [preauth]
>debug2: input_userauth_request: try method none [preauth]
>debug3: user_specific_delay: user specific delay 0.000ms [preauth]
>debug3: ensure_minimum_time_since: elapsed 1.182ms, delaying 7.482ms (requested 8.663ms) [preauth]
>debug3: mm_request_receive: entering
>debug3: monitor_read: checking request 4
>debug3: mm_answer_authserv: service=ssh-connection, style=
>debug2: monitor_read: 4 used once, disabling now
>debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive,hostbased" [preauth]
>debug3: send packet: type 51 [preauth]
>debug3: receive packet: type 50 [preauth]
>debug1: userauth-request for user dtucker service ssh-connection method hostbased [preauth]
>debug1: attempt 1 failures 0 [preauth]
>debug2: input_userauth_request: try method hostbased [preauth]
>debug1: userauth_hostbased: cuser dtucker chost gate.dtucker.net. pkalg ssh-ed25519 slen 83 [preauth]
>debug3: mm_key_allowed: entering [preauth]
>debug3: mm_request_send: entering, type 22 [preauth]
>debug3: mm_request_receive: entering
>debug3: monitor_read: checking request 22
>debug3: mm_answer_keyallowed: entering
>debug2: hostbased_key_allowed: chost gate.dtucker.net. resolvedname 192.168.32.1 ipaddr 192.168.32.1
>debug2: stripping trailing dot from chost gate.dtucker.net.
>debug2: auth_rhosts2: clientuser dtucker hostname gate.dtucker.net ipaddr gate.dtucker.net
>debug1: temporarily_use_uid: 500/500 (e=0/0)
>debug1: restore_uid: 0/0
>debug1: fd 4 clearing O_NONBLOCK
>debug3: Accepted for gate.dtucker.net [gate.dtucker.net] by /opt/openssh-9.1p1/etc/shosts.equiv.
>debug2: hostbased_key_allowed: access allowed by auth_rhosts2
>debug3: record_hostkey: found key type ED25519 in file /opt/openssh-9.1p1/etc/ssh_known_hosts:1
>debug3: load_hostkeys_file: loaded 1 keys from gate.dtucker.net
>debug1: temporarily_use_uid: 500/500 (e=0/0)
>debug1: restore_uid: 0/0
>debug1: check_key_in_hostfiles: key for gate.dtucker.net found at /opt/openssh-9.1p1/etc/ssh_known_hosts:1
>Accepted ED25519 public key SHA256:XzVjZOP7hMCfCIR+VB/5ba8h3R28Vbo57ZWQSd+e61w from dtucker@gate.dtucker.net
>debug3: mm_answer_keyallowed: hostbased authentication test: ED25519 key is allowed
>debug3: mm_request_send: entering, type 23
>debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
>debug3: mm_request_receive_expect: entering, type 23 [preauth]
>debug3: mm_request_receive: entering [preauth]
>debug3: mm_sshkey_verify: entering [preauth]
>debug3: mm_request_send: entering, type 24 [preauth]
>debug3: mm_request_receive: entering
>debug3: monitor_read: checking request 24
>debug3: mm_answer_keyverify: hostbased ED25519 signature using ssh-ed25519 verified
>debug3: mm_request_send: entering, type 25
>Accepted hostbased for dtucker from 192.168.32.1 port 49370 ssh2: ED25519 SHA256:XzVjZOP7hMCfCIR+VB/5ba8h3R28Vbo57ZWQSd+e61w
>debug1: monitor_child_preauth: user dtucker authenticated by privileged process
>debug3: mm_get_keystate: Waiting for new keys
>debug3: mm_request_receive_expect: entering, type 26
>debug3: mm_request_receive: entering
>debug3: mm_get_keystate: GOT new keys
>debug3: mm_sshkey_verify: waiting for MONITOR_ANS_KEYVERIFY [preauth]
>debug3: mm_request_receive_expect: entering, type 25 [preauth]
>debug3: mm_request_receive: entering [preauth]
>debug2: userauth_hostbased: authenticated 1 [preauth]
>debug3: user_specific_delay: user specific delay 0.000ms [preauth]
>debug3: ensure_minimum_time_since: elapsed 2.096ms, delaying 6.567ms (requested 8.663ms) [preauth]
>debug3: send packet: type 52 [preauth]
>debug3: mm_request_send: entering, type 26 [preauth]
>debug3: mm_send_keystate: Finished sending state [preauth]
>debug1: monitor_read_log: child log fd closed
>debug3: ssh_sandbox_parent_finish: finished
>User child is on pid 2002150
>debug1: permanently_set_uid: 500/500
>debug3: monitor_apply_keystate: packet_set_state
>debug2: ssh_set_newkeys: mode 0
>debug1: rekey in after 134217728 blocks
>debug2: ssh_set_newkeys: mode 1
>debug1: rekey out after 134217728 blocks
>debug1: ssh_packet_set_postauth: called
>debug3: ssh_packet_set_state: done
>debug3: notify_hostkeys: key 0: ssh-rsa SHA256:1FY5vg01dI2AWBK27OhD3XSKMgKwMz8vMj3cMIQPiDQ
>debug3: notify_hostkeys: key 1: ecdsa-sha2-nistp256 SHA256:umyxwtUf74bvjgCEjVR7qfS7klP6mKdCEpV82LA4vp4
>debug3: notify_hostkeys: key 2: ssh-ed25519 SHA256:XzVjZOP7hMCfCIR+VB/5ba8h3R28Vbo57ZWQSd+e61w
>debug3: notify_hostkeys: sent 3 hostkeys
>debug3: send packet: type 80
>debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
>debug3: sending debug message: Accepted for gate.dtucker.net [gate.dtucker.net] by /opt/openssh-9.1p1/etc/shosts.equiv.
>debug3: send packet: type 4
>debug1: Entering interactive session for SSH2.
>debug1: server_init_dispatch
>debug3: receive packet: type 90
>debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
>debug1: input_session_request
>debug1: channel 0: new [server-session]
>debug2: session_new: allocate (allocated 0 max 10)
>debug3: session_unused: session id 0 unused
>debug1: session_new: session 0
>debug1: session_open: channel 0
>debug1: session_open: session 0: link with channel 0
>debug1: server_input_channel_open: confirm session
>debug3: send packet: type 91
>debug3: receive packet: type 80
>debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
>debug3: receive packet: type 98
>debug1: server_input_channel_req: channel 0 request exec reply 1
>debug1: session_by_channel: session 0 channel 0
>debug1: session_input_channel_req: session 0 req exec
>Starting session: command for dtucker from 192.168.32.1 port 49370 id 0
>debug2: fd 3 setting TCP_NODELAY
>debug3: set_sock_tos: set socket 3 IP_TOS 0x20
>debug2: fd 8 setting O_NONBLOCK
>debug2: fd 7 setting O_NONBLOCK
>debug2: fd 10 setting O_NONBLOCK
>debug3: send packet: type 99
>debug2: channel 0: read 261 from efd 10
>debug2: channel 0: rwin 2097152 elen 261 euse 1
>debug2: channel 0: sent ext data 261
>debug2: channel 0: read failed rfd 8 maxlen 32768: Broken pipe
>debug2: channel 0: read failed
>debug2: chan_shutdown_read: channel 0: (i0 o0 sock -1 wfd 8 efd 10 [read])
>debug2: channel 0: input open -> drain
>debug2: channel 0: read 0 from efd 10
>debug2: channel 0: closing read-efd 10
>debug2: channel 0: ibuf empty
>debug2: channel 0: send eof
>debug3: send packet: type 96
>debug2: channel 0: input drain -> closed
>debug1: Received SIGCHLD.
>debug1: session_by_pid: pid 2002151
>debug1: session_exit_message: session 0 channel 0 pid 2002151
>debug2: channel 0: request exit-status confirm 0
>debug3: send packet: type 98
>debug1: session_exit_message: release channel 0
>debug2: channel 0: write failed
>debug2: chan_shutdown_write: channel 0: (i3 o0 sock -1 wfd 7 efd -1 [closed])
>debug2: channel 0: send eow
>debug3: send packet: type 98
>debug2: channel 0: output open -> closed
>debug2: channel 0: send close
>debug3: send packet: type 97
>debug3: channel 0: will not send data after close
>debug3: receive packet: type 97
>debug2: channel 0: rcvd close
>debug3: channel 0: will not send data after close
>debug2: channel 0: is dead
>debug2: channel 0: gc: notify user
>debug1: session_by_channel: session 0 channel 0
>debug1: session_close_by_channel: channel 0 child 0
>Close session: user dtucker from 192.168.32.1 port 49370 id 0
>debug3: session_unused: session id 0 unused
>debug2: channel 0: gc: user detached
>debug2: channel 0: is dead
>debug2: channel 0: garbage collecting
>debug1: channel 0: free: server-session, nchannels 1
>debug3: channel 0: status: The following connections are open:
>  #0 server-session (t4 r0 i3/0 o3/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1 io 0x00/0x00)
>
>debug3: receive packet: type 1
>Received disconnect from 192.168.32.1 port 49370:11: disconnected by user
>Disconnected from user dtucker 192.168.32.1 port 49370
>debug1: do_cleanup
>debug3: mm_request_receive: entering
>debug1: do_cleanup
>

Actions: View

Attachments on bug 3507: 3629 | 3630 | 3631 | 3632 | 3633 | 3634 | 3635 | 3636 | 3637 | 3638 | 3639