Skip to content

test flake: TestSpeedtest #6321

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.

Sign up for GitHub

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

Jump to bottom
Closed
johnstcn opened this issue Feb 23, 2023 · 3 comments
Closed

test flake: TestSpeedtest #6321

johnstcn opened this issue Feb 23, 2023 · 3 comments

Comments

@johnstcn
Copy link
Member

Seen here: https://github.com/coder/coder/actions/runs/4244867736/jobs/7387191511#step:9:631

    speedtest_test.go:58: 
        	Error Trace:	/home/runner/work/coder/coder/cli/speedtest_test.go:58
        	            				/home/runner/work/coder/coder/cli/ssh_test.go:561
        	            				/home/runner/work/coder/coder/cli/asm_amd64.s:1598
        	Error:      	Received unexpected error:
        	            	run speedtest:
        	            	    github.com/coder/coder/codersdk.(*WorkspaceAgentConn).Speedtest
        	            	        /home/runner/work/coder/coder/codersdk/workspaceagentconn.go:244
        	            	  - unexpected error has occurred: read tcp [fd7a:115c:a1e0:447e:88e0:7a4:2d4d:d2e]:39572->[fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4]:3: i/o timeout
        	Test:       	TestSpeedtest
@mafredri mafredri mentioned this issue Feb 24, 2023
Merged
@mafredri
Copy link
Member

mafredri commented Feb 24, 2023 •
edited
Loading

With the change in coder/tailscale#7, I'm able to reliably produce the following failure in TestSpeedtest:

Note that this includes improved logging via #6341.

