Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

x/crypto/ssh/test: tests fail on macOS 14 #64959

Open
dmitshur opened this issue Jan 4, 2024 · 18 comments
Open

x/crypto/ssh/test: tests fail on macOS 14 #64959

dmitshur opened this issue Jan 4, 2024 · 18 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin
Milestone

Comments

@dmitshur
Copy link
Contributor

dmitshur commented Jan 4, 2024

=== RUN   TestAgentForward
    exec.go:88: test timed out while running command: /usr/sbin/sshd -f /Users/swarming/.swarming/w/ir/x/t/sshtest3423651030/sshd_config -i -e
panic: test timed out after 10m0s
running tests:
	TestAgentForward (10m0s)
[...]

See https://ci.chromium.org/ui/p/golang/builders/ci/x_crypto-gotip-darwin-amd64-longtest/b8759816251100556177/test-results for full details.

It doesn't seem to reproduce for me locally:

$ go test -v ./ssh/test -run=^TestAgentForward$ 
=== RUN   TestAgentForward
--- PASS: TestAgentForward (0.79s)
PASS
ok  	golang.org/x/crypto/ssh/test	1.355s

Nor on the old dashboard, though it's hard to be sure whether this test is running or being skipped there.

This failure is blocking the automated monthly tagging workflow, so adding Soon label. If this ends up taking a while to figure out and fix, we might want to temporarily skip the test since it's happening since the builder was added in LUCI, to unblock the rest of the tagging.

CC @drakkan, @golang/security, @prattmic.

@dmitshur dmitshur added OS-Darwin Builders x/build issues (builders, bots, dashboards) NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Soon This needs to be done soon. (regressions, serious bugs, outages) labels Jan 4, 2024
@dmitshur dmitshur added this to the Unreleased milestone Jan 4, 2024
@gopherbot
Copy link

Change https://go.dev/cl/554115 mentions this issue: ssh: skip TestAgentForward on macOS

@drakkan
Copy link
Member

drakkan commented Jan 4, 2024

I can't reproduce it locally either. Not sure if related to #63937
I've sent a CL to skip this test on macOS for now

@gopherbot
Copy link

Change https://go.dev/cl/554062 mentions this issue: ssh/test: avoid leaking a net.UnixConn in server.TryDialWithAddr

@bcmills
Copy link
Contributor

bcmills commented Jan 5, 2024

This doesn't quite look like a symptom of #63937: there is nothing to suggest that the underlying sshd process has actually exited at the point where the hang occurs, and even if it has, there is a leaked net.UnixConn that might be holding the connection open if its finalizer is for some reason not being run.

@bcmills
Copy link
Contributor

bcmills commented Jan 5, 2024

The output for the pending change in https://go.dev/cl/554062 shows a more interesting failure mode:

