x/crypto/ssh: various tests fail on LUCI longtest builders

[heschi]

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.

cc @golang/security @bcmills @tklauser

[drakkan]

Hello,

TestValidTerminalMode may be fixed with this CL.

As for the agent tests, ssh-agent returns no output on Windows

Test cases expect an output like this:

SSH_AUTH_SOCK=/tmp/ssh-P65gpcqArqvH/agent.15541; export SSH_AUTH_SOCK;
SSH_AGENT_PID=15542; export SSH_AGENT_PID;
echo Agent pid 15542;

we should connect over a named pipe ( \.\pipe\openssh-ssh-agent) or maybe we can just skip agent tests on Windows

[heschi]

It sounds like agent support is just broken on Windows? In that case, skipping the tests seems unfortunate but reasonable.

[drakkan]

I have never used ssh-agent on Windows but as far as I can understand it is implemented as a Windows service and exposed on a named pipe, \.\pipe\openssh-ssh-agent by default.
On my Windows VM the agent service is disabled by default.

Therefore I think the agent support is just broken on Windows.

If adding something like https://github.com/Microsoft/go-winio as dependency is acceptable I can try to add agent support for Windows (cc @FiloSottile )

[gopherbot]

Change https://go.dev/cl/509035 mentions this issue: ssh: disable agent tests on Windows

[drakkan]

@heschi this issue is about test failures. I opened a new issue to track agent support on Windows. I think we can close this one

[heschi]

Yep! https://ci.chromium.org/p/golang is green, thanks for the help.