TestRootX11ForwardPermissions flakiness

[r0mant]

https://github.com/gravitational/teleport/actions/runs/3578384302/jobs/6018487002

5244 tests passed. 2 failed, 97 skipped
===================================================
FAIL: github.com/gravitational/teleport/lib/srv/regular
FAIL: github.com/gravitational/teleport/lib/srv/regular.TestRootX11ForwardPermissions
===================================================
OUTPUT github.com/gravitational/teleport/lib/srv/regular.TestRootX11ForwardPermissions
===================================================
=== RUN   TestRootX11ForwardPermissions
=== PAUSE TestRootX11ForwardPermissions
=== CONT  TestRootX11ForwardPermissions
=== CONT  TestRootX11ForwardPermissions
    sshserver_test.go:976: 
        	Error Trace:	/__w/teleport/teleport/lib/srv/regular/sshserver_test.go:976
        	Error:      	Received unexpected error:
        	            	user: unknown userid 1000
        	Test:       	TestRootX11ForwardPermissions
{"caller":"srv/sess.go:180","component":"session:node","level":"debug","message":"Closing Session Registry.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"srv/heartbeat.go:286","component":"node:beat","level":"debug","message":"Heartbeat exited.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"sshutils/server.go:397","component":"ssh:node","level":"debug","message":"Server 127.0.0.1:39317 has closed.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"sshutils/server.go:490","component":"ssh:node","level":"debug","message":"Closed connection 127.0.0.1:34118.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"auth/grpcserver.go:167","component":"auth:grpc","level":"debug","message":"Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"backend/buffer.go:280","component":"buffer","level":"debug","message":"Removing watcher 0xc002c7e3c0 via external close.","timestamp":"2022-11-29T22:09:30Z"}
--- FAIL: TestRootX11ForwardPermissions (2.41s)
{"caller":"backend/buffer.go:280","component":"buffer","level":"debug","message":"Removing watcher 0xc0010c6180 via external close.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"backend/buffer.go:283","component":"buffer","level":"debug","message":"Could not find watcher Watcher(name=auth, prefixes=/locks, capacity=1024, size=0).","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"backend/buffer.go:262","component":"buffer","level":"debug","message":"Add Watcher(name=c7caa7af-f8af-488d-a4a2-9ada9cea6eb7.localhost, prefixes=/locks, capacity=128, size=0).","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"native/native.go:219","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Node with principals: [00000000-0000-0000-0000-000000000000.localhost 00000000-0000-0000-0000-000000000000 localhost.localhost localhost 127.0.0.1 ::1].","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"tlsca/ca.go:886","common_name":"00000000-0000-0000-0000-000000000000.localhost","component":"ca","dns_names":[],"level":"info","locality":[],"message":"Generating TLS certificate {0xc001793620 0xc000708a80 1.3.9999.1.7=#13096c6f63616c686f7374,CN=00000000-0000-0000-0000-000000000000.localhost,O=Node,POSTALCODE=null,STREET= 1994-04-02 00:00:00 +0000 UTC [] [] 5 []}.","not_after":"1994-04-02T00:00:00Z","org":["Node"],"org_unit":[],"timestamp":"2022-11-29T22:09:30Z"}
{"caller":"srv/heartbeat.go:284","component":"node:beat","level":"debug","message":"Asked check out of cycle","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"native/native.go:219","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Node with principals: [00000000-0000-0000-0000-000000000000.localhost 00000000-0000-0000-0000-000000000000 localhost.localhost localhost 127.0.0.1 ::1].","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"tlsca/ca.go:886","common_name":"00000000-0000-0000-0000-000000000000.localhost","component":"ca","dns_names":[],"level":"info","locality":[],"message":"Generating TLS certificate {0xc001792d20 0xc00076a8b0 1.3.9999.1.7=#13096c6f63616c686f7374,CN=00000000-0000-0000-0000-000000000000.localhost,O=Node,POSTALCODE=null,STREET= 1994-04-02 00:00:00 +0000 UTC [] [] 5 []}.","not_after":"1994-04-02T00:00:00Z","org":["Node"],"org_unit":[],"timestamp":"2022-11-29T22:09:30Z"}
{"caller":"native/native.go:249","component":"keygen","level":"debug","message":"generated user key for [root -teleport-internal-join] with expiry on (449885100) 1984-04-04 00:05:00 +0000 UTC","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"auth/auth.go:1386","component":"auth","level":"debug","message":"Failed setting default kubernetes cluster for user login (user did not provide a cluster); leaving KubernetesCluster extension in the TLS certificate empty","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"tlsca/ca.go:886","common_name":"root","component":"ca","dns_names":null,"level":"info","locality":["root","-teleport-internal-join"],"message":"Generating TLS certificate {0xc0017933e0 0xc0020f26e0 1.3.9999.1.15=#13046e6f6e65,1.3.9999.1.7=#13096c6f63616c686f7374,CN=root,O=user:root,POSTALCODE=null,STREET=localhost,L=root+L=-teleport-internal-join 1984-04-04 00:05:00 +0000 UTC [] [] 5 []}.","not_after":"1984-04-04T00:05:00Z","org":["user:root"],"org_unit":[],"timestamp":"2022-11-29T22:09:30Z"}
{"caller":"native/native.go:219","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Auth with principals: [test-tls-server.localhost test-tls-server localhost 127.0.0.1 ::1].","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"tlsca/ca.go:886","common_name":"test-tls-server.localhost","component":"ca","dns_names":["*.teleport.cluster.local","teleport.cluster.local"],"level":"info","locality":[],"message":"Generating TLS certificate {0xc001792ae0 0xc002c4e180 1.3.9999.1.7=#13096c6f63616c686f7374,CN=test-tls-server.localhost,O=Auth,POSTALCODE=null,STREET= 1994-04-02 00:00:00 +0000 UTC [*.teleport.cluster.local teleport.cluster.local] [] 5 []}.","not_after":"1994-04-02T00:00:00Z","org":["Auth"],"org_unit":[],"timestamp":"2022-11-29T22:09:30Z"}
{"caller":"sshutils/server.go:485","component":"ssh:node","level":"debug","message":"Incoming connection 127.0.0.1:48878 -\u003e 127.0.0.1:40215 version: SSH-2.0-Go, certtype: \"user\"","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"srv/authhandlers.go:259","component":"node","level":"debug","message":"conn(127.0.0.1:44330-\u003e127.0.0.1:42917, user=root) auth attempt","timestamp":"2022-11-29T22:09:30Z","trace.fields":{"fingerprint":"[email protected] SHA256:mWC2g/3Xvb1fPRHm5rJH+J9591l8qb7bD5yDZtULBK0","local":{"IP":"127.0.0.1","Port":42917,"Zone":""},"remote":{"IP":"127.0.0.1","Port":44330,"Zone":""},"user":"root"}}
{"caller":"srv/sess.go:180","component":"session:node","level":"debug","message":"Closing Session Registry.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"sshutils/server.go:397","component":"ssh:node","level":"debug","message":"Server 127.0.0.1:40215 has closed.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"srv/heartbeat.go:286","component":"node:beat","level":"debug","message":"Heartbeat exited.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"auth/grpcserver.go:167","component":"auth:grpc","level":"debug","message":"Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"backend/buffer.go:280","component":"buffer","level":"debug","message":"Removing watcher 0xc0002a3ec0 via external close.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"sshutils/server.go:490","component":"ssh:node","level":"debug","message":"Closed connection 127.0.0.1:48878.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"backend/buffer.go:280","component":"buffer","level":"debug","message":"Removing watcher 0xc0031903c0 via external close.","timestamp":"2022-11-29T22:09:30Z"}
{"caller":"backend/buffer.go:283","component":"buffer","level":"debug","message":"Could not find watcher Watcher(name=auth, prefixes=/locks, capacity=1024, size=0).","timestamp":"2022-11-29T22:09:30Z"}
===================================================
make: *** [test-go] Error 1
Makefile:[567](https://github.com/gravitational/teleport/actions/runs/3578384302/jobs/6018487002#step:6:568): recipe for target 'test-go' failed
Error: Process completed with exit code 2.

[r0mant]

Doesn't look like it's flaky actually, just broken. Might be a problem with the ghcr-hosted buildbox that doesn't have a user with id 1000 for some reason.

[ptgott]

This cropped up again here: https://github.com/gravitational/teleport/actions/runs/12316693134/job/34377525508#step:6:1938

[rosstimothy]

Looks like the user with id 1000 was removed in #50176 causing the recent bout of flakiness.