=== RUN   TestAgentForward
    agent_unix_test.go:37: NewSession: ssh: unexpected packet in response to channel open: <nil>
    test_unix_test.go:235: sshd:
        Error reading managed configuration (2: No such file or directory). Proceeding with default configuration.
        /Volumes/Work/s/w/ir/x/t/sshtest1028730279/sshd_config line 10: Deprecated option KeyRegenerationInterval
        /Volumes/Work/s/w/ir/x/t/sshtest1028730279/sshd_config line 11: Deprecated option ServerKeyBits
        /Volumes/Work/s/w/ir/x/t/sshtest1028730279/sshd_config line 17: Deprecated option RSAAuthentication
        /Volumes/Work/s/w/ir/x/t/sshtest1028730279/sshd_config line 22: Deprecated option RhostsRSAAuthentication
        debug1: inetd sockets after dupping: 4, 5
        BSM audit: getaddrinfo failed for UNKNOWN: nodename nor servname provided, or not known
        Connection from UNKNOWN port 65535 on /Volumes/Work/s/w/ir/x/t/unixConnection1298930634/ssh port 65535
        debug1: Local version string SSH-2.0-OpenSSH_9.3
        debug1: Remote protocol version 2.0, remote software version Go
        debug1: compat_banner: no match: Go
        debug2: fd 4 setting O_NONBLOCK
        debug2: Network child is on pid 81555
        debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-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: 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,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-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,kex-strict-c-v00@openssh.com [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-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96 [preauth]
        debug2: MACs stoc: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-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: <implicit> compression: none [preauth]
        debug1: kex: server->client cipher: aes128-gcm@openssh.com MAC: <implicit> compression: none [preauth]
        debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
        debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
        debug2: monitor_read: 6 used once, disabling now
        debug2: ssh_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: ssh_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 848
        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: publickey test pkalg ecdsa-sha2-nistp256 pkblob ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo [preauth]
        debug1: temporarily_use_uid: 502/20 (e=502/20)
        debug1: trying public key file /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys
        debug1: fd 6 clearing O_NONBLOCK
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:1: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCitzS2KiRQTccfVApb0mbPpo1lt29JjeLBYAehXHWfQ+w8sXpd8e04n/020spx1R94yg+v0NjXyh2RNFXNBYdhNei33VJxUeKNlExaecvW2yxfuZqka+ZxT1aI8zrAsjh3Rwc6wayAJS4RwZuzlDv4jZitWqwD+mb/22Zwq/WSs4YX5dUHDklfdWSVnoBfue8K/00n8f5yMTdJvFF0qAJwf9spPEHla0lYcozJk64CO5lRkqfLor4UnsXXOiA7aRIoaUSKa+rlhiqt1EMGYiBjblPt4SwMelGGU2UfywPb4d85gpQ/s8SBARbpPxNVs2IbHDMwj70P3uZc74M3c4VJ
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:1: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAABAQCitzS2KiRQTccfVApb0mbPpo1lt29JjeLBYAehXHWfQ+w8sXpd8e04n/020spx1R94yg+v0NjXyh2RNFXNBYdhNei33VJxUeKNlExaecvW2yxfuZqka+ZxT1aI8zrAsjh3Rwc6wayAJS4RwZuzlDv4jZitWqwD+mb/22Zwq/WSs4YX5dUHDklfdWSVnoBfue8K/00n8f5yMTdJvFF0qAJwf9spPEHla0lYcozJk64CO5lRkqfLor4UnsXXOiA7aRIoaUSKa+rlhiqt1EMGYiBjblPt4SwMelGGU2UfywPb4d85gpQ/s8SBARbpPxNVs2IbHDMwj70P3uZc74M3c4VJ
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:2: check options: 'ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAID7d/uFLuDlRbBc4ZVOsx+GbHKuOrPtLHFvHsjWPwO+/
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:2: advance: 'AAAAC3NzaC1lZDI1NTE5AAAAID7d/uFLuDlRbBc4ZVOsx+GbHKuOrPtLHFvHsjWPwO+/
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:3: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC+D11D0hEbn2Vglv4YRJ8pZNyHjIGmvth3DWOQrq++2vH2MujmGQDxfr4SVE9GpMBlKU3lwGbpgIBxAg6yZcNSfo6PWVU9ACg6NMFO+yMzc2MaG+/naQdNjSewywF5j2rkNO2XOaViRVSrZroe2B/aY2LTV0jDl8nu5NOjwRs1/s7SLe5z1rw/X0dpmXk0qJY3gQhmR8HZZ1dhEkJUGwaBCPd0T8asSYf1Ag2rUD4aQ28r3q69mbwfWOOa6rMemVZruUV5dzHwVNVNtVv+ImtnYtz8m8g+K0plaGptHn3KsaOnASkh3tujhaE7kvc4HR9Igli9+76jhZie3h/dTN5z
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:3: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAABAQC+D11D0hEbn2Vglv4YRJ8pZNyHjIGmvth3DWOQrq++2vH2MujmGQDxfr4SVE9GpMBlKU3lwGbpgIBxAg6yZcNSfo6PWVU9ACg6NMFO+yMzc2MaG+/naQdNjSewywF5j2rkNO2XOaViRVSrZroe2B/aY2LTV0jDl8nu5NOjwRs1/s7SLe5z1rw/X0dpmXk0qJY3gQhmR8HZZ1dhEkJUGwaBCPd0T8asSYf1Ag2rUD4aQ28r3q69mbwfWOOa6rMemVZruUV5dzHwVNVNtVv+ImtnYtz8m8g+K0plaGptHn3KsaOnASkh3tujhaE7kvc4HR9Igli9+76jhZie3h/dTN5z
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:4: check options: 'ssh-dss AAAAB3NzaC1kc3MAAACBAPo8NITJeIj2N82z3ta4zjoxIMJiU6pbDzRqM3XoCiG0GdyzVgGUeT/91A68Jg6xhoT6A2LHaO2hGPBeEOxzbn8ipBtTVqFvuYHz+uxogtEYhsDlYfcSAW0mZcWi8PPeJ/oXpPO+EWkeAlGYthVHxyqx7MveERk6++zaIfsyiuTHAAAAFQCRw5w/NvpcYdn2+DzLCIml7nQLAQAAAIBBF/tD+Jo9Gfjdmq5SF3pbC+KupSP62Qi7p5XadlZiZcuWoVAoTLhN6OXtaTLOvY5Ji9tcvOjtM3EsqhaivqKmzSmFg88zJeV3XiuO6FPbgKuE7O4syEN24wOLTfbAMhkbhj4rsSVTw65+fxKPlaB7yvoA2aZWCYV/KesWF1gKeAAAAIEA3ucGJ93/Mx4q4eKRDxcWD3QzWyqpbRVRRV1Vmih9Ha/qC994nJFzDQIdjxDIT2Rk2AGzMqFEB68Zc3O+Wcsmz5eWWzEwFxaTwOGWTyDqsDRLm3fD+QYjnOwuxb0Kce+gWI8voWcqC9cyRm09jGzu2Ab3Bhtpg8JJ8L7gS3MRZK4=
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:4: advance: 'AAAAB3NzaC1kc3MAAACBAPo8NITJeIj2N82z3ta4zjoxIMJiU6pbDzRqM3XoCiG0GdyzVgGUeT/91A68Jg6xhoT6A2LHaO2hGPBeEOxzbn8ipBtTVqFvuYHz+uxogtEYhsDlYfcSAW0mZcWi8PPeJ/oXpPO+EWkeAlGYthVHxyqx7MveERk6++zaIfsyiuTHAAAAFQCRw5w/NvpcYdn2+DzLCIml7nQLAQAAAIBBF/tD+Jo9Gfjdmq5SF3pbC+KupSP62Qi7p5XadlZiZcuWoVAoTLhN6OXtaTLOvY5Ji9tcvOjtM3EsqhaivqKmzSmFg88zJeV3XiuO6FPbgKuE7O4syEN24wOLTfbAMhkbhj4rsSVTw65+fxKPlaB7yvoA2aZWCYV/KesWF1gKeAAAAIEA3ucGJ93/Mx4q4eKRDxcWD3QzWyqpbRVRRV1Vmih9Ha/qC994nJFzDQIdjxDIT2Rk2AGzMqFEB68Zc3O+Wcsmz5eWWzEwFxaTwOGWTyDqsDRLm3fD+QYjnOwuxb0Kce+gWI8voWcqC9cyRm09jGzu2Ab3Bhtpg8JJ8L7gS3MRZK4=
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:12: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:12: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:13: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:13: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
        '
        debug1: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:14: matching key found: ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo
        debug1: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:14: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
        Accepted key ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo found at /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:14
        debug2: auth_check_authkeys_file: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys: processed 14/14 lines
        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: 502/20 (e=502/20)
        debug1: trying public key file /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys
        debug1: fd 6 clearing O_NONBLOCK
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:1: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCitzS2KiRQTccfVApb0mbPpo1lt29JjeLBYAehXHWfQ+w8sXpd8e04n/020spx1R94yg+v0NjXyh2RNFXNBYdhNei33VJxUeKNlExaecvW2yxfuZqka+ZxT1aI8zrAsjh3Rwc6wayAJS4RwZuzlDv4jZitWqwD+mb/22Zwq/WSs4YX5dUHDklfdWSVnoBfue8K/00n8f5yMTdJvFF0qAJwf9spPEHla0lYcozJk64CO5lRkqfLor4UnsXXOiA7aRIoaUSKa+rlhiqt1EMGYiBjblPt4SwMelGGU2UfywPb4d85gpQ/s8SBARbpPxNVs2IbHDMwj70P3uZc74M3c4VJ
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:1: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAABAQCitzS2KiRQTccfVApb0mbPpo1lt29JjeLBYAehXHWfQ+w8sXpd8e04n/020spx1R94yg+v0NjXyh2RNFXNBYdhNei33VJxUeKNlExaecvW2yxfuZqka+ZxT1aI8zrAsjh3Rwc6wayAJS4RwZuzlDv4jZitWqwD+mb/22Zwq/WSs4YX5dUHDklfdWSVnoBfue8K/00n8f5yMTdJvFF0qAJwf9spPEHla0lYcozJk64CO5lRkqfLor4UnsXXOiA7aRIoaUSKa+rlhiqt1EMGYiBjblPt4SwMelGGU2UfywPb4d85gpQ/s8SBARbpPxNVs2IbHDMwj70P3uZc74M3c4VJ
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:2: check options: 'ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAID7d/uFLuDlRbBc4ZVOsx+GbHKuOrPtLHFvHsjWPwO+/
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:2: advance: 'AAAAC3NzaC1lZDI1NTE5AAAAID7d/uFLuDlRbBc4ZVOsx+GbHKuOrPtLHFvHsjWPwO+/
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:3: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC+D11D0hEbn2Vglv4YRJ8pZNyHjIGmvth3DWOQrq++2vH2MujmGQDxfr4SVE9GpMBlKU3lwGbpgIBxAg6yZcNSfo6PWVU9ACg6NMFO+yMzc2MaG+/naQdNjSewywF5j2rkNO2XOaViRVSrZroe2B/aY2LTV0jDl8nu5NOjwRs1/s7SLe5z1rw/X0dpmXk0qJY3gQhmR8HZZ1dhEkJUGwaBCPd0T8asSYf1Ag2rUD4aQ28r3q69mbwfWOOa6rMemVZruUV5dzHwVNVNtVv+ImtnYtz8m8g+K0plaGptHn3KsaOnASkh3tujhaE7kvc4HR9Igli9+76jhZie3h/dTN5z
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:3: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAABAQC+D11D0hEbn2Vglv4YRJ8pZNyHjIGmvth3DWOQrq++2vH2MujmGQDxfr4SVE9GpMBlKU3lwGbpgIBxAg6yZcNSfo6PWVU9ACg6NMFO+yMzc2MaG+/naQdNjSewywF5j2rkNO2XOaViRVSrZroe2B/aY2LTV0jDl8nu5NOjwRs1/s7SLe5z1rw/X0dpmXk0qJY3gQhmR8HZZ1dhEkJUGwaBCPd0T8asSYf1Ag2rUD4aQ28r3q69mbwfWOOa6rMemVZruUV5dzHwVNVNtVv+ImtnYtz8m8g+K0plaGptHn3KsaOnASkh3tujhaE7kvc4HR9Igli9+76jhZie3h/dTN5z
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:4: check options: 'ssh-dss AAAAB3NzaC1kc3MAAACBAPo8NITJeIj2N82z3ta4zjoxIMJiU6pbDzRqM3XoCiG0GdyzVgGUeT/91A68Jg6xhoT6A2LHaO2hGPBeEOxzbn8ipBtTVqFvuYHz+uxogtEYhsDlYfcSAW0mZcWi8PPeJ/oXpPO+EWkeAlGYthVHxyqx7MveERk6++zaIfsyiuTHAAAAFQCRw5w/NvpcYdn2+DzLCIml7nQLAQAAAIBBF/tD+Jo9Gfjdmq5SF3pbC+KupSP62Qi7p5XadlZiZcuWoVAoTLhN6OXtaTLOvY5Ji9tcvOjtM3EsqhaivqKmzSmFg88zJeV3XiuO6FPbgKuE7O4syEN24wOLTfbAMhkbhj4rsSVTw65+fxKPlaB7yvoA2aZWCYV/KesWF1gKeAAAAIEA3ucGJ93/Mx4q4eKRDxcWD3QzWyqpbRVRRV1Vmih9Ha/qC994nJFzDQIdjxDIT2Rk2AGzMqFEB68Zc3O+Wcsmz5eWWzEwFxaTwOGWTyDqsDRLm3fD+QYjnOwuxb0Kce+gWI8voWcqC9cyRm09jGzu2Ab3Bhtpg8JJ8L7gS3MRZK4=
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:4: advance: 'AAAAB3NzaC1kc3MAAACBAPo8NITJeIj2N82z3ta4zjoxIMJiU6pbDzRqM3XoCiG0GdyzVgGUeT/91A68Jg6xhoT6A2LHaO2hGPBeEOxzbn8ipBtTVqFvuYHz+uxogtEYhsDlYfcSAW0mZcWi8PPeJ/oXpPO+EWkeAlGYthVHxyqx7MveERk6++zaIfsyiuTHAAAAFQCRw5w/NvpcYdn2+DzLCIml7nQLAQAAAIBBF/tD+Jo9Gfjdmq5SF3pbC+KupSP62Qi7p5XadlZiZcuWoVAoTLhN6OXtaTLOvY5Ji9tcvOjtM3EsqhaivqKmzSmFg88zJeV3XiuO6FPbgKuE7O4syEN24wOLTfbAMhkbhj4rsSVTw65+fxKPlaB7yvoA2aZWCYV/KesWF1gKeAAAAIEA3ucGJ93/Mx4q4eKRDxcWD3QzWyqpbRVRRV1Vmih9Ha/qC994nJFzDQIdjxDIT2Rk2AGzMqFEB68Zc3O+Wcsmz5eWWzEwFxaTwOGWTyDqsDRLm3fD+QYjnOwuxb0Kce+gWI8voWcqC9cyRm09jGzu2Ab3Bhtpg8JJ8L7gS3MRZK4=
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:12: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:12: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQC8A6FGHDiWCSREAXCq6yBfNVr0xCVG2CzvktFNRpue+RXrGs/2a6ySEJQb3IYquw7HlJgu6fg3WIWhOmHCjfpG0PrL4CRwbqQ2LaPPXhJErWYejcD8Di00cF3677+G10KMZk9RXbmHtuBFZT98wxg8j+ZsBMqGM1+7yrWUvynswQ==
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:13: check options: 'ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
        '
        debug2: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:13: advance: 'AAAAB3NzaC1yc2EAAAADAQABAAAAgQDBrjzJ9YWLe4h2rO5/1fsLZnF95r8hprDTMjAe52kXxT3ZZUiILmWgS5bX45pWLdRZ8gSNYxXW0cbKysc7C3BzfgE8ImomSdRA78q0NMFMng+vKHDVtY8L330vNr7KsJN01BgHOhE5coTFmA8WH2lMyLnCqkcO45DapkUgQjeVPQ==
        '
        debug1: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:14: matching key found: ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo
        debug1: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:14: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
        Accepted key ECDSA SHA256:DbuSF5a8c3JMmpZ5WiK8oLAx97Uu8zIAFReb/NyTPuo found at /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys:14
        debug2: auth_check_authkeys_file: /Volumes/Work/s/w/ir/x/t/sshtest1028730279/authorized_keys: processed 14/14 lines
        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: user chrome-bot 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
        BSM audit: bsm_audit_session_setup: setaudit_addr failed: Invalid argument
        debug1: do_cleanup
--- FAIL: TestAgentForward (0.11s)

@bcmills
Copy link
Contributor

bcmills commented Jan 5, 2024

Some interesting differences vs. a gomote on a legacy TryBot:

  • The LUCI log shows an extra line at the beginning:
    Error reading managed configuration (2: No such file or directory). Proceeding with default configuration.
    Unfortunately, ["Error reading managed configuration"] is currently a Googlewhack. 😅

  • The LUCI log shows debug1: do_cleanup where the gomote log shows User child is on pid XXXX.

I suspect that the Proceeding with default configuration. line is telling us the nature of the problem: I suspect that somehow we are picking up a default configuration beyond what is in the sshd_config provided by the test, but I can't seem to get gomote to give me a LUCI instance (@cagedmantis, maybe?), and man sshd on the legacy TryBot doesn't indicate any kind of option that would correspond to that.

@bcmills
Copy link
Contributor

bcmills commented Jan 5, 2024

Hmm. The source of that very unique error message seems to be here:
https://github.com/apple-open-source/macos/blob/8a7a6aab534a6ca275e9354cc818b7a1d527daa6/OpenSSH/openssh/sshd.c#L1602-L1623

But it looks like the “default configuration” is just “not doing the custom Apple fork thing”, so maybe that's not the problem after all.

Still, there are enough #ifdef __APPLE_… in that file that I do wonder if Apple has just broken our use of sshd with some recent vendor patch. 🤔

@gopherbot
Copy link

Change https://go.dev/cl/554077 mentions this issue: ssh/test: skip tests on darwin that fail on the darwin-amd64-longtest LUCI builder

@dmitshur
Copy link
Contributor Author

dmitshur commented Jan 6, 2024

I tried go test -v ./ssh/test -run=^TestAgentForward$ on another Mac which is closer to a "default out of the box" setup, running macOS 14.2.1 (23C71), and the issue reproduces on it (i.e., it stalls). Its sshd is located at /usr/sbin/sshd and its version is OpenSSH_9.4p1, LibreSSL 3.3.6.

@drakkan You mentioned having OpenSSH_9.0p1, LibreSSL 3.3.6. Which macOS version is that on?

@dmitshur dmitshur removed the Builders x/build issues (builders, bots, dashboards) label Jan 6, 2024
@drakkan
Copy link
Member

drakkan commented Jan 6, 2024

@dmitshur I have a 2017 iMac with macOS 13.6.3 (22G436)

@dmitshur dmitshur changed the title x/crypto/ssh/test: TestAgentForward fails on x_crypto-gotip-darwin-amd64-longtest LUCI builder x/crypto/ssh/test: TestAgentForward fails on macOS 14 Jan 7, 2024
gopherbot pushed a commit to golang/crypto that referenced this issue Jan 8, 2024
For golang/go#64959.

Change-Id: I2153166f4960058cdc2b82ae34ca250dcc6ba1c6
Cq-Include-Trybots: luci.golang.try:x_crypto-gotip-linux-amd64-longtest,x_crypto-gotip-windows-amd64-longtest
Reviewed-on: https://go-review.googlesource.com/c/crypto/+/554062
Run-TryBot: Bryan Mills <bcmills@google.com>
Auto-Submit: Bryan Mills <bcmills@google.com>
Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
@bcmills bcmills changed the title x/crypto/ssh/test: TestAgentForward fails on macOS 14 x/crypto/ssh/test: tests fail on macOS 14 Jan 8, 2024
@bcmills
Copy link
Contributor

bcmills commented Jan 8, 2024

This is now mitigated by skipping the failing tests at head. Leaving open to investigate the root cause and hopefully remove the skips.

gopherbot pushed a commit to golang/crypto that referenced this issue Jan 8, 2024
… LUCI builder

We don't yet understand why these tests fail, but the Apple sshd seems
to have some non-trivial vendor patches, so it is plausibly a
platform-specific bug in the test. Let's skip that failure mode on the
whole platform until/unless someone has time to reproduce and
investigate the failure.

For golang/go#64959.

Cq-Include-Trybots: luci.golang.try:x_crypto-gotip-darwin-amd64-longtest,x_crypto-gotip-linux-amd64-longtest,x_crypto-gotip-windows-amd64-longtest
Change-Id: I9e43579469de3fe9329c093b5916bbed0edd3751
Reviewed-on: https://go-review.googlesource.com/c/crypto/+/554077
Reviewed-by: Dmitri Shuralyov <dmitshur@golang.org>
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
Reviewed-by: Nicola Murino <nicola.murino@gmail.com>
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Auto-Submit: Bryan Mills <bcmills@google.com>
@bcmills bcmills removed the Soon This needs to be done soon. (regressions, serious bugs, outages) label Jan 8, 2024
@bcmills
Copy link
Contributor

bcmills commented Jan 8, 2024

I wonder if this is related to the race reported in #64094. 🤔

@drakkan
Copy link
Member

drakkan commented Jan 8, 2024

I wonder if this is related to the race reported in #64094. 🤔

The code for tcpip and streamlocal forwarding is not covered in test cases

@drakkan
Copy link
Member

drakkan commented Jan 9, 2024

Hello, is there gomote access to a macOS 14 instance? This would make testing much easier. Thank you

@drakkan
Copy link
Member

drakkan commented Jan 20, 2024

Hello,

I was finally able to get access to macOS 14 (using QEMU/KVM on Linux).

This error

Error reading managed configuration (2: No such file or directory). Proceeding with default configuration.

does not seem relevant. The managed configuration directory resolves to /private/var/db/ManagedConfigurationFiles which is empty in my installation.

The relevant error looks like this and occurs every time we open a session

BSM audit: bsm_audit_session_setup: setaudit_addr failed: Invalid argument
Could not create new audit session

It is generated here.

In previous versions, this error was not fatal.

In the latest version Apple added

#ifdef __APPLE__
	if (rc < 0 && e != EPERM)
		fatal("Could not create new audit session");
#endif

I guess the error happens because we start sshd in inetd mode like this

cmd := testenv.Command(s.t, sshd, "-f", s.configfile, "-i", "-e")

if we start sshd in TCP mode the error does not happen and it also work it we connect to sshd managed by launchd so the issue seems limited to our test cases.

I'm not sure how to proceed, maybe we can start sshd in tcp mode on Darwin (or all platforms), this will complicate things. Please let me know what you think. Thank you

@bcmills
Copy link
Contributor

bcmills commented Feb 15, 2024

It sounds like Apple has just completely broken inetd support in their sshd? In that case, we should probably ask someone at Apple what they intend to be used instead.

Is it even feasible to start sshd in TCP mode? It would need to pick its own port and omcmunicate that somehow, but I don't see a standard flag that does that.

@drakkan
Copy link
Member

drakkan commented Feb 16, 2024

We generate a config file on the fly, we can set the port there. We should first find a free port from Go and then set it in the sshd configuration file, this could be problematic with parallel tests, if we want to proceed this way perhaps it is better to add a TestMain and start the server(s) there.

I guess Apple cares about launchd, not inetd

@bcmills
Copy link
Contributor

bcmills commented Feb 16, 2024

We should first find a free port from Go and then set it in the sshd configuration file, this could be problematic with parallel tests

It's problematic period. In a heavily loaded CI environment, we cannot assume that there aren't other processes running concurrently that may be opening previously-free ports.

The usual solutions are to have the program allocate its own port (and log that for the consumer to connect to), or to avoid communicating over numeric ports entirely (instead using an inetd-style API, a Unix domain socket, or similar API that avoids use of the global port namespace).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Darwin
Projects
None yet
Development

No branches or pull requests

4 participants