go icon indicating copy to clipboard operation
go copied to clipboard
Published 3 weeks ago • verified publisher icon golang

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

Open dmitshur opened this issue 1 year ago • 16 comments 

=== 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 avatar Jan 04 '24 17:01 dmitshur

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

gopherbot avatar Jan 04 '24 17:01 gopherbot

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

drakkan avatar Jan 04 '24 17:01 drakkan

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

gopherbot avatar Jan 05 '24 20:01 gopherbot

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 avatar Jan 05 '24 20:01 bcmills

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,[email protected],[email protected],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: [email protected],curve25519-sha256,[email protected],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,[email protected],[email protected],ecdsa-sha2-nistp256 [preauth]
        debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
        debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
        debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
        debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
        debug2: compression ctos: none,[email protected] [preauth]
        debug2: compression stoc: none,[email protected] [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,[email protected],ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c,[email protected] [preauth]
        debug2: host key algorithms: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-rsa,ssh-dss,ssh-ed25519 [preauth]
        debug2: ciphers ctos: [email protected],[email protected],[email protected],aes128-ctr,aes192-ctr,aes256-ctr [preauth]
        debug2: ciphers stoc: [email protected],[email protected],[email protected],aes128-ctr,aes192-ctr,aes256-ctr [preauth]
        debug2: MACs ctos: [email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96 [preauth]
        debug2: MACs stoc: [email protected],[email protected],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: [email protected] MAC: <implicit> compression: none [preauth]
        debug1: kex: server->client cipher: [email protected] 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 avatar Jan 05 '24 21:01 bcmills

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 avatar Jan 05 '24 22:01 bcmills

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. 🤔

bcmills avatar Jan 05 '24 22:01 bcmills

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

gopherbot avatar Jan 05 '24 23:01 gopherbot

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 avatar Jan 06 '24 20:01 dmitshur

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

drakkan avatar Jan 06 '24 20:01 drakkan

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

bcmills avatar Jan 08 '24 16:01 bcmills

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

bcmills avatar Jan 08 '24 16:01 bcmills

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 avatar Jan 08 '24 17:01 drakkan

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

drakkan avatar Jan 09 '24 16:01 drakkan

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

drakkan avatar Jan 20 '24 17:01 drakkan

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.

bcmills avatar Feb 15 '24 22:02 bcmills

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

drakkan avatar Feb 16 '24 17:02 drakkan

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).

bcmills avatar Feb 16 '24 20:02 bcmills