❯ while go test ./cli -run=TestSpeedtest -count=1 -timeout=5m; do :; done
ok  	github.com/coder/coder/cli	14.230s
ok  	github.com/coder/coder/cli	6.665s
ok  	github.com/coder/coder/cli	6.371s
ok  	github.com/coder/coder/cli	6.049s
ok  	github.com/coder/coder/cli	5.897s
2023-02-24 17:51:08.030 [INFO]	(stdlib)	<net/http/server.go:3217>	(*Server).logf	2023/02/24 17:51:08 http: superfluous response.WriteHeader call from github.com/coder/coder/coderd/tracing.(*StatusWriter).WriteHeader (status_writer.go:40)
2023-02-24 17:51:08.031 [INFO]	(stdlib)	<net/http/server.go:3217>	(*Server).logf	2023/02/24 17:51:08 http: superfluous response.WriteHeader call from github.com/coder/coder/coderd/tracing.(*StatusWriter).WriteHeader (status_writer.go:40)
--- FAIL: TestSpeedtest (20.78s)
    t.go:81: 2023-02-24 17:51:07.425 [DEBUG]	(metrics_cache)	<github.com/coder/coder/coderd/metricscache/metricscache.go:219>	(*Cache).run	metrics refreshed	{"took": "147.125µs", "interval": "1h0m0s"}
    t.go:81: 2023-02-24 17:51:07.427 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "POST", "url": "http://localhost:32869/api/v2/users/first", "body": ""}
    t.go:81: 2023-02-24 17:51:07.427 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/provisionerd.go:197>	(*Server).connect	connected
    t.go:81: 2023-02-24 17:51:07.429 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/users/first", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "858.459µs", "status_code": 201, "latency_ms": 0, "request_id": "3ea0b599-1cf2-4eea-b02f-a633d7e61731"}
    t.go:81: 2023-02-24 17:51:07.430 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "POST", "url": "http://localhost:32869/api/v2/users/first", "status": 201, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.430 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "POST", "url": "http://localhost:32869/api/v2/users/login", "body": ""}
    t.go:81: 2023-02-24 17:51:07.431 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/users/login", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "419.811µs", "status_code": 201, "latency_ms": 0, "request_id": "aa70bbf7-5951-4e6a-b0d8-e4bc4b6ecf50"}
    t.go:81: 2023-02-24 17:51:07.431 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "POST", "url": "http://localhost:32869/api/v2/users/login", "status": 201, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.432 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "POST", "url": "http://localhost:32869/api/v2/files", "body": ""}
    t.go:81: 2023-02-24 17:51:07.434 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/files", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.928197ms", "status_code": 201, "latency_ms": 1, "request_id": "e83f4884-2117-460d-9798-890bbb08a48b"}
    t.go:81: 2023-02-24 17:51:07.434 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "POST", "url": "http://localhost:32869/api/v2/files", "status": 201, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.435 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "POST", "url": "http://localhost:32869/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/templateversions", "body": ""}
    t.go:81: 2023-02-24 17:51:07.437 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/templateversions", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.740193ms", "status_code": 201, "latency_ms": 1, "request_id": "0ff640b8-54a9-4732-9f90-b5566d1e133d"}
    t.go:81: 2023-02-24 17:51:07.437 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "POST", "url": "http://localhost:32869/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/templateversions", "status": 201, "body": "", "trace_id": "", "span_id": ""}
    speedtest_test.go:28: waiting for template version job 88f95e88-8a32-4a99-9cac-b202fcd185d4
    t.go:81: 2023-02-24 17:51:07.462 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/templateversions/88f95e88-8a32-4a99-9cac-b202fcd185d4", "body": ""}
    t.go:81: 2023-02-24 17:51:07.463 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/templateversions/88f95e88-8a32-4a99-9cac-b202fcd185d4", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "825.567µs", "status_code": 200, "latency_ms": 0, "request_id": "470d6173-ae13-43a1-81a3-c906a78f48a2"}
    t.go:81: 2023-02-24 17:51:07.463 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/templateversions/88f95e88-8a32-4a99-9cac-b202fcd185d4", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.479 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:98>	(*Server).AcquireJob	locked job from database	{"id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.480 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/provisionerd.go:375>	(*Server).acquireJob	acquired job	{"initiator_username": "testuser", "provisioner": "echo", "job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.480 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:386>	(*Runner).do	unpacking template source archive	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "size_bytes": 3072}
    t.go:81: 2023-02-24 17:51:07.480 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:433>	(*Runner).do	extracted file	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "size_bytes": 2, "path": "/tmp/TestSpeedtest3330013018/002/0.parse.protobuf", "mode": "-rw-r--r--"}
    t.go:81: 2023-02-24 17:51:07.480 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:433>	(*Runner).do	extracted file	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "size_bytes": 112, "path": "/tmp/TestSpeedtest3330013018/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}
    t.go:81: 2023-02-24 17:51:07.480 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:433>	(*Runner).do	extracted file	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "size_bytes": 2, "path": "/tmp/TestSpeedtest3330013018/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}
    t.go:81: 2023-02-24 17:51:07.481 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:442>	(*Runner).do	acquired job is template import	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "user_variable_values": null}
    t.go:81: 2023-02-24 17:51:07.481 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:670>	(*Runner).runTemplateImportParse	parse complete	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "parameter_schemas": null, "template_variables": null}
    t.go:81: 2023-02-24 17:51:07.482 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:390>	(*Server).UpdateJob	UpdateJob starting	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.483 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:770>	(*Runner).runTemplateImportProvisionWithRichParameters	parse dry-run provision successful	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "resource_count": 0, "resources": null, "state_length": 0}
    t.go:81: 2023-02-24 17:51:07.484 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:770>	(*Runner).runTemplateImportProvisionWithRichParameters	parse dry-run provision successful	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "resource_count": 0, "resources": null, "state_length": 0}
    t.go:81: 2023-02-24 17:51:07.484 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:356>	(*Runner).doCleanFinish.func2	cleaned up work directory	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:390>	(*Server).UpdateJob	UpdateJob starting	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "stage": "Setting up", "output": ""}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "stage": "No README.md provided", "output": ""}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "stage": "Parsing template parameters", "output": ""}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "stage": "Detecting persistent resources", "output": ""}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "stage": "Detecting ephemeral resources", "output": ""}
    t.go:81: 2023-02-24 17:51:07.485 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1", "stage": "Cleaning Up", "output": ""}
    t.go:81: 2023-02-24 17:51:07.486 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:441>	(*Server).UpdateJob	inserted job logs	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.486 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:453>	(*Server).UpdateJob	published job logs	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.486 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:217>	(*Runner).Run	sending CompletedJob	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.487 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:747>	(*Server).CompleteJob	CompleteJob starting	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.487 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:826>	(*Server).CompleteJob	marked import job as completed	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.487 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1040>	(*Server).CompleteJob	CompleteJob done	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.487 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:222>	(*Runner).Run	sent CompletedJob	{"job_id": "75d1f41f-1b63-4a13-a0b1-80acdf8bc0b1"}
    t.go:81: 2023-02-24 17:51:07.487 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/templateversions/88f95e88-8a32-4a99-9cac-b202fcd185d4", "body": ""}
    t.go:81: 2023-02-24 17:51:07.489 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/templateversions/88f95e88-8a32-4a99-9cac-b202fcd185d4", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.838733ms", "status_code": 200, "latency_ms": 1, "request_id": "43f981ea-7038-471b-b9fd-d1bcc27b981c"}
    t.go:81: 2023-02-24 17:51:07.490 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/templateversions/88f95e88-8a32-4a99-9cac-b202fcd185d4", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    speedtest_test.go:28: got template version job 88f95e88-8a32-4a99-9cac-b202fcd185d4
    t.go:81: 2023-02-24 17:51:07.490 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "POST", "url": "http://localhost:32869/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/templates", "body": ""}
    t.go:81: 2023-02-24 17:51:07.491 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/templates", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.144415ms", "status_code": 201, "latency_ms": 1, "request_id": "3e78aeff-6cb3-4a2b-894d-95af79bb5dde"}
    t.go:81: 2023-02-24 17:51:07.491 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "POST", "url": "http://localhost:32869/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/templates", "status": 201, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.492 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "POST", "url": "http://localhost:32869/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/members/me/workspaces", "body": ""}
    t.go:81: 2023-02-24 17:51:07.495 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/members/me/workspaces", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.492242ms", "status_code": 201, "latency_ms": 3, "request_id": "095bb0c7-1b22-4eea-91c3-b5deaf4595d2"}
    t.go:81: 2023-02-24 17:51:07.496 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "POST", "url": "http://localhost:32869/api/v2/organizations/0698875e-2dec-4187-8dd6-8a017bef3ce1/members/me/workspaces", "status": 201, "body": "", "trace_id": "", "span_id": ""}
    speedtest_test.go:28: waiting for workspace build job 7a17fa0f-012e-4de2-b165-ccd369498852
    t.go:81: 2023-02-24 17:51:07.521 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.523 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.717203ms", "status_code": 200, "latency_ms": 1, "request_id": "ca90ab51-2666-4d6f-bcb2-c1b03881eded"}
    t.go:81: 2023-02-24 17:51:07.523 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.547 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.549 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "2.161154ms", "status_code": 200, "latency_ms": 2, "request_id": "12aaff9d-6a78-4789-b9f8-b2c437fd6902"}
    t.go:81: 2023-02-24 17:51:07.549 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.572 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.574 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.531852ms", "status_code": 200, "latency_ms": 1, "request_id": "4048c507-4ddc-46f5-8b3c-9b1437ac1541"}
    t.go:81: 2023-02-24 17:51:07.574 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.597 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.598 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "891.197µs", "status_code": 200, "latency_ms": 0, "request_id": "6efbc4cc-dbb7-49c0-893f-0540c7b585e1"}
    t.go:81: 2023-02-24 17:51:07.598 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.622 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.624 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.892212ms", "status_code": 200, "latency_ms": 1, "request_id": "72624f00-8307-4b69-9696-b5a2f34ce84f"}
    t.go:81: 2023-02-24 17:51:07.624 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.647 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.649 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.851294ms", "status_code": 200, "latency_ms": 1, "request_id": "9aea1838-b241-4d9b-b35e-d285aa592dff"}
    t.go:81: 2023-02-24 17:51:07.649 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.671 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.673 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.732336ms", "status_code": 200, "latency_ms": 1, "request_id": "4ee7333e-0410-4b2c-b45d-36caf66e5310"}
    t.go:81: 2023-02-24 17:51:07.674 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.697 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.699 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.861566ms", "status_code": 200, "latency_ms": 1, "request_id": "de28c856-37da-41da-966e-08fe110f859f"}
    t.go:81: 2023-02-24 17:51:07.699 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.717 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:98>	(*Server).AcquireJob	locked job from database	{"id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.717 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/provisionerd.go:375>	(*Server).acquireJob	acquired job	{"initiator_username": "testuser", "provisioner": "echo", "job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "workspace_transition": "START", "workspace_owner": "testuser", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1"}
    t.go:81: 2023-02-24 17:51:07.718 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:386>	(*Runner).do	unpacking template source archive	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "size_bytes": 3072}
    t.go:81: 2023-02-24 17:51:07.718 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:433>	(*Runner).do	extracted file	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "size_bytes": 2, "path": "/tmp/TestSpeedtest3330013018/002/0.parse.protobuf", "mode": "-rw-r--r--"}
    t.go:81: 2023-02-24 17:51:07.718 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:433>	(*Runner).do	extracted file	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "size_bytes": 112, "path": "/tmp/TestSpeedtest3330013018/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}
    t.go:81: 2023-02-24 17:51:07.718 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:433>	(*Runner).do	extracted file	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "size_bytes": 2, "path": "/tmp/TestSpeedtest3330013018/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}
    t.go:81: 2023-02-24 17:51:07.719 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:460>	(*Runner).do	acquired job is workspace provision	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "workspace_name": "frosty-kirch1", "state_length": 0, "parameters": null, "rich_parameter_values": null, "variable_values": null}
    t.go:81: 2023-02-24 17:51:07.719 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:902>	(*Runner).buildWorkspace	provision successful	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "resource_count": 0, "resources": null, "state_length": 0}
    t.go:81: 2023-02-24 17:51:07.720 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:390>	(*Server).UpdateJob	UpdateJob starting	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.720 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "stage": "Setting up", "output": ""}
    t.go:81: 2023-02-24 17:51:07.720 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:441>	(*Server).UpdateJob	inserted job logs	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.720 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:453>	(*Server).UpdateJob	published job logs	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.721 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:390>	(*Server).UpdateJob	UpdateJob starting	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.721 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.721 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:902>	(*Runner).buildWorkspace	provision successful	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START", "resource_count": 1, "resources": [{"name": "dev", "type": "google_compute_instance", "agents": [{"id": "605e10bd-9004-43ce-8e25-5bea71fbd00b", "Auth": {"Token": "11f33c4c-936a-4800-96b3-0346f2bf52e5"}}]}], "state_length": 0}
    t.go:81: 2023-02-24 17:51:07.722 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:390>	(*Server).UpdateJob	UpdateJob starting	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.722 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "stage": "Starting workspace", "output": ""}
    t.go:81: 2023-02-24 17:51:07.722 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:441>	(*Server).UpdateJob	inserted job logs	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.723 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:453>	(*Server).UpdateJob	published job logs	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.723 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:356>	(*Runner).doCleanFinish.func2	cleaned up work directory	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START"}
    t.go:81: 2023-02-24 17:51:07.723 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:390>	(*Server).UpdateJob	UpdateJob starting	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.723 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:427>	(*Server).UpdateJob	job log	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "stage": "Cleaning Up", "output": ""}
    t.go:81: 2023-02-24 17:51:07.724 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:441>	(*Server).UpdateJob	inserted job logs	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.724 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:453>	(*Server).UpdateJob	published job logs	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.724 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:217>	(*Runner).Run	sending CompletedJob	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START"}
    t.go:81: 2023-02-24 17:51:07.724 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "2.590184ms", "status_code": 200, "latency_ms": 2, "request_id": "118508ad-0376-4367-b13e-9c35395ab2a5"}
    t.go:81: 2023-02-24 17:51:07.724 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:747>	(*Server).CompleteJob	CompleteJob starting	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.725 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.725 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:905>	(*Server).CompleteJob.func1	triggering workspace notification after agent timeout	{"workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "timeout": "0s"}
    t.go:81: 2023-02-24 17:51:07.725 [DEBUG]	(provisionerd-optimistic_chebyshev9)	<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1040>	(*Server).CompleteJob	CompleteJob done	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692"}
    t.go:81: 2023-02-24 17:51:07.725 [INFO]	(provisionerd)	<github.com/coder/coder/provisionerd/runner/runner.go:222>	(*Runner).Run	sent CompletedJob	{"job_id": "a5b3ba6b-0780-4667-b2ac-c4b0cfd47692", "template_name": "sad-hellman0", "template_version": "condescending_jang9", "workspace_build_id": "7a17fa0f-012e-4de2-b165-ccd369498852", "workspace_id": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "workspace_name": "frosty-kirch1", "workspace_owner": "testuser", "workspace_transition": "START"}
    t.go:81: 2023-02-24 17:51:07.746 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "body": ""}
    t.go:81: 2023-02-24 17:51:07.749 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "2.596182ms", "status_code": 200, "latency_ms": 2, "request_id": "da05160e-22df-48f0-a930-534acf66f539"}
    t.go:81: 2023-02-24 17:51:07.749 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspacebuilds/7a17fa0f-012e-4de2-b165-ccd369498852", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    speedtest_test.go:28: got workspace build job 7a17fa0f-012e-4de2-b165-ccd369498852
    t.go:81: 2023-02-24 17:51:07.749 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "body": ""}
    t.go:81: 2023-02-24 17:51:07.751 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.383456ms", "status_code": 200, "latency_ms": 1, "request_id": "972a3bb2-c033-46a5-b641-701a90648d0e"}
    t.go:81: 2023-02-24 17:51:07.751 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:07.751 [INFO]	(agent)	<github.com/coder/coder/agent/agent.go:649>	(*agent).init	generating host key
    speedtest_test.go:36: waiting for workspace agents (workspace fbc99a86-4a8a-43c2-9e54-a1d99518a388)
    t.go:81: 2023-02-24 17:51:08.027 [INFO]	(agent)	<github.com/coder/coder/agent/agent.go:159>	(*agent).runLoop	running loop
    t.go:81: 2023-02-24 17:51:08.028 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/me/metadata", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "205.192µs", "status_code": 200, "latency_ms": 0, "request_id": "109f9b7b-5c8c-43ae-8f8e-23268f34905d"}
    t.go:81: 2023-02-24 17:51:08.028 [INFO]	(agent)	<github.com/coder/coder/agent/agent.go:245>	(*agent).run	fetched metadata
    t.go:81: 2023-02-24 17:51:08.028 [INFO]	<github.com/coder/coder/coderd/workspaceagents.go:186>	(*API).postWorkspaceAgentStartup	post workspace agent version	{"request_id": "a2ae5b26-7464-4a18-b3ec-22ce95ea7e5b", "agent_id": "a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4", "agent_version": "v0.0.0-devel"}
    t.go:81: 2023-02-24 17:51:08.029 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/me/startup", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "397.965µs", "status_code": 200, "latency_ms": 0, "request_id": "a2ae5b26-7464-4a18-b3ec-22ce95ea7e5b"}
    t.go:81: 2023-02-24 17:51:08.029 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:222>	(*agent).setLifecycle	set lifecycle state	{"state": "starting", "previous": ""}
    t.go:81: 2023-02-24 17:51:08.029 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:333>	(*agent).run	running tailnet with derpmap	{"derpmap": {"Regions": {"1": {"EmbeddedRelay": true, "RegionID": 1, "RegionCode": "coder", "RegionName": "Coder", "Nodes": [{"Name": "1a", "RegionID": 1, "HostName": "localhost", "IPv4": "127.0.0.1", "STUNPort": 45838, "DERPPort": 32869, "InsecureForTests": true, "ForceHTTP": true}]}}}}
    t.go:81: 2023-02-24 17:51:08.029 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:339>	(*agent).run	creating tailnet
    t.go:81: 2023-02-24 17:51:08.029 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:200>	(*agent).reportLifecycleLoop	post lifecycle state	{"state": "starting"}
    t.go:81: 2023-02-24 17:51:08.029 [INFO]	(agent)	<github.com/coder/coder/agent/agent.go:320>	(*agent).run.func2	startup script completed	{"execution_time": "103.161µs"}
    t.go:81: 2023-02-24 17:51:08.029 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:222>	(*agent).setLifecycle	set lifecycle state	{"state": "ready", "previous": "starting"}
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	<github.com/coder/coder/coderd/workspaceagents.go:998>	(*API).workspaceAgentReportLifecycle	workspace agent state report	{"request_id": "bcdbda45-316b-4c3f-86d1-5a8d0120dfdf", "agent": "a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4", "workspace": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "payload": {"state": "starting"}}
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:270>	NewUserspaceEngine	[v1] using fake (no-op) tun device
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/me/report-lifecycle", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "354.607µs", "status_code": 204, "latency_ms": 0, "request_id": "bcdbda45-316b-4c3f-86d1-5a8d0120dfdf"}
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:274>	NewUserspaceEngine	[v1] using fake (no-op) OS network configurator
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:278>	NewUserspaceEngine	[v1] using fake (no-op) DNS configurator
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:200>	(*agent).reportLifecycleLoop	post lifecycle state	{"state": "ready"}
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: using dns.noopManager
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	<github.com/coder/coder/coderd/workspaceagents.go:998>	(*API).workspaceAgentReportLifecycle	workspace agent state report	{"request_id": "cd36e442-c620-4f4c-b792-b00347094644", "agent": "a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4", "workspace": "fbc99a86-4a8a-43c2-9e54-a1d99518a388", "payload": {"state": "ready"}}
    t.go:81: 2023-02-24 17:51:08.030 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:334>	NewUserspaceEngine	link state: interfaces.State{defaultRoute=eth0 ifs={eth0:[172.20.0.2/16]} v4=true v6=false}
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/me/report-lifecycle", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "179.229µs", "status_code": 204, "latency_ms": 0, "request_id": "cd36e442-c620-4f4c-b792-b00347094644"}
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:306>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:310>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:306>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:310>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:655>	NewConn	[v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:661>	NewConn	[v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable
    t.go:81: 2023-02-24 17:51:08.031 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1030>	(*Conn).DiscoPublicKey	magicsock: disco key = d:7dc3c91b8d2b9231
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:412>	NewUserspaceEngine	Creating WireGuard device...
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:437>	NewUserspaceEngine	Bringing WireGuard device up...
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] UDP bind has been updated
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Interface state was Down, requested Up, now Up
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Routine: receive incoming v6 - started
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Routine: receive incoming v4 - started
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:441>	NewUserspaceEngine	Bringing router up...
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Routine: receive incoming receiveDERP - started
    t.go:81: 2023-02-24 17:51:08.032 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/router/router_fake.go:21>	fakeRouter.Up	[v1] warning: fakeRouter.Up: not implemented.
    t.go:81: 2023-02-24 17:51:08.033 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:449>	NewUserspaceEngine	Clearing router settings...
    t.go:81: 2023-02-24 17:51:08.033 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/router/router_fake.go:26>	fakeRouter.Set	[v1] warning: fakeRouter.Set: not implemented.
    t.go:81: 2023-02-24 17:51:08.033 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:453>	NewUserspaceEngine	Starting link monitor...
    t.go:81: 2023-02-24 17:51:08.033 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:456>	NewUserspaceEngine	Engine created.
    t.go:81: 2023-02-24 17:51:08.034 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2397>	(*Conn).SetPrivateKey	magicsock: SetPrivateKey called (init)
    t.go:81: 2023-02-24 17:51:08.038 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:182>	NewConn	updating network map
    t.go:81: 2023-02-24 17:51:08.038 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 0 peers
    t.go:81: 2023-02-24 17:51:08.039 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	POST	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/me/report-stats", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "313.547µs", "status_code": 200, "latency_ms": 0, "request_id": "6a055403-2196-42f9-90b6-97c2acfc022d"}
    t.go:81: 2023-02-24 17:51:08.039 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:388>	(*agent).run	running coordinator
    t.go:81: 2023-02-24 17:51:08.040 [INFO]	(agent)	<github.com/coder/coder/agent/agent.go:603>	(*agent).runCoordinator	connected to coordination server
    t.go:81: 2023-02-24 17:51:08.040 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 8398940954202956643, "as_of": "2023-02-24T17:51:08.040118Z", "key": "nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61", "disco": "discokey:7dc3c91b8d2b92313410b951bb9a7a26729cc9969de34f72c7be648240cbd02d", "preferred_derp": 0, "derp_latency": null, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": []}}
    t.go:81: 2023-02-24 17:51:08.040 [INFO]	<github.com/coder/coder/coderd/workspaceagents.go:672>	(*API).workspaceAgentCoordinate	accepting agent	{"request_id": "2a1aa73b-3408-4d83-a9f2-591eeec0f043", "agent": {"id": "a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4", "created_at": "2023-02-24T17:51:07.725155Z", "updated_at": "2023-02-24T17:51:07.725155Z", "name": "", "first_connected_at": {"Time": "0001-01-01T00:00:00Z", "Valid": false}, "last_connected_at": {"Time": "0001-01-01T00:00:00Z", "Valid": false}, "disconnected_at": {"Time": "0001-01-01T00:00:00Z", "Valid": false}, "resource_id": "c2b6c675-5ce2-4d81-9375-7017ad1f6697", "auth_token": "11f33c4c-936a-4800-96b3-0346f2bf52e5", "auth_instance_id": {"String": "", "Valid": false}, "architecture": "", "environment_variables": {"RawMessage": null, "Valid": false}, "operating_system": "", "startup_script": {"String": "", "Valid": false}, "instance_metadata": {"RawMessage": null, "Valid": false}, "resource_metadata": {"RawMessage": null, "Valid": false}, "directory": "", "version": "v0.0.0-devel", "last_connected_replica_id": null, "connection_timeout_seconds": 0, "troubleshooting_url": "", "motd_file": "", "lifecycle_state": "ready", "login_before_ready": false, "startup_script_timeout_seconds": 0, "expanded_directory": ""}}
    t.go:81: 2023-02-24 17:51:08.053 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "body": ""}
    t.go:81: 2023-02-24 17:51:08.055 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.997983ms", "status_code": 200, "latency_ms": 1, "request_id": "ac8e9352-260e-41ae-aa07-7fc46b6df27f"}
    t.go:81: 2023-02-24 17:51:08.056 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    speedtest_test.go:36: got workspace agents (workspace fbc99a86-4a8a-43c2-9e54-a1d99518a388)
    t.go:81: 2023-02-24 17:51:08.082 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:170>	(*Client).Request.func1	sdk request	{"method": "GET", "url": "http://localhost:32869/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "body": ""}
    t.go:81: 2023-02-24 17:51:08.085 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "2.312387ms", "status_code": 200, "latency_ms": 2, "request_id": "f30e8ee9-31a9-4224-bdc2-5a019f4be77b"}
    t.go:81: 2023-02-24 17:51:08.085 [DEBUG]	(client)	<github.com/coder/coder/codersdk/client.go:200>	(*Client).Request.func2	sdk response	{"method": "GET", "url": "http://localhost:32869/api/v2/workspaces/fbc99a86-4a8a-43c2-9e54-a1d99518a388", "status": 200, "body": "", "trace_id": "", "span_id": ""}
    t.go:81: 2023-02-24 17:51:08.089 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/logger.go:98>	NewConn.func6	netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest=false hair= portmap= v4a=127.0.0.1:56505 derp=1 derpdist=1v4:0s
    t.go:81: 2023-02-24 17:51:08.089 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1066>	(*Conn).setNearestDERP	magicsock: home is now derp-1 (coder)
    t.go:81: 2023-02-24 17:51:08.089 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1454>	(*Conn).derpWriteChanOfAddr	magicsock: adding connection to derp-1 for home-keep-alive
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2700>	(*Conn).logActiveDerpLocked	magicsock: 1 active derp conns: derp-1=cr0s,wr0s
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2712>	(*Conn).logEndpointChange	magicsock: endpoints changed: 127.0.0.1:56505 (stun), 172.20.0.2:56505 (local)
    t.go:81: 2023-02-24 17:51:08.089 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:240>	NewConn.func7	netinfo callback	{"netinfo": {"MappingVariesByDestIP": false, "HairPinning": null, "WorkingIPv6": false, "OSHasIPv6": false, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.000282899}}}
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/derp/derphttp/derphttp_client.go:333>	(*Client).connect	derphttp.Client.Connect: connecting to derp-1 (coder)
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:219>	NewConn.func6	wireguard status	{"status": "\u0026{AsOf:2023-02-24 17:51:08.090222577 +0000 UTC m=+0.803078921 Peers:[] LocalAddrs:[] DERPs:1}", "err": null}
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:219>	NewConn.func6	wireguard status	{"status": "\u0026{AsOf:2023-02-24 17:51:08.09034316 +0000 UTC m=+0.803199500 Peers:[] LocalAddrs:[{Addr:127.0.0.1:56505 Type:stun} {Addr:172.20.0.2:56505 Type:local}] DERPs:1}", "err": null}
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 8398940954202956643, "as_of": "2023-02-24T17:51:08.090375Z", "key": "nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61", "disco": "discokey:7dc3c91b8d2b92313410b951bb9a7a26729cc9969de34f72c7be648240cbd02d", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000282899}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": []}}
    t.go:81: 2023-02-24 17:51:08.090 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 8398940954202956643, "as_of": "2023-02-24T17:51:08.0908Z", "key": "nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61", "disco": "discokey:7dc3c91b8d2b92313410b951bb9a7a26729cc9969de34f72c7be648240cbd02d", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000282899}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:56505", "172.20.0.2:56505"]}}
    t.go:81: 2023-02-24 17:51:08.092 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1671>	(*Conn).runDerpReader	magicsock: derp-1 connected; connGen=1
    t.go:81: 2023-02-24 17:51:08.095 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/entitlements", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "158.564µs", "status_code": 404, "latency_ms": 0, "request_id": "688a8066-2532-4e8c-aa66-e3fb69157279"}
    t.go:81: 2023-02-24 17:51:08.095 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/buildinfo", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "201.132µs", "status_code": 200, "latency_ms": 0, "request_id": "b0f171fe-e00a-4bb7-9735-c396cfa8d131"}
    t.go:81: 2023-02-24 17:51:08.098 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/users/me/workspace/frosty-kirch1", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.716981ms", "status_code": 200, "latency_ms": 1, "request_id": "85e4a11d-53ce-4639-be2c-84c5f2951319"}
    t.go:81: 2023-02-24 17:51:08.099 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "980.359µs", "status_code": 200, "latency_ms": 0, "request_id": "2f3c81df-8050-4dbe-8335-eee05694d03c"}
    t.go:81: 2023-02-24 17:51:08.101 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4/connection", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.545544ms", "status_code": 200, "latency_ms": 1, "request_id": "31b9e688-7b86-408e-afa5-bbaa623e9d9d"}
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:270>	NewUserspaceEngine	[v1] using fake (no-op) tun device
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:274>	NewUserspaceEngine	[v1] using fake (no-op) OS network configurator
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:278>	NewUserspaceEngine	[v1] using fake (no-op) DNS configurator
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: using dns.noopManager
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:334>	NewUserspaceEngine	link state: interfaces.State{defaultRoute=eth0 ifs={eth0:[172.20.0.2/16]} v4=true v6=false}
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:306>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:310>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:306>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP read buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock_linux.go:310>	trySetSocketBuffer.func1	magicsock: failed to force-set UDP write buffer size to 7340032: operation not permitted
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:655>	NewConn	[v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:661>	NewConn	[v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1030>	(*Conn).DiscoPublicKey	magicsock: disco key = d:b9779dbc7c1c8263
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:412>	NewUserspaceEngine	Creating WireGuard device...
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:437>	NewUserspaceEngine	Bringing WireGuard device up...
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] UDP bind has been updated
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Interface state was Down, requested Up, now Up
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:441>	NewUserspaceEngine	Bringing router up...
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Routine: receive incoming v4 - started
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/router/router_fake.go:21>	fakeRouter.Up	[v1] warning: fakeRouter.Up: not implemented.
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Routine: receive incoming receiveDERP - started
    t.go:81: 2023-02-24 17:51:08.103 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:449>	NewUserspaceEngine	Clearing router settings...
    t.go:81: 2023-02-24 17:51:08.102 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:58>	NewLogger.func1	wg: [v2] Routine: receive incoming v6 - started
    t.go:81: 2023-02-24 17:51:08.103 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/router/router_fake.go:26>	fakeRouter.Set	[v1] warning: fakeRouter.Set: not implemented.
    t.go:81: 2023-02-24 17:51:08.103 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:453>	NewUserspaceEngine	Starting link monitor...
    t.go:81: 2023-02-24 17:51:08.104 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:456>	NewUserspaceEngine	Engine created.
    t.go:81: 2023-02-24 17:51:08.104 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2397>	(*Conn).SetPrivateKey	magicsock: SetPrivateKey called (init)
    t.go:81: 2023-02-24 17:51:08.105 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:182>	NewConn	updating network map
    t.go:81: 2023-02-24 17:51:08.105 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 0 peers
    t.go:81: 2023-02-24 17:51:08.106 [DEBUG]	(speedtest)	<github.com/coder/coder/codersdk/workspaceagents.go:165>	(*Client).DialWorkspaceAgent.func3	connecting
    t.go:81: 2023-02-24 17:51:08.109 [DEBUG]	(speedtest)	<github.com/coder/coder/codersdk/workspaceagents.go:191>	(*Client).DialWorkspaceAgent.func3	serving coordinator
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1241>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1241>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): no matching peer
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.109941Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 0, "derp_latency": null, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": []}}
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:403>	(*Conn).UpdateNodes	adding node	{"node": {"id": 8398940954202956643, "as_of": "2023-02-24T17:51:08.0908Z", "key": "nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61", "disco": "discokey:7dc3c91b8d2b92313410b951bb9a7a26729cc9969de34f72c7be648240cbd02d", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000282899}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:56505", "172.20.0.2:56505"]}}
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:400>	(*Conn).UpdateNodes	no preferred DERP, skipping node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.109941Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 0, "derp_latency": null, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": []}}
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:431>	(*Conn).UpdateNodes	updating network map
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(agent.tailnet.netstack)	<tailscale.com/wgengine/netstack/netstack.go:369>	(*Impl).updateIPs	[v2] netstack: registered IP fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:431>	(*Conn).UpdateNodes	updating network map
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 1 peers
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest.netstack)	<tailscale.com/wgengine/netstack/netstack.go:369>	(*Impl).updateIPs	[v2] netstack: registered IP fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 0/0 peers)
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 0/1 peers)
    t.go:81: 2023-02-24 17:51:08.110 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] UAPI: Updating private key
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] UAPI: Updating private key
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:921>	(*userspaceEngine).Reconfig	wgengine: Reconfig: configuring router
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/router/router_fake.go:26>	fakeRouter.Set	[v1] warning: fakeRouter.Set: not implemented.
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:931>	(*userspaceEngine).Reconfig	wgengine: Reconfig: configuring DNS
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:921>	(*userspaceEngine).Reconfig	wgengine: Reconfig: configuring router
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/router/router_fake.go:26>	fakeRouter.Set	[v1] warning: fakeRouter.Set: not implemented.
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:931>	(*userspaceEngine).Reconfig	wgengine: Reconfig: configuring DNS
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:967>	(*userspaceEngine).Reconfig	[v1] wgengine: Reconfig done
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/net/dns/logger.go:98>	NewManager.func1	dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}
    t.go:81: 2023-02-24 17:51:08.111 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:967>	(*userspaceEngine).Reconfig	[v1] wgengine: Reconfig done
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/logger.go:98>	NewConn.func6	netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest=false hair= portmap= v4a=127.0.0.1:35109 derp=1 derpdist=1v4:1ms
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1066>	(*Conn).setNearestDERP	magicsock: home is now derp-1 (coder)
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1454>	(*Conn).derpWriteChanOfAddr	magicsock: adding connection to derp-1 for home-keep-alive
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2700>	(*Conn).logActiveDerpLocked	magicsock: 1 active derp conns: derp-1=cr0s,wr0s
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:240>	NewConn.func7	netinfo callback	{"netinfo": {"MappingVariesByDestIP": false, "HairPinning": null, "WorkingIPv6": false, "OSHasIPv6": false, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.000798439}}}
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest.wgengine)	<tailscale.com/derp/derphttp/derphttp_client.go:333>	(*Client).connect	derphttp.Client.Connect: connecting to derp-1 (coder)
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2712>	(*Conn).logEndpointChange	magicsock: endpoints changed: 127.0.0.1:35109 (stun), 172.20.0.2:35109 (local)
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.158796Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000798439}, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": []}}
    t.go:81: 2023-02-24 17:51:08.158 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:219>	NewConn.func6	wireguard status	{"status": "\u0026{AsOf:2023-02-24 17:51:08.158742085 +0000 UTC m=+0.871598459 Peers:[] LocalAddrs:[] DERPs:1}", "err": null}
    t.go:81: 2023-02-24 17:51:08.159 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:219>	NewConn.func6	wireguard status	{"status": "\u0026{AsOf:2023-02-24 17:51:08.159038664 +0000 UTC m=+0.871895074 Peers:[] LocalAddrs:[{Addr:127.0.0.1:35109 Type:stun} {Addr:172.20.0.2:35109 Type:local}] DERPs:1}", "err": null}
    t.go:81: 2023-02-24 17:51:08.159 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.159362Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000798439}, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": ["127.0.0.1:35109", "172.20.0.2:35109"]}}
    t.go:81: 2023-02-24 17:51:08.160 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:403>	(*Conn).UpdateNodes	adding node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.158796Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000798439}, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": []}}
    t.go:81: 2023-02-24 17:51:08.161 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:431>	(*Conn).UpdateNodes	updating network map
    t.go:81: 2023-02-24 17:51:08.161 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 1 peers
    t.go:81: 2023-02-24 17:51:08.161 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 0/1 peers)
    t.go:81: 2023-02-24 17:51:08.161 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:967>	(*userspaceEngine).Reconfig	[v1] wgengine: Reconfig done
    t.go:81: 2023-02-24 17:51:08.161 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1671>	(*Conn).runDerpReader	magicsock: derp-1 connected; connGen=1
    t.go:81: 2023-02-24 17:51:08.161 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:403>	(*Conn).UpdateNodes	adding node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.159362Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000798439}, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": ["127.0.0.1:35109", "172.20.0.2:35109"]}}
    t.go:81: 2023-02-24 17:51:08.162 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:431>	(*Conn).UpdateNodes	updating network map
    t.go:81: 2023-02-24 17:51:08.162 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 1 peers
    t.go:81: 2023-02-24 17:51:08.162 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:967>	(*userspaceEngine).Reconfig	[v1] wgengine: Reconfig done
    t.go:81: 2023-02-24 17:51:08.177 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1254>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): sending disco ping to [R4PyQ]  ...
    t.go:81: 2023-02-24 17:51:08.178 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1565>	(*Conn).setPeerLastDerpLocked	[v1] magicsock: derp route for [R4PyQ] set to derp-1 (shared home)
    t.go:81: 2023-02-24 17:51:08.178 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:4340>	(*endpoint).handlePongConnLocked	magicsock: disco: node [R4PyQ] d:7dc3c91b8d2b9231 now using 127.0.0.1:56505
    t.go:81: 2023-02-24 17:51:08.178 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:1565>	(*Conn).setPeerLastDerpLocked	[v1] magicsock: derp route for [k8ok3] set to derp-1 (shared home)
    t.go:81: 2023-02-24 17:51:08.179 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1254>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): sending disco ping to [R4PyQ]  ...
    t.go:81: 2023-02-24 17:51:08.179 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1254>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): sending disco ping to [R4PyQ]  ...
    ptytest.go:118: 2023-02-24 17:51:08.179: cmd: stdout: "Starting a 5s download test..."
    t.go:81: 2023-02-24 17:51:08.179 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1254>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): sending disco ping to [R4PyQ]  ...
    t.go:81: 2023-02-24 17:51:08.179 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:1254>	(*userspaceEngine).Ping	ping(fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4): sending disco ping to [R4PyQ]  ...
    t.go:81: 2023-02-24 17:51:08.180 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 1/1 peers)
    t.go:81: 2023-02-24 17:51:08.180 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - UAPI: Created
    t.go:81: 2023-02-24 17:51:08.181 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - UAPI: Updating endpoint
    t.go:81: 2023-02-24 17:51:08.181 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - UAPI: Removing all allowedips
    t.go:81: 2023-02-24 17:51:08.181 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - UAPI: Adding allowedip
    t.go:81: 2023-02-24 17:51:08.181 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - UAPI: Updating persistent keepalive interval
    t.go:81: 2023-02-24 17:51:08.181 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - Starting
    t.go:81: 2023-02-24 17:51:08.181 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - Sending handshake initiation
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:584>	(*userspaceEngine).noteRecvActivity	wgengine: idle peer [k8ok3] now active, reconfiguring WireGuard
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 1/1 peers)
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - UAPI: Created
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - UAPI: Updating endpoint
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - UAPI: Removing all allowedips
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - UAPI: Adding allowedip
    t.go:81: 2023-02-24 17:51:08.182 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - UAPI: Updating persistent keepalive interval
    t.go:81: 2023-02-24 17:51:08.183 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - Starting
    t.go:81: 2023-02-24 17:51:08.183 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:219>	NewConn.func6	wireguard status	{"status": "\u0026{AsOf:2023-02-24 17:51:08.183076318 +0000 UTC m=+0.895932662 Peers:[{TxBytes:0 RxBytes:0 LastHandshake:1970-01-01 00:00:00 +0000 UTC NodeKey:nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844}] LocalAddrs:[{Addr:127.0.0.1:56505 Type:stun} {Addr:172.20.0.2:56505 Type:local}] DERPs:1}", "err": null}
    t.go:81: 2023-02-24 17:51:08.183 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - Received handshake initiation
    t.go:81: 2023-02-24 17:51:08.183 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - Sending handshake response
    t.go:81: 2023-02-24 17:51:08.184 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:4340>	(*endpoint).handlePongConnLocked	magicsock: disco: node [k8ok3] d:b9779dbc7c1c8263 now using 127.0.0.1:35109
    t.go:81: 2023-02-24 17:51:08.184 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:219>	NewConn.func6	wireguard status	{"status": "\u0026{AsOf:2023-02-24 17:51:08.184419088 +0000 UTC m=+0.897275437 Peers:[{TxBytes:148 RxBytes:0 LastHandshake:1970-01-01 00:00:00 +0000 UTC NodeKey:nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61}] LocalAddrs:[{Addr:127.0.0.1:35109 Type:stun} {Addr:172.20.0.2:35109 Type:local}] DERPs:1}", "err": null}
    t.go:81: 2023-02-24 17:51:08.185 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - Received handshake response
    t.go:81: 2023-02-24 17:51:08.210 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/logger.go:98>	NewConn.func6	netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest= hair= portmap= v4a=127.0.0.1:35109 derp=1 derpdist=1v4:0s
    t.go:81: 2023-02-24 17:51:08.210 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:240>	NewConn.func7	netinfo callback	{"netinfo": {"MappingVariesByDestIP": null, "HairPinning": null, "WorkingIPv6": false, "OSHasIPv6": false, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.000158557}}}
    t.go:81: 2023-02-24 17:51:08.210 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.210949Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000158557}, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": ["127.0.0.1:35109", "172.20.0.2:35109"]}}
    t.go:81: 2023-02-24 17:51:08.211 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:403>	(*Conn).UpdateNodes	adding node	{"node": {"id": 7606118280122935549, "as_of": "2023-02-24T17:51:08.210949Z", "key": "nodekey:93ca24dea646117a3e9c7f535f6d30287b117826a1ece6d00d4c7d0106868844", "disco": "discokey:b9779dbc7c1c82639cd4e1f030fae210a3443fc077ea46e5fc72a30ee4084862", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000158557}, "addresses": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "allowed_ips": ["fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570/128"], "endpoints": ["127.0.0.1:35109", "172.20.0.2:35109"]}}
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:431>	(*Conn).UpdateNodes	updating network map
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/logger.go:98>	NewConn.func6	netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest= hair= portmap= v4a=127.0.0.1:56505 derp=1 derpdist=1v4:0s
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 1 peers
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 1/1 peers)
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - UAPI: Updating persistent keepalive interval
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - Sending keepalive packet
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:240>	NewConn.func7	netinfo callback	{"netinfo": {"MappingVariesByDestIP": null, "HairPinning": null, "WorkingIPv6": false, "OSHasIPv6": false, "WorkingUDP": true, "WorkingICMPv4": false, "UPnP": false, "PMP": false, "PCP": false, "PreferredDERP": 1, "DERPLatency": {"1-v4": 0.000139796}}}
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/userspace.go:967>	(*userspaceEngine).Reconfig	[v1] wgengine: Reconfig done
    t.go:81: 2023-02-24 17:51:08.212 [DEBUG]	(agent.tailnet)	<github.com/coder/coder/tailnet/conn.go:607>	(*Conn).sendNode.func1	sending node	{"node": {"id": 8398940954202956643, "as_of": "2023-02-24T17:51:08.212723Z", "key": "nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61", "disco": "discokey:7dc3c91b8d2b92313410b951bb9a7a26729cc9969de34f72c7be648240cbd02d", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000139796}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:56505", "172.20.0.2:56505"]}}
    t.go:81: 2023-02-24 17:51:08.213 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:403>	(*Conn).UpdateNodes	adding node	{"node": {"id": 8398940954202956643, "as_of": "2023-02-24T17:51:08.212723Z", "key": "nodekey:4783f240c09c4a345dece80197ed573f4ab42d45eb9017016e24069c49a56d61", "disco": "discokey:7dc3c91b8d2b92313410b951bb9a7a26729cc9969de34f72c7be648240cbd02d", "preferred_derp": 1, "derp_latency": {"1-v4": 0.000139796}, "addresses": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "allowed_ips": ["fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"], "endpoints": ["127.0.0.1:56505", "172.20.0.2:56505"]}}
    t.go:81: 2023-02-24 17:51:08.213 [DEBUG]	(speedtest)	<github.com/coder/coder/tailnet/conn.go:431>	(*Conn).UpdateNodes	updating network map
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2531>	(*Conn).SetNetworkMap	[v1] magicsock: got updated network map; 1 peers
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:706>	(*userspaceEngine).maybeReconfigWireguardLocked	wgengine: Reconfig: configuring userspace WireGuard config (with 1/1 peers)
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - UAPI: Updating persistent keepalive interval
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - Sending keepalive packet
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - Receiving keepalive packet
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/userspace.go:967>	(*userspaceEngine).Reconfig	[v1] wgengine: Reconfig done
    t.go:81: 2023-02-24 17:51:08.214 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - Receiving keepalive packet
    t.go:81: 2023-02-24 17:51:23.095 [DEBUG]	(speedtest)	<github.com/coder/coder/codersdk/workspaceagents.go:198>	(*Client).DialWorkspaceAgent.func3	error serving coordinator ...
        "error": read:
                     github.com/coder/coder/tailnet.ServeCoordinator.func2
                         /home/mafredri/src/coder/coder/tailnet/coordinator.go:86
                   - failed to get reader: WebSocket closed: read timed out: context deadline exceeded
    t.go:81: 2023-02-24 17:51:23.095 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/a4f88e35-f906-4ee0-9f42-5a55bbbaf2b4/coordinate", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "14.988120222s", "status_code": 101, "latency_ms": 14988, "request_id": "0b4a1b79-dd20-4306-974c-65c7902db2e6"}
    t.go:81: 2023-02-24 17:51:28.187 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2689>	(*Conn).closeDerpLocked	magicsock: closing connection to derp-1 (conn-close), age 20s
    t.go:81: 2023-02-24 17:51:28.187 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2700>	(*Conn).logActiveDerpLocked	magicsock: 0 active derp conns
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/router/router_fake.go:31>	fakeRouter.Close	[v1] warning: fakeRouter.Close: not implemented.
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Device closing
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Routine: receive incoming v6 - stopped
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Routine: receive incoming receiveDERP - stopped
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Routine: receive incoming v4 - stopped
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [R4PyQ] - Stopping
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	(speedtest.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Device closed
    t.go:81: 2023-02-24 17:51:28.188 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "", "path": "/derp", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "20.029016078s", "status_code": 0, "latency_ms": 20029, "request_id": "98dd6449-fed5-4688-9693-a5b68556c9ba"}
    speedtest_test.go:63:
        	Error Trace:	/home/mafredri/src/coder/coder/cli/speedtest_test.go:63
        	            				/home/mafredri/src/coder/coder/cli/ssh_test.go:563
        	            				/home/mafredri/src/coder/coder/cli/asm_amd64.s:1598
        	Error:      	Received unexpected error:
        	            	run speedtest:
        	            	    github.com/coder/coder/codersdk.(*WorkspaceAgentConn).Speedtest
        	            	        /home/mafredri/src/coder/coder/codersdk/workspaceagentconn.go:252
        	            	  - unexpected error has occurred: read tcp [fd7a:115c:a1e0:47e6:bf5c:c210:fff8:5570]:48981->[fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4]:3: i/o timeout
        	Test:       	TestSpeedtest
    t.go:81: 2023-02-24 17:51:28.189 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2689>	(*Conn).closeDerpLocked	magicsock: closing connection to derp-1 (conn-close), age 20s
    t.go:81: 2023-02-24 17:51:28.189 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/magicsock/magicsock.go:2700>	(*Conn).logActiveDerpLocked	magicsock: 0 active derp conns
    t.go:81: 2023-02-24 17:51:28.189 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:391>	(*agent).run	coordinator exited	{"error": "context canceled"}
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/router/router_fake.go:31>	fakeRouter.Close	[v1] warning: fakeRouter.Close: not implemented.
    t.go:81: 2023-02-24 17:51:28.189 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost:32869", "path": "/api/v2/workspaceagents/me/coordinate", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "20.150052533s", "status_code": 101, "latency_ms": 20150, "request_id": "2a1aa73b-3408-4d83-a9f2-591eeec0f043"}
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Device closing
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Routine: receive incoming v4 - stopped
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Routine: receive incoming v6 - stopped
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Routine: receive incoming receiveDERP - stopped
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	<github.com/coder/coder/coderd/httpmw/logger.go:63>	Logger.func1.1.1	GET	{"host": "localhost", "path": "/derp", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "20.099196816s", "status_code": 0, "latency_ms": 20099, "request_id": "2a98b353-20a7-4a32-a826-e7dce8fcecfe"}
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] [k8ok3] - Stopping
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.tailnet.wgengine)	<tailscale.com/wgengine/wglog/wglog.go:81>	NewLogger.func1	wg: [v2] Device closed
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent.reconnecting-pty)	<github.com/coder/coder/agent/agent.go:477>	(*agent).createTailnet.func5	accept pty failed ...
        "error": wgnet:
                     github.com/coder/coder/tailnet.(*listener).Accept
                         /home/mafredri/src/coder/coder/tailnet/conn.go:803
                   - use of closed network connection
    t.go:81: 2023-02-24 17:51:28.190 [DEBUG]	(agent)	<github.com/coder/coder/agent/agent.go:532>	(*agent).createTailnet.func7	speedtest listener failed ...
        "error": wgnet:
                     github.com/coder/coder/tailnet.(*listener).Accept
                         /home/mafredri/src/coder/coder/tailnet/conn.go:803
                   - use of closed network connection
    ptytest.go:79: 2023-02-24 17:51:28.190: cmd: closing tpty: close
    ptytest.go:70: 2023-02-24 17:51:28.190: cmd: closing pty
    ptytest.go:72: 2023-02-24 17:51:28.190: cmd: closed pty: <nil>
    ptytest.go:106: 2023-02-24 17:51:28.190: cmd: copy done: read /dev/ptmx: input/output error
    ptytest.go:107: 2023-02-24 17:51:28.191: cmd: closing out
    ptytest.go:109: 2023-02-24 17:51:28.191: cmd: closed out: read /dev/ptmx: input/output error
    ptytest.go:70: 2023-02-24 17:51:28.191: cmd: closing logw
    ptytest.go:72: 2023-02-24 17:51:28.191: cmd: closed logw: <nil>
    ptytest.go:70: 2023-02-24 17:51:28.191: cmd: closing logr
    ptytest.go:72: 2023-02-24 17:51:28.191: cmd: closed logr: <nil>
    ptytest.go:98: 2023-02-24 17:51:28.191: cmd: closed tpty
    t.go:81: 2023-02-24 17:51:28.191 [DEBUG]	(provisionerd)	<github.com/coder/coder/provisionerd/provisionerd.go:550>	(*Server).closeWithError	closing server with error	{"error": null}
    stuntest.go:63: STUN server shutdown
FAIL
FAIL	github.com/coder/coder/cli	20.942s
FAIL

@github-actions
Copy link

This issue is becoming stale. In order to keep the tracker readable and actionable, I'm going close to this issue in 7 days if there isn't more activity.

@github-actions github-actions bot added the stale This issue is like stale bread. label May 26, 2023
@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Jun 2, 2023
@matifali matifali removed the chore label Sep 2, 2023
@coadler
Copy link
Contributor

coadler commented Jan 26, 2024

This is still referenced in the code

@coadler coadler reopened this Jan 26, 2024
@coadler coadler removed the stale This issue is like stale bread. label Jan 26, 2024
@sreya sreya closed this as not planned Won't fix, can't repro, duplicate, stale Apr 4, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@mafredri @sreya @johnstcn @coadler @matifali