x/crypto/ssh: various tests fail on LUCI longtest builders #60981
Description
The LUCI longtest builders seem to be triggering some behavioral differences in the SSH tests.
TestValidTerminalMode fails with no obvious cause on linux-amd64:
session_test.go:266: missing output from echo SHELL $SHELL
=== RUN TestValidTerminalMode
session_test.go:261: echo SHELL $SHELL && stty -a && exit:
�]0;chrome-bot@luci-golang-ci-focal-us-central1-a-4-qopo: ~��[01;32mchrome-bot@luci-golang-ci-focal-us-central1-a-4-qopo�[00m:�[01;34m(Linux 20.04)�[00m:�[01;34m~�[00m$ SHELL /bin/bash
speed 38400 baud; rows 80; columns 40;
line = 0;
intr = ^C; quit = ^\; erase = ^?;
kill = ^U; eof = ^D; eol = ;
eol2 = ; swtch = ;
start = ^Q; stop = ^S; susp = ^Z;
rprnt = ^R; werase = ^W; lnext = ^V;
discard = ^O; min = 1; time = 0;
-parenb -parodd -cmspar cs8 -hupcl
-cstopb cread -clocal -crtscts
-ignbrk -brkint -ignpar -parmrk -inpck
-istrip -inlcr -igncr icrnl ixon -ixoff
-iuclc -ixany -imaxbel -iutf8
opost -olcuc -ocrnl onlcr -onocr -onlret
-ofill -ofdel nl0 cr0 tab0 bs0 vt0 ff0
isig icanon iexten -echo echoe echok
-echonl -noflsh -xcase -tostop -echoprt
echoctl echoke -flusho -extproc
logout
session_test.go:266: missing output from echo SHELL $SHELL
test_unix_test.go:229: sshd:
/b/s/w/ir/x/t/sshtest1967584695/sshd_config line 10: Deprecated option KeyRegenerationInterval
/b/s/w/ir/x/t/sshtest1967584695/sshd_config line 11: Deprecated option ServerKeyBits
/b/s/w/ir/x/t/sshtest1967584695/sshd_config line 17: Deprecated option RSAAuthentication
/b/s/w/ir/x/t/sshtest1967584695/sshd_config line 22: Deprecated option RhostsRSAAuthentication
debug1: inetd sockets after dupping: 3, 4
Connection from UNKNOWN port 65535 on /b/s/w/ir/x/t/unixConnection2051831659/ssh port 65535
debug1: Local version string SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.5
debug1: Remote protocol version 2.0, remote software version Go
debug1: no match: Go
debug2: fd 3 setting O_NONBLOCK
debug2: Network child is on pid 11975
debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ecdsa-sha2-nistp256 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug2: local server KEXINIT proposal [preauth]
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256 [preauth]
debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ecdsa-sha2-nistp256 [preauth]
debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
debug2: compression ctos: none,zlib@openssh.com [preauth]
debug2: compression stoc: none,zlib@openssh.com [preauth]
debug2: languages ctos: [preauth]
debug2: languages stoc: [preauth]
debug2: first_kex_follows 0 [preauth]
debug2: reserved 0 [preauth]
debug2: peer client KEXINIT proposal [preauth]
debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c [preauth]
debug2: host key algorithms: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss,ssh-ed25519 [preauth]
debug2: ciphers ctos: aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr [preauth]
debug2: ciphers stoc: aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr [preauth]
debug2: MACs ctos: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96 [preauth]
debug2: MACs stoc: hmac-sha2-512-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96 [preauth]
debug2: compression ctos: none [preauth]
debug2: compression stoc: none [preauth]
debug2: languages ctos: [preauth]
debug2: languages stoc: [preauth]
debug2: first_kex_follows 0 [preauth]
debug2: reserved 0 [preauth]
debug1: kex: algorithm: curve25519-sha256 [preauth]
debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
debug1: kex: client->server cipher: aes128-gcm@openssh.com MAC: compression: none [preauth]
debug1: kex: server->client cipher: aes128-gcm@openssh.com MAC: compression: none [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug2: monitor_read: 6 used once, disabling now
debug2: set_newkeys: mode 1 [preauth]
debug1: rekey out after 4294967296 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: Sending SSH2_MSG_EXT_INFO [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug2: set_newkeys: mode 0 [preauth]
debug1: rekey in after 4294967296 blocks [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user chrome-bot service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug2: parse_server_config_depth: config reprocess config len 734
reprocess config line 17: Deprecated option RSAAuthentication
reprocess config line 22: Deprecated option RhostsRSAAuthentication
debug2: monitor_read: 8 used once, disabling now
debug2: input_userauth_request: setting up authctxt for chrome-bot [preauth]
debug2: monitor_read: 4 used once, disabling now
debug2: monitor_read: 10 used once, disabling now
debug1: userauth_send_banner: sent [preauth]
debug2: input_userauth_request: try method none [preauth]
debug1: userauth-request for user chrome-bot service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug2: userauth_pubkey: valid user chrome-bot querying public key ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBGHDtsTSokVGDixBzO1WAKeexzcimznWLRw/N2eIczT1QuLTOZnRgzyy/CBML2LtsKvpaV3xkJzTG82H/YLKRtM= [preauth]
debug1: userauth_pubkey: test pkalg ecdsa-sha2-nistp256 pkblob ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
debug1: trying public key file /b/s/w/ir/x/t/sshtest1967584695/authorized_keys
debug1: fd 5 clearing O_NONBLOCK
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:1: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
'
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:1: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
'
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:2: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
'
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:2: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
'
debug1: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:5: matching key found: ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo
debug1: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:5: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Accepted key ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo found at /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:5
debug1: restore_uid: (unprivileged)
debug2: userauth_pubkey: authenticated 0 pkalg ecdsa-sha2-nistp256 [preauth]
Postponed publickey for chrome-bot from UNKNOWN port 65535 ssh2 [preauth]
debug1: userauth-request for user chrome-bot service ssh-connection method publickey [preauth]
debug1: attempt 2 failures 0 [preauth]
debug2: input_userauth_request: try method publickey [preauth]
debug2: userauth_pubkey: valid user chrome-bot attempting public key ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBGHDtsTSokVGDixBzO1WAKeexzcimznWLRw/N2eIczT1QuLTOZnRgzyy/CBML2LtsKvpaV3xkJzTG82H/YLKRtM= [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
debug1: trying public key file /b/s/w/ir/x/t/sshtest1967584695/authorized_keys
debug1: fd 5 clearing O_NONBLOCK
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:1: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
'
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:1: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
'
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:2: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
'
debug2: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:2: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
'
debug1: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:5: matching key found: ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo
debug1: /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:5: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Accepted key ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo found at /b/s/w/ir/x/t/sshtest1967584695/authorized_keys:5
debug1: restore_uid: (unprivileged)
debug1: auth_activate_options: setting new authentication options
Accepted publickey for chrome-bot from UNKNOWN port 65535 ssh2: ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo
debug1: monitor_child_preauth: chrome-bot has been authenticated by privileged process
debug1: auth_activate_options: setting new authentication options [preauth]
debug2: userauth_pubkey: authenticated 1 pkalg ecdsa-sha2-nistp256 [preauth]
debug1: monitor_read_log: child log fd closed
User child is on pid 11976
debug1: SELinux support disabled
debug2: set_newkeys: mode 0
debug1: rekey in after 4294967296 blocks
debug2: set_newkeys: mode 1
debug1: rekey out after 4294967296 blocks
debug1: ssh_packet_set_postauth: called
debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Entering interactive session for SSH2.
debug2: fd 7 setting O_NONBLOCK
debug2: fd 8 setting O_NONBLOCK
debug1: server_init_dispatch
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)
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
debug1: server_input_channel_req: channel 0 request pty-req reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req pty-req
debug1: Allocating pty.
debug2: session_new: allocate (allocated 0 max 10)
debug1: session_new: session 0
debug1: SELinux support disabled
Attempt to write login records by non-root user (aborting)
debug1: session_pty_req: session 0 alloc /dev/pts/0
debug1: server_input_channel_req: channel 0 request shell reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req shell
Starting session: shell on pts/0 for chrome-bot from UNKNOWN port 65535 id 0
debug2: channel 0: rfd 11 isatty
debug2: fd 11 setting O_NONBLOCK
debug1: Setting controlling tty using TIOCSCTTY.
debug2: channel 0: rcvd adjust 169
debug2: channel 0: rcvd adjust 17
debug2: channel 0: rcvd adjust 638
debug2: channel 0: rcvd adjust 8
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 11977
debug1: session_exit_message: session 0 channel 0 pid 11977
debug2: channel 0: request exit-status confirm 0
debug1: session_exit_message: release channel 0
debug2: channel 0: write failed
debug2: channel 0: chan_shutdown_write (i0 o0 sock -1 wfd 9 efd -1 [closed])
debug2: channel 0: send eow
debug2: channel 0: output open -> closed
debug1: session_by_tty: session 0 tty /dev/pts/0
debug2: channel 0: read<=0 rfd 11 len -1
debug1: session_pty_cleanup2: session 0 release /dev/pts/0
debug2: channel 0: read failed
debug2: channel 0: chan_shutdown_read (i0 o3 sock -1 wfd 11 efd -1 [closed])
debug2: channel 0: input open -> drain
debug2: channel 0: ibuf empty
debug2: channel 0: send eof
debug2: channel 0: input drain -> closed
debug2: channel 0: send close
debug2: notify_done: reading
Attempt to write login records by non-root user (aborting)
debug2: channel 0: rcvd 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 chrome-bot from UNKNOWN port 65535 id 0
debug2: channel 0: gc: user detached
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: server-session, nchannels 1
Connection closed by UNKNOWN port 65535
debug1: do_cleanup
debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
debug1: do_cleanup
debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
debug1: restore_uid: (unprivileged)
debug1: audit_event: unhandled event 12
--- FAIL: TestValidTerminalMode (1.20s)
And a variety of agent tests fail on Windows with errors like:
=== RUN TestAgent
client_test.go:43: C:\Windows\System32\OpenSSH\ssh-agent.exe -s failed: exit status 255
--- FAIL: TestAgent (0.06s)
After some experimentation, it's due to the environment being cleared on https://cs.opensource.google/go/x/crypto/+/master:ssh/agent/client_test.go;l=39;drc=fcc990c556feee8d78e4f1019de3b4416fce00d9. Leaving the PROGRAMDATA variable set produces a new failure mode:
=== RUN TestAgent
client_test.go:61: agent stderr:
client_test.go:72: could not find key SSH_AUTH_SOCK in ""
--- FAIL: TestAgent (0.14s)
Which I'm stumped by.