t.go:85: 2023-08-15 09:59:45.973 [debu] metrics_cache: deployment stats metrics refreshed took=12.716µs interval=5m0s t.go:85: 2023-08-15 09:59:45.976 [info] inmem-provisionerd-sweet_meitner3: starting in-memory provisioner daemon t.go:85: 2023-08-15 09:59:45.976 [info] provisionerd: provisionerd successfully connected to coderd t.go:85: 2023-08-15 09:59:45.976 [debu] metrics_cache: template daus metrics refreshed took=3.074276ms interval=1h0m0s t.go:85: 2023-08-15 09:59:45.996 [debu] POST host=localhost:38795 path=/api/v2/users/first proto=HTTP/1.1 remote_addr=127.0.0.1 took=19.168862ms status_code=201 latency_ms=19 request_id=b08fb51e-3cec-4b2e-be72-b33526fffdfd t.go:85: 2023-08-15 09:59:46.007 [debu] POST host=localhost:38795 path=/api/v2/users/login proto=HTTP/1.1 remote_addr=127.0.0.1 took=5.425984ms status_code=201 latency_ms=5 request_id=d734d4b9-065c-4983-bcac-33fdaf825189 t.go:85: 2023-08-15 09:59:46.024 [debu] GET host=localhost:38795 path=/api/v2/users/20d3c323-ead7-4c3c-90fc-fe1f82bff32e proto=HTTP/1.1 remote_addr=127.0.0.1 took=12.515585ms status_code=200 latency_ms=12 request_id=92f47931-8675-4395-8c91-9c4d86dcc8c3 t.go:85: 2023-08-15 09:59:46.066 [debu] POST host=localhost:38795 path=/api/v2/files proto=HTTP/1.1 remote_addr=127.0.0.1 took=32.9523ms status_code=201 latency_ms=32 request_id=feb0e930-bb3f-43d9-860b-1c1fb5786d18 t.go:85: 2023-08-15 09:59:46.080 [debu] POST host=localhost:38795 path=/api/v2/organizations/25f93b15-2186-4879-979e-cdfef794e518/templateversions proto=HTTP/1.1 remote_addr=127.0.0.1 took=13.496514ms status_code=201 latency_ms=13 request_id=6f9f48d2-9622-477b-ba37-d82afebabc3c t.go:85: 2023-08-15 09:59:46.115 [debu] POST host=localhost:38795 path=/api/v2/organizations/25f93b15-2186-4879-979e-cdfef794e518/templates proto=HTTP/1.1 remote_addr=127.0.0.1 took=31.692584ms status_code=201 latency_ms=31 request_id=8580914f-5a16-4b6a-b3f2-e8fd8a69208c portforward_test.go:311: waiting for template version job 32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 t.go:85: 2023-08-15 09:59:46.143 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=563.36µs status_code=200 latency_ms=0 request_id=02e4508e-779b-4912-a70f-26c5c2711d4c t.go:85: 2023-08-15 09:59:46.167 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=611.256µs status_code=200 latency_ms=0 request_id=6c56720e-a206-47e3-8ef5-8f2f341847e3 t.go:85: 2023-08-15 09:59:46.192 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=533.831µs status_code=200 latency_ms=0 request_id=61db2a9d-6e8b-4811-a65f-79748fe6888c t.go:85: 2023-08-15 09:59:46.220 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.973158ms status_code=200 latency_ms=1 request_id=e0b6c404-8229-4aaf-8f69-27899abe3783 t.go:85: 2023-08-15 09:59:46.242 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=471.657µs status_code=200 latency_ms=0 request_id=72170a7f-cd01-4134-80f3-ba1e5fa81c8e t.go:85: 2023-08-15 09:59:46.267 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=502.458µs status_code=200 latency_ms=0 request_id=03550729-a71a-410a-9bf9-b30bfc6c92d2 t.go:85: 2023-08-15 09:59:46.292 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=453.83µs status_code=200 latency_ms=0 request_id=da0fb73d-b789-4a7a-b2f0-e81f88cf0f40 t.go:85: 2023-08-15 09:59:46.317 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=513.33µs status_code=200 latency_ms=0 request_id=cbebf43b-5726-49fd-a3e7-efec59f9b2de t.go:85: 2023-08-15 09:59:46.342 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=502.999µs status_code=200 latency_ms=0 request_id=bb49b39e-857b-43b5-98be-2e12ad07372d t.go:85: 2023-08-15 09:59:46.367 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=615.003µs status_code=200 latency_ms=0 request_id=6aec2460-0edc-4112-875f-ceffc1f3f24e t.go:85: 2023-08-15 09:59:46.393 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=2.185814ms status_code=200 latency_ms=2 request_id=91952f2d-cfac-4254-85fd-6104aee56498 t.go:85: 2023-08-15 09:59:46.418 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=707.179µs status_code=200 latency_ms=0 request_id=3028a5f1-1c45-4c95-a1f6-59795a8814af t.go:85: 2023-08-15 09:59:46.442 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=496.125µs status_code=200 latency_ms=0 request_id=bd7b3847-9ac9-45ea-bf25-21d592111524 t.go:85: 2023-08-15 09:59:46.467 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=379.12µs status_code=200 latency_ms=0 request_id=91859b65-6dcc-47d5-bd26-5a581d9a1fad t.go:85: 2023-08-15 09:59:46.492 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=560.013µs status_code=200 latency_ms=0 request_id=1628b0fa-bc6d-463a-a38f-3c62d85b7f2a t.go:85: 2023-08-15 09:59:46.517 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=472.448µs status_code=200 latency_ms=0 request_id=87b465d2-63c5-4454-b26f-717d19c8e035 t.go:85: 2023-08-15 09:59:46.541 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=422.357µs status_code=200 latency_ms=0 request_id=09f0a837-1e98-4b0a-b033-4e17a12e1e44 t.go:85: 2023-08-15 09:59:46.567 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=676.016µs status_code=200 latency_ms=0 request_id=b02a27e1-fc7b-4105-8dfc-d490caf55a76 t.go:85: 2023-08-15 09:59:46.592 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=385.623µs status_code=200 latency_ms=0 request_id=04b7364e-96f9-49a2-830e-9d5fde3c1c6f t.go:85: 2023-08-15 09:59:46.617 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=404.882µs status_code=200 latency_ms=0 request_id=f445bf01-becb-4381-90b3-f3603d1443d6 t.go:85: 2023-08-15 09:59:46.642 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=506.486µs status_code=200 latency_ms=0 request_id=d31d2a93-6ef8-46d0-a17e-36fbb1bea98d t.go:85: 2023-08-15 09:59:46.666 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=469.071µs status_code=200 latency_ms=0 request_id=63178726-4c92-4889-a518-0926895c97eb t.go:85: 2023-08-15 09:59:46.692 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=432.137µs status_code=200 latency_ms=0 request_id=a4b16c6f-edbf-4c20-a002-150d4887b4be t.go:85: 2023-08-15 09:59:46.717 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=444.021µs status_code=200 latency_ms=0 request_id=8a0368ed-6c28-4dce-9413-2e533a5b5101 t.go:85: 2023-08-15 09:59:46.742 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=604.563µs status_code=200 latency_ms=0 request_id=f30cb395-d5e8-48c2-b7de-b416a0822f93 t.go:85: 2023-08-15 09:59:46.766 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=421.034µs status_code=200 latency_ms=0 request_id=312069a7-c7e8-45bb-8f43-940c99407c4f t.go:85: 2023-08-15 09:59:46.791 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=346.235µs status_code=200 latency_ms=0 request_id=33ca8af4-b4e2-4cee-9460-d2ffd9e3d6b2 t.go:85: 2023-08-15 09:59:46.816 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=449.051µs status_code=200 latency_ms=0 request_id=5f5b0e2b-77dc-4a78-824a-7965b79a41c6 t.go:85: 2023-08-15 09:59:46.842 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=517.488µs status_code=200 latency_ms=0 request_id=2d968dfe-a640-4889-9789-4779c697f133 t.go:85: 2023-08-15 09:59:46.864 [debu] inmem-provisionerd-sweet_meitner3: locked job from database job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.866 [debu] provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.866 [info] provisionerd: unpacking template source archive job_id=37ef4a17-0200-4181-81f7-3c14311217ac size_bytes=3072 t.go:85: 2023-08-15 09:59:46.866 [debu] provisionerd: extracted file job_id=37ef4a17-0200-4181-81f7-3c14311217ac size_bytes=2 path=/tmp/TestDERPHeaders978573694/002/0.parse.protobuf mode=-rw-r--r-- t.go:85: 2023-08-15 09:59:46.866 [debu] provisionerd: extracted file job_id=37ef4a17-0200-4181-81f7-3c14311217ac size_bytes=114 path=/tmp/TestDERPHeaders978573694/002/0.provision.apply.protobuf mode=-rw-r--r-- t.go:85: 2023-08-15 09:59:46.866 [debu] provisionerd: extracted file job_id=37ef4a17-0200-4181-81f7-3c14311217ac size_bytes=2 path=/tmp/TestDERPHeaders978573694/002/0.provision.plan.protobuf mode=-rw-r--r-- t.go:85: 2023-08-15 09:59:46.866 [debu] provisionerd: acquired job is template import job_id=37ef4a17-0200-4181-81f7-3c14311217ac user_variable_values=[] t.go:85: 2023-08-15 09:59:46.866 [debu] provisionerd: parse complete job_id=37ef4a17-0200-4181-81f7-3c14311217ac template_variables=[] t.go:85: 2023-08-15 09:59:46.866 [debu] inmem-provisionerd-sweet_meitner3: stage UpdateJob starting job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.866 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=365.934µs status_code=200 latency_ms=0 request_id=61c09efe-d4f6-4a63-9e99-afda32857f31 t.go:85: 2023-08-15 09:59:46.866 [info] provisionerd: parse dry-run provision successful job_id=37ef4a17-0200-4181-81f7-3c14311217ac resource_count=0 resources=[] state_length=0 t.go:85: 2023-08-15 09:59:46.867 [info] provisionerd: parse dry-run provision successful job_id=37ef4a17-0200-4181-81f7-3c14311217ac resource_count=0 resources=[] state_length=0 t.go:85: 2023-08-15 09:59:46.867 [debu] provisionerd: cleaned up work directory job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: stage UpdateJob starting job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=37ef4a17-0200-4181-81f7-3c14311217ac stage="Setting up" output="" t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=37ef4a17-0200-4181-81f7-3c14311217ac stage="No README.md provided" output="" t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=37ef4a17-0200-4181-81f7-3c14311217ac stage="Parsing template parameters" output="" t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=37ef4a17-0200-4181-81f7-3c14311217ac stage="Detecting persistent resources" output="" t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=37ef4a17-0200-4181-81f7-3c14311217ac stage="Detecting ephemeral resources" output="" t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=37ef4a17-0200-4181-81f7-3c14311217ac stage="Cleaning Up" output="" t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: inserted job logs job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: published job logs job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.867 [debu] provisionerd: sending CompletedJob job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.867 [debu] inmem-provisionerd-sweet_meitner3: stage CompleteJob starting job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.868 [debu] inmem-provisionerd-sweet_meitner3: marked import job as completed job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.869 [debu] inmem-provisionerd-sweet_meitner3: stage CompleteJob done job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.869 [debu] provisionerd: sent CompletedJob job_id=37ef4a17-0200-4181-81f7-3c14311217ac t.go:85: 2023-08-15 09:59:46.893 [debu] GET host=localhost:38795 path=/api/v2/templateversions/32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 proto=HTTP/1.1 remote_addr=127.0.0.1 took=744.202µs status_code=200 latency_ms=0 request_id=43ffbf54-5407-4426-9dc9-7bca2db8a86a portforward_test.go:311: got template version job 32e9a0ca-d9f1-4172-8a6d-6dd6d500e582 t.go:85: 2023-08-15 09:59:46.908 [debu] POST host=localhost:38795 path=/api/v2/organizations/25f93b15-2186-4879-979e-cdfef794e518/members/me/workspaces proto=HTTP/1.1 remote_addr=127.0.0.1 took=14.737262ms status_code=201 latency_ms=14 request_id=b58bcf44-d2b5-41ed-bf33-8bf370399381 portforward_test.go:313: waiting for workspace build job a9a8d6f2-8650-47e3-9d02-166393c7e25e t.go:85: 2023-08-15 09:59:46.936 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=530.104µs status_code=200 latency_ms=0 request_id=1320e890-30fc-4ebd-876d-73826fa4efab t.go:85: 2023-08-15 09:59:46.961 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=544.973µs status_code=200 latency_ms=0 request_id=a7af98e4-fcec-4cb8-99bf-3d3b3e5c40f9 t.go:85: 2023-08-15 09:59:46.986 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=523.971µs status_code=200 latency_ms=0 request_id=32912697-ab9b-4031-9edf-1324ed63ff32 t.go:85: 2023-08-15 09:59:47.021 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.398686ms status_code=200 latency_ms=1 request_id=09c17552-e4d9-47fc-a539-51d707388bd5 t.go:85: 2023-08-15 09:59:47.035 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=508.76µs status_code=200 latency_ms=0 request_id=0bf1cc3a-3d14-43bc-865b-7b02a71693bc t.go:85: 2023-08-15 09:59:47.061 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=575.916µs status_code=200 latency_ms=0 request_id=9e13d3d2-76b2-45c5-bb3f-68d26020d1e9 t.go:85: 2023-08-15 09:59:47.085 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=427.618µs status_code=200 latency_ms=0 request_id=82e1c2a7-3c6b-4587-8495-8b8b63aa51e5 t.go:85: 2023-08-15 09:59:47.110 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=443.851µs status_code=200 latency_ms=0 request_id=654a991a-2842-49c8-b354-194fe6f793dd t.go:85: 2023-08-15 09:59:47.135 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=385.884µs status_code=200 latency_ms=0 request_id=82e491e6-e73e-4344-a5d4-3c3ee194187e t.go:85: 2023-08-15 09:59:47.161 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=693.351µs status_code=200 latency_ms=0 request_id=a1c5682a-2715-4da8-a011-1ca0b2684244 t.go:85: 2023-08-15 09:59:47.396 [debu] inmem-provisionerd-sweet_meitner3: locked job from database job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.401 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.154496ms status_code=200 latency_ms=1 request_id=e129fa1e-20f6-4409-8f9b-054a0fd30a39 t.go:85: 2023-08-15 09:59:47.402 [debu] provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=ad777c36-c64b-4f0a-ac25-03681547b3df workspace_transition=START workspace_owner=testuser template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T t.go:85: 2023-08-15 09:59:47.403 [info] provisionerd: unpacking template source archive job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start size_bytes=3072 t.go:85: 2023-08-15 09:59:47.403 [debu] provisionerd: extracted file job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start size_bytes=2 path=/tmp/TestDERPHeaders978573694/002/0.parse.protobuf mode=-rw-r--r-- t.go:85: 2023-08-15 09:59:47.403 [debu] provisionerd: extracted file job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start size_bytes=114 path=/tmp/TestDERPHeaders978573694/002/0.provision.apply.protobuf mode=-rw-r--r-- t.go:85: 2023-08-15 09:59:47.403 [debu] provisionerd: extracted file job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start size_bytes=2 path=/tmp/TestDERPHeaders978573694/002/0.provision.plan.protobuf mode=-rw-r--r-- t.go:85: 2023-08-15 09:59:47.404 [debu] provisionerd: acquired job is workspace provision job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start workspace_name=upbeat-aryabhata8-p2T state_length=0 rich_parameter_values=[] variable_values=[] t.go:85: 2023-08-15 09:59:47.404 [info] provisionerd: provision successful job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start resource_count=0 resources=[] state_length=0 t.go:85: 2023-08-15 09:59:47.404 [debu] inmem-provisionerd-sweet_meitner3: stage UpdateJob starting job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.405 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=ad777c36-c64b-4f0a-ac25-03681547b3df stage="Setting up" output="" t.go:85: 2023-08-15 09:59:47.405 [debu] inmem-provisionerd-sweet_meitner3: inserted job logs job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.405 [debu] inmem-provisionerd-sweet_meitner3: published job logs job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.405 [debu] inmem-provisionerd-sweet_meitner3: stage UpdateJob starting job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.406 [info] provisionerd: provision successful job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start resource_count=1 resources="[name:\"example\" type:\"aws_instance\" agents:{id:\"7472b684-36e3-4c55-b9e9-85d0ff6641db\" name:\"example\" token:\"1b545a4a-bbe0-4a7d-99d8-070f682a7b5b\"}]" state_length=0 t.go:85: 2023-08-15 09:59:47.407 [debu] inmem-provisionerd-sweet_meitner3: stage UpdateJob starting job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.408 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=ad777c36-c64b-4f0a-ac25-03681547b3df stage="Starting workspace" output="" t.go:85: 2023-08-15 09:59:47.409 [debu] inmem-provisionerd-sweet_meitner3: inserted job logs job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.409 [debu] inmem-provisionerd-sweet_meitner3: published job logs job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.409 [debu] provisionerd: cleaned up work directory job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start t.go:85: 2023-08-15 09:59:47.409 [debu] inmem-provisionerd-sweet_meitner3: stage UpdateJob starting job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.410 [debu] inmem-provisionerd-sweet_meitner3: job log job_id=ad777c36-c64b-4f0a-ac25-03681547b3df stage="Cleaning Up" output="" t.go:85: 2023-08-15 09:59:47.411 [debu] inmem-provisionerd-sweet_meitner3: inserted job logs job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.411 [debu] inmem-provisionerd-sweet_meitner3: published job logs job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.411 [debu] provisionerd: sending CompletedJob job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start t.go:85: 2023-08-15 09:59:47.411 [debu] inmem-provisionerd-sweet_meitner3: stage CompleteJob starting job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.411 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=707.98µs status_code=200 latency_ms=0 request_id=b526300c-178a-41ce-8358-7ba205e585be t.go:85: 2023-08-15 09:59:47.415 [debu] inmem-provisionerd-sweet_meitner3: triggering workspace notification after agent timeout workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e timeout=0s t.go:85: 2023-08-15 09:59:47.415 [debu] inmem-provisionerd-sweet_meitner3: stage CompleteJob done job_id=ad777c36-c64b-4f0a-ac25-03681547b3df t.go:85: 2023-08-15 09:59:47.416 [debu] provisionerd: sent CompletedJob job_id=ad777c36-c64b-4f0a-ac25-03681547b3df template_name=frosty-ishizaka6-4H7 template_version=thirsty_thompson5 workspace_build_id=a9a8d6f2-8650-47e3-9d02-166393c7e25e workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 workspace_name=upbeat-aryabhata8-p2T workspace_owner=testuser workspace_transition=start t.go:85: 2023-08-15 09:59:47.447 [debu] GET host=localhost:38795 path=/api/v2/workspacebuilds/a9a8d6f2-8650-47e3-9d02-166393c7e25e proto=HTTP/1.1 remote_addr=127.0.0.1 took=774.824µs status_code=200 latency_ms=0 request_id=3ffbe82b-5ee9-44b7-a06c-d9ac5bc9acee portforward_test.go:313: got workspace build job a9a8d6f2-8650-47e3-9d02-166393c7e25e clitest.go:70: invoking command: coder --global-config /tmp/TestDERPHeaders978573694/003 agent --agent-token 1b545a4a-bbe0-4a7d-99d8-070f682a7b5b --agent-url http://localhost:38795 portforward_test.go:333: waiting for workspace agents (workspace 84d76d39-a28f-4509-bec8-97732fb947e8) ptytest.go:131: 2023-08-15 09:59:47.453: cmd: "2023-08-15 09:59:47.452 [info] agent is starting now url=http://localhost:38795 auth=token version=v0.0.0-devel" ptytest.go:131: 2023-08-15 09:59:47.455: cmd: "2023-08-15 09:59:47.452 [debu] http server listening addr=127.0.0.1:6060 name=pprof" ptytest.go:131: 2023-08-15 09:59:47.455: cmd: "2023-08-15 09:59:47.453 [erro] http server listen name=pprof error=\"listen tcp 127.0.0.1:6060: bind: address already in use\"" t.go:85: 2023-08-15 09:59:47.736 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=29.91596ms status_code=200 latency_ms=29 request_id=c542cae8-84cf-4466-9573-1cb723a6f612 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:47.754 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=16.512674ms status_code=200 latency_ms=16 request_id=e519960c-fca1-4d34-aed4-773da27c08d4 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.059 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=304.509469ms status_code=200 latency_ms=304 request_id=b09bba0b-42c3-490b-8c1e-70c2781f7c96 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.078 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=18.621052ms status_code=200 latency_ms=18 request_id=2505f774-5e0e-43b7-a456-7d57da894889 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.093 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=14.119082ms status_code=200 latency_ms=14 request_id=285b6331-5320-4359-80a8-6c7d79e56b66 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.440 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=28.880172ms status_code=200 latency_ms=28 request_id=bdd77e87-e558-4371-80eb-4534147b854e coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.470 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=28.020187ms status_code=200 latency_ms=28 request_id=7f6f5193-ef31-4f51-8c3f-6c26a5e68925 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.724 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=252.401584ms status_code=200 latency_ms=252 request_id=294501b0-b97f-4317-8c7e-a52815d9ec05 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.832 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=106.153047ms status_code=200 latency_ms=106 request_id=a6a103a5-3ec2-4c41-af6e-72ef807bed13 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.854 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=21.995782ms status_code=200 latency_ms=21 request_id=f236327d-8a86-4483-8cd0-f36ba2868547 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:48.883 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=27.394672ms status_code=200 latency_ms=27 request_id=552cac03-8068-4447-9883-6303f535c26e coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.182 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=294.926256ms status_code=200 latency_ms=294 request_id=8c6977ce-931c-4476-9675-7bd064ca196a coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.198 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=15.207986ms status_code=200 latency_ms=15 request_id=c66e0e8e-7cd3-48b7-8334-adf0fcb03448 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.416 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=213.306621ms status_code=200 latency_ms=213 request_id=48909e1e-3db7-4245-8768-9e6d7dbb23bf coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.425 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=8.401703ms status_code=200 latency_ms=8 request_id=c3f4bcca-cb1c-4f43-89e3-b9e41794d5f6 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.443 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=15.616626ms status_code=200 latency_ms=15 request_id=5ba1a392-0d8a-4be9-81f7-28ca6cb878bc coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.461 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=8.40999ms status_code=200 latency_ms=8 request_id=d2be0983-c01b-4c58-9746-1b5d7c3472e9 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.677 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=20.361073ms status_code=200 latency_ms=20 request_id=e22c0a36-48e6-4b57-b878-075843f1e702 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.875 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=197.212798ms status_code=200 latency_ms=197 request_id=94262f6d-a55d-4846-8479-2ab57656e8c5 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:49.898 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=22.183849ms status_code=200 latency_ms=22 request_id=50e69a40-ae87-49af-bceb-2fee88de99a2 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.085 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=186.764599ms status_code=200 latency_ms=186 request_id=5659ddfa-63c7-4de5-ab5a-577e9d30b88f coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.098 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=12.560245ms status_code=200 latency_ms=12 request_id=829329b2-4779-44ed-8fa5-870c49efb269 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.397 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=162.232218ms status_code=200 latency_ms=162 request_id=16514178-97e6-48e5-9287-3b9baf722870 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.571 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=173.350301ms status_code=200 latency_ms=173 request_id=0c54ae79-2f1b-4a67-a7dc-9e8c067dd34d coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.578 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=7.533792ms status_code=200 latency_ms=7 request_id=7bd0ad27-c6dc-4d37-9822-da76390cc6a3 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.705 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=126.204669ms status_code=200 latency_ms=126 request_id=a50f5da9-3b89-4e7e-8d1e-e7d86277ce74 coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.717 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=10.674913ms status_code=200 latency_ms=10 request_id=4cac97e3-dd76-4004-8025-bcc6751dcbc6 coderdtest.go:804: agent example not connected yet ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [debu] http server listening addr=127.0.0.1:2112 name=prometheus" ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [info] connecting to coderd" ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [debu] http server listening addr=127.0.0.1:2113 name=debug" ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [debu] sdk request method=GET url=http://localhost:38795/api/v2/appearance body=\"\"" ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [erro] http server listen name=debug error=\"listen tcp 127.0.0.1:2113: bind: address already in use\"" ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [erro] http server listen name=prometheus error=\"listen tcp 127.0.0.1:2112: bind: address already in use\"" t.go:85: 2023-08-15 09:59:50.893 [debu] GET host=localhost:38795 path=/api/v2/appearance proto=HTTP/1.1 remote_addr=127.0.0.1 took=90.572µs status_code=404 latency_ms=0 request_id=afd61b11-8631-4863-ae75-1b8a12632d97 ptytest.go:131: 2023-08-15 09:59:50.893: cmd: "2023-08-15 09:59:50.893 [debu] sdk response method=GET url=http://localhost:38795/api/v2/appearance status=404 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:50.894: cmd: "2023-08-15 09:59:50.894 [debu] sdk request method=GET url=http://localhost:38795/api/v2/workspaceagents/me/manifest body=\"\"" t.go:85: 2023-08-15 09:59:50.896 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=13.573928ms status_code=200 latency_ms=13 request_id=8c0441b3-5ec3-4045-992b-8c734ce3eade coderdtest.go:804: agent example not connected yet t.go:85: 2023-08-15 09:59:50.898 [debu] GET host=localhost:38795 path=/api/v2/workspaceagents/me/manifest proto=HTTP/1.1 remote_addr=127.0.0.1 took=3.857328ms status_code=200 latency_ms=3 request_id=60803b2a-2c36-4502-bd8b-8c8e7f510abc ptytest.go:131: 2023-08-15 09:59:50.898: cmd: "2023-08-15 09:59:50.898 [debu] sdk response method=GET url=http://localhost:38795/api/v2/workspaceagents/me/manifest status=200 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:50.899: cmd: "2023-08-15 09:59:50.898 [info] fetched manifest manifest={\"agent_id\":\"12492c07-3cc3-472e-92d9-6fc4b7f7e4ef\",\"git_auth_configs\":0,\"vscode_port_proxy_uri\":\":38795\",\"apps\":[],\"derpmap\":{\"Regions\":{\"1000\":{\"EmbeddedRelay\":false,\"RegionID\":1000,\"RegionCode\":\"coder_stun_1000\",\"RegionName\":\"Coder STUN 1000\",\"Nodes\":[{\"Name\":\"1000stun0\",\"RegionID\":1000,\"HostName\":\"stun.l.google.com\",\"STUNPort\":19302,\"STUNOnly\":true}]},\"1001\":{\"EmbeddedRelay\":false,\"RegionID\":1001,\"RegionCode\":\"coder_stun_1001\",\"RegionName\":\"Coder STUN 1001\",\"Nodes\":[{\"Name\":\"1001stun0\",\"RegionID\":1001,\"HostName\":\"stun1.l.google.com\",\"STUNPort\":19302,\"STUNOnly\":true}]},\"1002\":{\"EmbeddedRelay\":false,\"RegionID\":1002,\"RegionCode\":\"coder_stun_1002\",\"RegionName\":\"Coder STUN 1002\",\"Nodes\":[{\"Name\":\"1002stun0\",\"RegionID\":1002,\"HostName\":\"stun2.l.google.com\",\"STUNPort\":19302,\"STUNOnly\":true}]},\"1003\":{\"EmbeddedRelay\":false,\"RegionID\":1003,\"RegionCode\":\"coder_stun_1003\",\"RegionName\":\"Coder STUN 1003\",\"Nodes\":[{\"Name\":\"1003stun0\",\"RegionID\":1003,\"HostName\":\"stun3.l.google.com\",\"STUNPort\":19302,\"STUNOnly\":true}]},\"1004\":{\"EmbeddedRelay\":false,\"RegionID\":1004,\"RegionCode\":\"coder_stun_1004\",\"RegionName\":\"Coder STUN 1004\",\"Nodes\":[{\"Name\":\"1004stun0\",\"RegionID\":1004,\"HostName\":\"stun4.l.google.com\",\"STUNPort\":19302,\"STUNOnly\":true}]},\"999\":{\"EmbeddedRelay\":true,\"RegionID\":999,\"RegionCode\":\"coder\",\"RegionName\":\"Coder Embedded Relay\",\"Nodes\":[{\"Name\":\"999b\",\"RegionID\":999,\"HostName\":\"localhost\",\"IPv4\":\"127.0.0.1\",\"STUNPort\":-1,\"DERPPort\":38795,\"InsecureForTests\":true,\"ForceHTTP\":true}]}}},\"environment_variables\":null,\"startup_script\":\"\",\"startup_script_timeout\":0,\"directory\":\"\",\"motd_file\":\"\",\"shutdown_script\":\"\",\"shutdown_script_timeout\":0,\"disable_direct_connections\":false,\"metadata\":[]}" ptytest.go:131: 2023-08-15 09:59:50.899: cmd: "2023-08-15 09:59:50.899 [debu] sdk request method=POST url=http://localhost:38795/api/v2/workspaceagents/me/startup body=\"\"" t.go:85: 2023-08-15 09:59:50.899 [info] post workspace agent version request_id=d60fc64a-e331-42a9-b029-146685a80e72 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef agent_version=v0.0.0-devel t.go:85: 2023-08-15 09:59:50.900 [debu] POST host=localhost:38795 path=/api/v2/workspaceagents/me/startup proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.188965ms status_code=200 latency_ms=1 request_id=d60fc64a-e331-42a9-b029-146685a80e72 ptytest.go:131: 2023-08-15 09:59:50.900: cmd: "2023-08-15 09:59:50.900 [debu] sdk response method=POST url=http://localhost:38795/api/v2/workspaceagents/me/startup status=200 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:50.900: cmd: "2023-08-15 09:59:50.900 [debu] set lifecycle state current={\"state\":\"starting\",\"changed_at\":\"2023-08-15T09:59:50.900815Z\"} last={\"state\":\"created\",\"changed_at\":\"0001-01-01T00:00:00Z\"}" ptytest.go:131: 2023-08-15 09:59:50.900: cmd: "2023-08-15 09:59:50.900 [debu] set lifecycle state current={\"state\":\"ready\",\"changed_at\":\"2023-08-15T09:59:50.900911Z\"} last={\"state\":\"starting\",\"changed_at\":\"2023-08-15T09:59:50.900815Z\"}" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.900 [debu] reporting lifecycle state payload={\"state\":\"starting\",\"changed_at\":\"2023-08-15T09:59:50.900815Z\"}" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] sdk request method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle body=\"\"" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: [v1] using fake (no-op) tun device" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: [v1] using fake (no-op) OS network configurator" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: [v1] using fake (no-op) DNS configurator" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: dns: using dns.noopManager" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: link state: interfaces.State{defaultRoute=eth0 ifs={docker0:[172.17.0.1/16] eth0:[172.20.0.6/16]} v4=true v6=false}" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: magicsock: [warning] failed to force-set UDP read buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: magicsock: [warning] failed to force-set UDP write buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: magicsock: [warning] failed to force-set UDP read buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: magicsock: [warning] failed to force-set UDP write buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)" ptytest.go:131: 2023-08-15 09:59:50.901: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: [v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable" t.go:85: 2023-08-15 09:59:50.901 [debu] workspace agent state report workspace_agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 payload={"state":"starting","changed_at":"2023-08-15T09:59:50.900815Z"} request_id=2d1ad2b0-e5da-44db-9041-98bb72ca5e5a t.go:85: 2023-08-15 09:59:50.901 [debu] POST host=localhost:38795 path=/api/v2/workspaceagents/me/report-lifecycle proto=HTTP/1.1 remote_addr=127.0.0.1 took=488.49µs status_code=204 latency_ms=0 request_id=2d1ad2b0-e5da-44db-9041-98bb72ca5e5a ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: [v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: magicsock: disco key = d:0550d4e32039b477" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.901 [debu] net.tailnet.net.wgengine: Creating WireGuard device..." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: Bringing WireGuard device up..." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: wg: [v2] UDP bind has been updated" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] sdk response method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle status=204 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - started" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] reporting lifecycle state payload={\"state\":\"ready\",\"changed_at\":\"2023-08-15T09:59:50.900911Z\"}" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: wg: [v2] Interface state was Down, requested Up, now Up" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] sdk request method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle body=\"\"" ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: Bringing router up..." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: [v1] warning: fakeRouter.Up: not implemented." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: Clearing router settings..." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: Starting network monitor..." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet.net.wgengine: Engine created." ptytest.go:131: 2023-08-15 09:59:50.902: cmd: "2023-08-15 09:59:50.902 [debu] net.tailnet: magicsock debug logging disabled, use CODER_MAGICSOCK_DEBUG_LOGGING=true to enable" ptytest.go:131: 2023-08-15 09:59:50.903: cmd: "2023-08-15 09:59:50.903 [debu] net.tailnet.net.wgengine: magicsock: SetPrivateKey called (init)" ptytest.go:131: 2023-08-15 09:59:50.903: cmd: "2023-08-15 09:59:50.903 [debu] net.tailnet: updating network map" ptytest.go:131: 2023-08-15 09:59:50.903: cmd: "2023-08-15 09:59:50.903 [debu] net.tailnet.net.wgengine: [v1] magicsock: got updated network map; 0 peers" ptytest.go:131: 2023-08-15 09:59:50.903: cmd: "2023-08-15 09:59:50.903 [info] ssh-server: started serving listener listen_addr={}" ptytest.go:131: 2023-08-15 09:59:50.903: cmd: "2023-08-15 09:59:50.903 [debu] sdk request method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-stats body=\"\"" ptytest.go:131: 2023-08-15 09:59:50.903: cmd: "2023-08-15 09:59:50.903 [debu] net.tailnet.net.wgengine: magicsock: endpoints changed: 172.17.0.1:60589 (local), 172.20.0.6:60589 (local)" ptytest.go:131: 2023-08-15 09:59:50.904: cmd: "2023-08-15 09:59:50.904 [debu] net.tailnet: wireguard status status=\"&{AsOf:2023-08-15 09:59:50.904225977 +0000 UTC m=+10.339930301 Peers:[] LocalAddrs:[{Addr:172.17.0.1:60589 Type:local} {Addr:172.20.0.6:60589 Type:local}] DERPs:0}\" error=" ptytest.go:131: 2023-08-15 09:59:50.904: cmd: "2023-08-15 09:59:50.904 [debu] net.tailnet: skipped sending node; no PreferredDERP node=\"&{ID:nodeid:6d26903b48081b11 AsOf:2023-08-15 09:59:50.904298 +0000 UTC Key:nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54 DiscoKey:discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71 PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[172.17.0.1:60589 172.20.0.6:60589]}\"" t.go:85: 2023-08-15 09:59:50.990 [debu] workspace agent state report workspace_agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 payload={"state":"ready","changed_at":"2023-08-15T09:59:50.900911Z"} request_id=b3fb10eb-2eb0-4599-b9f6-a6dfef1e80af t.go:85: 2023-08-15 09:59:50.991 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=88.333802ms status_code=200 latency_ms=88 request_id=ecf3e65b-8ad2-4578-b243-e117124b7b19 t.go:85: 2023-08-15 09:59:50.991 [debu] POST host=localhost:38795 path=/api/v2/workspaceagents/me/report-lifecycle proto=HTTP/1.1 remote_addr=127.0.0.1 took=88.128449ms status_code=204 latency_ms=88 request_id=b3fb10eb-2eb0-4599-b9f6-a6dfef1e80af t.go:85: 2023-08-15 09:59:50.991 [debu] POST host=localhost:38795 path=/api/v2/workspaceagents/me/report-stats proto=HTTP/1.1 remote_addr=127.0.0.1 took=87.162532ms status_code=200 latency_ms=87 request_id=1246f803-e0d9-4efd-89f6-f8054836f08a coderdtest.go:804: agent example not connected yet ptytest.go:131: 2023-08-15 09:59:50.991: cmd: "2023-08-15 09:59:50.991 [debu] sdk response method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle status=204 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:50.991: cmd: "2023-08-15 09:59:50.991 [debu] sdk response method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-stats status=200 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:50.991: cmd: "2023-08-15 09:59:50.991 [debu] running derp map subscriber" ptytest.go:131: 2023-08-15 09:59:50.991: cmd: "2023-08-15 09:59:50.991 [debu] running tailnet connection coordinator" ptytest.go:131: 2023-08-15 09:59:50.992: cmd: "2023-08-15 09:59:50.992 [info] connected to derp map endpoint" t.go:85: 2023-08-15 09:59:51.014 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=22.300053ms status_code=200 latency_ms=22 request_id=a53eef63-8453-4dd2-ab54-9d26fef22744 ptytest.go:131: 2023-08-15 09:59:51.014: cmd: "2023-08-15 09:59:51.014 [info] connected to coordination endpoint" coderdtest.go:804: agent example not connected yet ptytest.go:131: 2023-08-15 09:59:51.014: cmd: "2023-08-15 09:59:51.014 [debu] net.tailnet: skipped sending node; no PreferredDERP node=\"&{ID:nodeid:6d26903b48081b11 AsOf:2023-08-15 09:59:51.014131 +0000 UTC Key:nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54 DiscoKey:discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71 PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[172.17.0.1:60589 172.20.0.6:60589]}\"" t.go:85: 2023-08-15 09:59:51.015 [debu] accepting agent request_id=c6ffaf4d-7a14-4938-b8da-f33510efd20e owner=testuser workspace=upbeat-aryabhata8-p2T name=example t.go:85: 2023-08-15 09:59:51.015 [debu] accepting agent details request_id=c6ffaf4d-7a14-4938-b8da-f33510efd20e agent={"id":"12492c07-3cc3-472e-92d9-6fc4b7f7e4ef","created_at":"2023-08-15T09:59:47.415368Z","updated_at":"2023-08-15T09:59:47.415368Z","name":"example","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":"5f672302-22f0-4f64-9a94-7a6be0d35b39","auth_token":"1b545a4a-bbe0-4a7d-99d8-070f682a7b5b","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","startup_script_timeout_seconds":0,"expanded_directory":"","shutdown_script":{"String":"","Valid":false},"shutdown_script_timeout_seconds":0,"logs_length":0,"logs_overflowed":false,"startup_script_behavior":"non-blocking","started_at":{"Time":"2023-08-15T09:59:50.900815Z","Valid":true},"ready_at":{"Time":"2023-08-15T09:59:50.900911Z","Valid":true},"subsystems":[]} t.go:85: 2023-08-15 09:59:51.015 [debu] coordinating agent agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef t.go:85: 2023-08-15 09:59:51.016 [debu] added agent socket agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ptytest.go:131: 2023-08-15 09:59:51.162: cmd: "2023-08-15 09:59:51.162 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1004stun0 from 95.217.228.124:60589 (43f87183ade06a71795f2e6f) in 257.055809ms" t.go:85: 2023-08-15 09:59:51.162 [debu] GET host=localhost:38795 path=/api/v2/workspaces/84d76d39-a28f-4509-bec8-97732fb947e8 proto=HTTP/1.1 remote_addr=127.0.0.1 took=147.975009ms status_code=200 latency_ms=147 request_id=6387472f-50b6-4261-b565-fefd80ebcb64 ptytest.go:131: 2023-08-15 09:59:51.162: cmd: "2023-08-15 09:59:51.162 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1004stun0 from 95.217.228.124:60589 (5cc5eece7bda33dec260fe84) in 257.154226ms" ptytest.go:131: 2023-08-15 09:59:51.162: cmd: "2023-08-15 09:59:51.162 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1004stun0 from 95.217.228.124:60589 (ed868fb4e80cb6c34c96b00a) in 257.234356ms" portforward_test.go:333: got workspace agents (workspace 84d76d39-a28f-4509-bec8-97732fb947e8) clitest.go:70: invoking command: coder --global-config /tmp/TestDERPHeaders978573694/004 --no-feature-warning --no-version-warning ping upbeat-aryabhata8-p2T -n 1 --header-command printf X-Process-Testing=very-wow --header X-Test-Header=test-value --header Cool-Header=Dean was Here! t.go:85: 2023-08-15 09:59:51.167 [debu] cli-telemetry: report sent request_id=f807f8de-c1bd-4064-9d70-d7026dba7c8e count=1 ptytest.go:131: 2023-08-15 09:59:51.179: cmd: "2023-08-15 09:59:51.178 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1003stun0 from 95.217.228.124:60589 (f56d3d9338a0e7d9044beee5) in 273.724536ms" ptytest.go:131: 2023-08-15 09:59:51.179: cmd: "2023-08-15 09:59:51.179 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1003stun0 from 95.217.228.124:60589 (ccfdb882579d5cfc07069717) in 273.833283ms" ptytest.go:131: 2023-08-15 09:59:51.179: cmd: "2023-08-15 09:59:51.179 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1003stun0 from 95.217.228.124:60589 (0f90fdf5084961b148b4c846) in 273.879997ms" t.go:85: 2023-08-15 09:59:51.182 [debu] GET host=localhost:38795 path=/api/v2/users/me/workspace/upbeat-aryabhata8-p2T proto=HTTP/1.1 remote_addr=127.0.0.1 took=15.582819ms status_code=200 latency_ms=15 request_id=f807f8de-c1bd-4064-9d70-d7026dba7c8e t.go:85: 2023-08-15 09:59:51.183 [debu] GET host=localhost:38795 path=/api/v2/workspaceagents/12492c07-3cc3-472e-92d9-6fc4b7f7e4ef/connection proto=HTTP/1.1 remote_addr=127.0.0.1 took=605.915µs status_code=200 latency_ms=0 request_id=9ab54c58-021c-4e50-962c-f8ce18392842 t.go:85: 2023-08-15 09:59:51.188 [debu] coordinating client client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef t.go:85: 2023-08-15 09:59:51.188 [debu] multiagent node doesn't exist client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef t.go:85: 2023-08-15 09:59:51.189 [debu] agent node doesn't exist client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ptytest.go:131: 2023-08-15 09:59:51.229: cmd: "2023-08-15 09:59:51.229 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1002stun0 from 95.217.228.124:60589 (1b55b6e54b88798f02304228) in 324.509897ms" ptytest.go:131: 2023-08-15 09:59:51.229: cmd: "2023-08-15 09:59:51.229 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1002stun0 from 95.217.228.124:60589 (370d6071ffb6b1ef54c873ff) in 324.574738ms" ptytest.go:131: 2023-08-15 09:59:51.229: cmd: "2023-08-15 09:59:51.229 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1002stun0 from 95.217.228.124:60589 (c37ec0cc0bac36c5c698241a) in 324.587894ms" ptytest.go:131: 2023-08-15 09:59:52.905: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: named node \"1000stun0\" has no address" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest=false hair=false portmap= v4a=95.217.228.124:60589 derp=0" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: named node \"1000stun0\" has no address" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: named node \"1001stun0\" has no address" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: named node \"1001stun0\" has no address" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: named node \"1000stun0\" has no address" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: named node \"1001stun0\" has no address" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: magicsock: home is now derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: magicsock: adding connection to derp-1004 for home-keep-alive" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: magicsock: 1 active derp conns: derp-1004=cr0s,wr0s" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet: wireguard status status=\"&{AsOf:2023-08-15 09:59:52.905837085 +0000 UTC m=+12.341541459 Peers:[] LocalAddrs:[{Addr:172.17.0.1:60589 Type:local} {Addr:172.20.0.6:60589 Type:local}] DERPs:1}\" error=" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet: netinfo callback netinfo=\"NetInfo{varies=false hairpin=false ipv6=false ipv6os=false udp=true icmpv4=false derp=#1004 portmap= link=\\\"\\\"}\"" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.905 [debu] net.tailnet.net.wgengine: derphttp.Client.Connect: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet.net.wgengine: magicsock: endpoints changed: 95.217.228.124:60589 (stun), 172.17.0.1:60589 (local), 172.20.0.6:60589 (local)" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet: sending node node=\"&{ID:nodeid:6d26903b48081b11 AsOf:2023-08-15 09:59:52.90603 +0000 UTC Key:nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54 DiscoKey:discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71 PreferredDERP:1004 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[172.17.0.1:60589 172.20.0.6:60589]}\"" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet: wireguard status status=\"&{AsOf:2023-08-15 09:59:52.906099021 +0000 UTC m=+12.341803375 Peers:[] LocalAddrs:[{Addr:95.217.228.124:60589 Type:stun} {Addr:172.17.0.1:60589 Type:local} {Addr:172.20.0.6:60589 Type:local}] DERPs:1}\" error=" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 12 msec" t.go:85: 2023-08-15 09:59:52.906 [debu] decoded agent node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef node={"id":7865132383535110929,"as_of":"2023-08-15T09:59:52.90603Z","key":"nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54","disco":"discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71","preferred_derp":1004,"derp_latency":{},"derp_forced_websockets":{},"addresses":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"allowed_ips":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"endpoints":["172.17.0.1:60589","172.20.0.6:60589"]} t.go:85: 2023-08-15 09:59:52.906 [debu] enqueued agent node to client agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef client_id=a8084073-db4c-4ccb-8767-09b961a9d459 ptytest.go:131: 2023-08-15 09:59:52.906: cmd: "2023-08-15 09:59:52.906 [debu] net.tailnet: sending node node=\"&{ID:nodeid:6d26903b48081b11 AsOf:2023-08-15 09:59:52.906377 +0000 UTC Key:nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54 DiscoKey:discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71 PreferredDERP:1004 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[95.217.228.124:60589 172.17.0.1:60589 172.20.0.6:60589]}\"" t.go:85: 2023-08-15 09:59:52.906 [debu] decoded agent node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef node={"id":7865132383535110929,"as_of":"2023-08-15T09:59:52.906377Z","key":"nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54","disco":"discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71","preferred_derp":1004,"derp_latency":{},"derp_forced_websockets":{},"addresses":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"allowed_ips":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"endpoints":["95.217.228.124:60589","172.17.0.1:60589","172.20.0.6:60589"]} t.go:85: 2023-08-15 09:59:52.906 [debu] enqueued agent node to client agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef client_id=a8084073-db4c-4ccb-8767-09b961a9d459 t.go:85: 2023-08-15 09:59:52.906 [debu] wrote nodes client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef nodes="[{\"id\":7865132383535110929,\"as_of\":\"2023-08-15T09:59:52.90603Z\",\"key\":\"nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54\",\"disco\":\"discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71\",\"preferred_derp\":1004,\"derp_latency\":{},\"derp_forced_websockets\":{},\"addresses\":[\"fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128\",\"fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128\"],\"allowed_ips\":[\"fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128\",\"fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128\"],\"endpoints\":[\"172.17.0.1:60589\",\"172.20.0.6:60589\"]}]" t.go:85: 2023-08-15 09:59:52.906 [debu] wrote nodes client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef nodes="[{\"id\":7865132383535110929,\"as_of\":\"2023-08-15T09:59:52.906377Z\",\"key\":\"nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54\",\"disco\":\"discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71\",\"preferred_derp\":1004,\"derp_latency\":{},\"derp_forced_websockets\":{},\"addresses\":[\"fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128\",\"fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128\"],\"allowed_ips\":[\"fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128\",\"fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128\"],\"endpoints\":[\"95.217.228.124:60589\",\"172.17.0.1:60589\",\"172.20.0.6:60589\"]}]" ptytest.go:131: 2023-08-15 09:59:52.919: cmd: "2023-08-15 09:59:52.919 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.920: cmd: "2023-08-15 09:59:52.919 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.920: cmd: "2023-08-15 09:59:52.919 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 24 msec" ptytest.go:131: 2023-08-15 09:59:52.945: cmd: "2023-08-15 09:59:52.945 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.945: cmd: "2023-08-15 09:59:52.945 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:52.945: cmd: "2023-08-15 09:59:52.945 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 96 msec" ptytest.go:131: 2023-08-15 09:59:53.042: cmd: "2023-08-15 09:59:53.042 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.042: cmd: "2023-08-15 09:59:53.042 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.042: cmd: "2023-08-15 09:59:53.042 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 96 msec" ptytest.go:131: 2023-08-15 09:59:53.139: cmd: "2023-08-15 09:59:53.139 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.139: cmd: "2023-08-15 09:59:53.139 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.139: cmd: "2023-08-15 09:59:53.139 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 233 msec" ptytest.go:131: 2023-08-15 09:59:53.163: cmd: "2023-08-15 09:59:53.163 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1004stun0 from 95.217.228.124:60589 (a53c11e27582e7c078c0f111) in 256.940658ms" ptytest.go:131: 2023-08-15 09:59:53.163: cmd: "2023-08-15 09:59:53.163 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1004stun0 from 95.217.228.124:60589 (42731056b37f09c4873c155d) in 256.935448ms" ptytest.go:131: 2023-08-15 09:59:53.163: cmd: "2023-08-15 09:59:53.163 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1004stun0 from 95.217.228.124:60589 (3c3862c79082036d7a69bad6) in 256.978574ms" ptytest.go:131: 2023-08-15 09:59:53.180: cmd: "2023-08-15 09:59:53.180 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1003stun0 from 95.217.228.124:60589 (1f021f2d129552a191ee6873) in 273.757122ms" ptytest.go:131: 2023-08-15 09:59:53.180: cmd: "2023-08-15 09:59:53.180 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1003stun0 from 95.217.228.124:60589 (a14e700a049210358e7f73ad) in 273.813956ms" ptytest.go:131: 2023-08-15 09:59:53.180: cmd: "2023-08-15 09:59:53.180 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1003stun0 from 95.217.228.124:60589 (91861f403eb7b498cab96e51) in 273.829046ms" t.go:85: 2023-08-15 09:59:53.187 [debu] got client node update client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 node={"id":8350398848642747947,"as_of":"2023-08-15T09:59:53.186985Z","key":"nodekey:54f4bf0d8f14a99d092e05554befb87dfba4cd9988cebbbe1e1c0872c182f21c","disco":"discokey:b7a07669535b1a7e7299953155dddbd68d3f65aa2bb8ebec9d7af27a81f80e2f","preferred_derp":1001,"derp_latency":{},"derp_forced_websockets":{},"addresses":["fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128"],"allowed_ips":["fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128"],"endpoints":["172.17.0.1:54237","172.20.0.6:54237"]} t.go:85: 2023-08-15 09:59:53.187 [debu] enqueued node to agents client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 agent_ids=[12492c07-3cc3-472e-92d9-6fc4b7f7e4ef] t.go:85: 2023-08-15 09:59:53.187 [debu] wrote nodes agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef nodes="[{\"id\":8350398848642747947,\"as_of\":\"2023-08-15T09:59:53.186985Z\",\"key\":\"nodekey:54f4bf0d8f14a99d092e05554befb87dfba4cd9988cebbbe1e1c0872c182f21c\",\"disco\":\"discokey:b7a07669535b1a7e7299953155dddbd68d3f65aa2bb8ebec9d7af27a81f80e2f\",\"preferred_derp\":1001,\"derp_latency\":{},\"derp_forced_websockets\":{},\"addresses\":[\"fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128\"],\"allowed_ips\":[\"fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128\"],\"endpoints\":[\"172.17.0.1:54237\",\"172.20.0.6:54237\"]}]" t.go:85: 2023-08-15 09:59:53.187 [debu] got client node update client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 node={"id":8350398848642747947,"as_of":"2023-08-15T09:59:53.187352Z","key":"nodekey:54f4bf0d8f14a99d092e05554befb87dfba4cd9988cebbbe1e1c0872c182f21c","disco":"discokey:b7a07669535b1a7e7299953155dddbd68d3f65aa2bb8ebec9d7af27a81f80e2f","preferred_derp":1001,"derp_latency":{},"derp_forced_websockets":{},"addresses":["fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128"],"allowed_ips":["fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128"],"endpoints":["95.217.228.124:54237","172.17.0.1:54237","172.20.0.6:54237"]} t.go:85: 2023-08-15 09:59:53.187 [debu] enqueued node to agents client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 agent_ids=[12492c07-3cc3-472e-92d9-6fc4b7f7e4ef] t.go:85: 2023-08-15 09:59:53.187 [debu] wrote nodes agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef nodes="[{\"id\":8350398848642747947,\"as_of\":\"2023-08-15T09:59:53.187352Z\",\"key\":\"nodekey:54f4bf0d8f14a99d092e05554befb87dfba4cd9988cebbbe1e1c0872c182f21c\",\"disco\":\"discokey:b7a07669535b1a7e7299953155dddbd68d3f65aa2bb8ebec9d7af27a81f80e2f\",\"preferred_derp\":1001,\"derp_latency\":{},\"derp_forced_websockets\":{},\"addresses\":[\"fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128\"],\"allowed_ips\":[\"fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128\"],\"endpoints\":[\"95.217.228.124:54237\",\"172.17.0.1:54237\",\"172.20.0.6:54237\"]}]" ptytest.go:131: 2023-08-15 09:59:53.187: cmd: "2023-08-15 09:59:53.187 [debu] net.tailnet: adding node node=\"&{ID:nodeid:73e29382b22e8e2b AsOf:2023-08-15 09:59:53.186985 +0000 UTC Key:nodekey:54f4bf0d8f14a99d092e05554befb87dfba4cd9988cebbbe1e1c0872c182f21c DiscoKey:discokey:b7a07669535b1a7e7299953155dddbd68d3f65aa2bb8ebec9d7af27a81f80e2f PreferredDERP:1001 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128] AllowedIPs:[fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128] Endpoints:[172.17.0.1:54237 172.20.0.6:54237]}\"" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.187 [debu] net.tailnet: updating network map" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: [v1] magicsock: got updated network map; 1 peers" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.netstack: [v2] netstack: registered IP fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.netstack: [v2] netstack: registered IP fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: wgengine: Reconfig: configuring userspace WireGuard config (with 0/1 peers)" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: wg: [v2] UAPI: Updating private key" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: wgengine: Reconfig: configuring router" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented." ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: wgengine: Reconfig: configuring DNS" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: [v1] wgengine: Reconfig done" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet: adding node node=\"&{ID:nodeid:73e29382b22e8e2b AsOf:2023-08-15 09:59:53.187352 +0000 UTC Key:nodekey:54f4bf0d8f14a99d092e05554befb87dfba4cd9988cebbbe1e1c0872c182f21c DiscoKey:discokey:b7a07669535b1a7e7299953155dddbd68d3f65aa2bb8ebec9d7af27a81f80e2f PreferredDERP:1001 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128] AllowedIPs:[fd7a:115c:a1e0:4451:aad8:c196:14cd:6d04/128] Endpoints:[95.217.228.124:54237 172.17.0.1:54237 172.20.0.6:54237]}\"" ptytest.go:131: 2023-08-15 09:59:53.188: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet: updating network map" ptytest.go:131: 2023-08-15 09:59:53.189: cmd: "2023-08-15 09:59:53.188 [debu] net.tailnet.net.wgengine: [v1] magicsock: got updated network map; 1 peers" ptytest.go:131: 2023-08-15 09:59:53.189: cmd: "2023-08-15 09:59:53.189 [debu] net.tailnet.net.wgengine: [v1] wgengine: Reconfig done" ptytest.go:131: 2023-08-15 09:59:53.190: cmd: "p2p connection established in 0s" ptytest.go:131: 2023-08-15 09:59:53.190: cmd: "pong from upbeat-aryabhata8-p2T p2p via 172.20.0.6:60589 in 0s" root_test.go:193: 2023-08-15 09:59:53.190: cmd: matched "pong from upbeat-aryabhata8-p2T" = "p2p connection established in 0s\r\npong from upbeat-aryabhata8-p2T" t.go:85: 2023-08-15 09:59:53.190 [debu] unable to read client update, connection may be closed client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ... error= read json: github.com/coder/coder/tailnet.(*coordinator).handleNextClientMessage /home/coder/repos/coder/tailnet/coordinator.go:350 - failed to get reader: failed to read frame header: EOF t.go:85: 2023-08-15 09:59:53.190 [debu] deleted client node client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 t.go:85: 2023-08-15 09:59:53.190 [debu] deleted client connectionSocket from map client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef t.go:85: 2023-08-15 09:59:53.190 [debu] deleted last client connectionSocket from map client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef t.go:85: 2023-08-15 09:59:53.190 [debu] deleted client agents client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=00000000-0000-0000-0000-000000000000 t.go:85: 2023-08-15 09:59:53.190 [debu] GET host=localhost:38795 path=/api/v2/workspaceagents/12492c07-3cc3-472e-92d9-6fc4b7f7e4ef/coordinate proto=HTTP/1.1 remote_addr=127.0.0.1 took=2.004449102s status_code=101 latency_ms=2004 request_id=9381fbf9-ee06-4121-a7c7-536739a1332f t.go:85: 2023-08-15 09:59:53.190 [debu] done sending updates client_id=a8084073-db4c-4ccb-8767-09b961a9d459 agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ptytest.go:131: 2023-08-15 09:59:53.231: cmd: "2023-08-15 09:59:53.231 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1002stun0 from 95.217.228.124:60589 (53d55153a3521804636e7e3f) in 324.551703ms" ptytest.go:131: 2023-08-15 09:59:53.231: cmd: "2023-08-15 09:59:53.231 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1002stun0 from 95.217.228.124:60589 (e7c930c4e6ba75e011829663) in 324.630922ms" ptytest.go:131: 2023-08-15 09:59:53.231: cmd: "2023-08-15 09:59:53.231 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1002stun0 from 95.217.228.124:60589 (dd8158bf5b6a67ba1d5cc955) in 324.715612ms" root_test.go:196: Error Trace: /home/coder/repos/coder/cli/root_test.go:196 Error: "0" is not greater than "0" Test: TestDERPHeaders Messages: expected /derp to be called at least once ptytest.go:95: 2023-08-15 09:59:53.239: cmd: closing expecter: PTY close ptytest.go:120: 2023-08-15 09:59:53.239: cmd: copy done: ptytest.go:121: 2023-08-15 09:59:53.239: cmd: closing out ptytest.go:123: 2023-08-15 09:59:53.239: cmd: closed out: ptytest.go:86: 2023-08-15 09:59:53.239: cmd: closing logw ptytest.go:88: 2023-08-15 09:59:53.239: cmd: closed logw: ptytest.go:86: 2023-08-15 09:59:53.239: cmd: closing logr ptytest.go:88: 2023-08-15 09:59:53.239: cmd: closed logr: ptytest.go:112: 2023-08-15 09:59:53.239: cmd: closed expecter ptytest.go:131: 2023-08-15 09:59:53.239: cmd: "2023-08-15 09:59:53.239 [info] shutting down agent" ptytest.go:131: 2023-08-15 09:59:53.239: cmd: "2023-08-15 09:59:53.239 [debu] set lifecycle state current={\"state\":\"shutting_down\",\"changed_at\":\"2023-08-15T09:59:53.239498Z\"} last={\"state\":\"ready\",\"changed_at\":\"2023-08-15T09:59:50.900911Z\"}" ptytest.go:131: 2023-08-15 09:59:53.239: cmd: "2023-08-15 09:59:53.239 [debu] set lifecycle state current={\"state\":\"off\",\"changed_at\":\"2023-08-15T09:59:53.239558Z\"} last={\"state\":\"shutting_down\",\"changed_at\":\"2023-08-15T09:59:53.239498Z\"}" ptytest.go:131: 2023-08-15 09:59:53.239: cmd: "2023-08-15 09:59:53.239 [debu] reporting lifecycle state payload={\"state\":\"shutting_down\",\"changed_at\":\"2023-08-15T09:59:53.239498Z\"}" ptytest.go:131: 2023-08-15 09:59:53.239: cmd: "2023-08-15 09:59:53.239 [debu] sdk request method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle body=\"\"" t.go:85: 2023-08-15 09:59:53.240 [debu] workspace agent state report workspace_agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 payload={"state":"shutting_down","changed_at":"2023-08-15T09:59:53.239498Z"} request_id=7109cb2f-97b7-4e4c-8c02-d219eb61c480 t.go:85: 2023-08-15 09:59:53.240 [debu] POST host=localhost:38795 path=/api/v2/workspaceagents/me/report-lifecycle proto=HTTP/1.1 remote_addr=127.0.0.1 took=459.812µs status_code=204 latency_ms=0 request_id=7109cb2f-97b7-4e4c-8c02-d219eb61c480 ptytest.go:131: 2023-08-15 09:59:53.240: cmd: "2023-08-15 09:59:53.240 [debu] sdk response method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle status=204 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:53.374: cmd: "2023-08-15 09:59:53.374 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.375: cmd: "2023-08-15 09:59:53.375 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.375: cmd: "2023-08-15 09:59:53.375 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 534 msec" ptytest.go:131: 2023-08-15 09:59:53.911: cmd: "2023-08-15 09:59:53.911 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.911: cmd: "2023-08-15 09:59:53.911 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:53.911: cmd: "2023-08-15 09:59:53.911 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 293 msec" ptytest.go:131: 2023-08-15 09:59:54.098: cmd: "2023-08-15 09:59:54.098 [debu] net.tailnet.net.wgengine: netcheck: [v1] measuring ICMP latency of coder (999): no address for node 999b" t.go:85: 2023-08-15 09:59:54.098 [debu] GET host=localhost path=/derp/latency-check proto=HTTP/1.1 remote_addr=127.0.0.1 took=115.873µs status_code=200 latency_ms=0 request_id=77738bd9-feea-46f7-a9a3-19fb9776ddc1 ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest=false hair=false portmap= v4a=95.217.228.124:60589 derp=999 derpdist=999v4:0s" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet.net.wgengine: magicsock: home is now derp-999 (coder)" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet.net.wgengine: magicsock: adding connection to derp-999 for home-keep-alive" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet: netinfo callback netinfo=\"NetInfo{varies=false hairpin=false ipv6=false ipv6os=false udp=true icmpv4=false derp=#999 portmap= link=\\\"\\\"}\"" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet.net.wgengine: magicsock: 2 active derp conns: derp-999=cr0s,wr0s derp-1004=cr1s,wr1s" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet: sending node node=\"&{ID:nodeid:6d26903b48081b11 AsOf:2023-08-15 09:59:54.09948 +0000 UTC Key:nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54 DiscoKey:discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71 PreferredDERP:999 DERPLatency:map[999-v4:0.000482367] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[95.217.228.124:60589 172.17.0.1:60589 172.20.0.6:60589]}\"" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-999 (coder)" ptytest.go:131: 2023-08-15 09:59:54.099: cmd: "2023-08-15 09:59:54.099 [debu] net.tailnet: wireguard status status=\"&{AsOf:2023-08-15 09:59:54.099558703 +0000 UTC m=+13.535263068 Peers:[] LocalAddrs:[{Addr:95.217.228.124:60589 Type:stun} {Addr:172.17.0.1:60589 Type:local} {Addr:172.20.0.6:60589 Type:local}] DERPs:2}\" error=" t.go:85: 2023-08-15 09:59:54.102 [debu] decoded agent node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef node={"id":7865132383535110929,"as_of":"2023-08-15T09:59:54.09948Z","key":"nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54","disco":"discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71","preferred_derp":999,"derp_latency":{"999-v4":0.000482367},"derp_forced_websockets":{},"addresses":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"allowed_ips":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"endpoints":["95.217.228.124:60589","172.17.0.1:60589","172.20.0.6:60589"]} t.go:85: 2023-08-15 09:59:54.102 [debu] no client sockets; unable to send node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ptytest.go:131: 2023-08-15 09:59:54.103: cmd: "2023-08-15 09:59:54.103 [debu] net.tailnet.net.wgengine: magicsock: derp-999 connected; connGen=1" ptytest.go:131: 2023-08-15 09:59:54.117: cmd: "2023-08-15 09:59:54.116 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 95.217.228.124:60589 (b732daa520f0e7a1c5712cb5) in 16.360769ms" ptytest.go:131: 2023-08-15 09:59:54.205: cmd: "2023-08-15 09:59:54.205 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:54.206: cmd: "2023-08-15 09:59:54.205 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:54.206: cmd: "2023-08-15 09:59:54.206 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 460 msec" ptytest.go:131: 2023-08-15 09:59:54.252: cmd: "2023-08-15 09:59:54.252 [debu] net.tailnet.net.wgengine: netcheck: [v1] measuring ICMP latency of coder (999): no address for node 999b" t.go:85: 2023-08-15 09:59:54.253 [debu] GET host=localhost path=/derp/latency-check proto=HTTP/1.1 remote_addr=127.0.0.1 took=76.724µs status_code=200 latency_ms=0 request_id=fd0cdf8c-cec2-4a44-8508-2b342ca0e43f ptytest.go:131: 2023-08-15 09:59:54.253: cmd: "2023-08-15 09:59:54.253 [debu] net.tailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest= hair=false portmap= v4a=95.217.228.124:60589 derp=999 derpdist=999v4:0s" ptytest.go:131: 2023-08-15 09:59:54.253: cmd: "2023-08-15 09:59:54.253 [debu] net.tailnet: netinfo callback netinfo=\"NetInfo{varies= hairpin=false ipv6=false ipv6os=false udp=true icmpv4=false derp=#999 portmap= link=\\\"\\\"}\"" ptytest.go:131: 2023-08-15 09:59:54.253: cmd: "2023-08-15 09:59:54.253 [debu] net.tailnet: sending node node=\"&{ID:nodeid:6d26903b48081b11 AsOf:2023-08-15 09:59:54.253673 +0000 UTC Key:nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54 DiscoKey:discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71 PreferredDERP:999 DERPLatency:map[999-v4:0.000318749] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] AllowedIPs:[fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128 fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128] Endpoints:[95.217.228.124:60589 172.17.0.1:60589 172.20.0.6:60589]}\"" t.go:85: 2023-08-15 09:59:54.254 [debu] decoded agent node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef node={"id":7865132383535110929,"as_of":"2023-08-15T09:59:54.253673Z","key":"nodekey:04b2dd36773f8b619c6a5a3ade814805215181f29b7e4eff23e1e666270daa54","disco":"discokey:0550d4e32039b477702e07510beb3399fcd7ede3f431f93c5c9f0e85ab2ebe71","preferred_derp":999,"derp_latency":{"999-v4":0.000318749},"derp_forced_websockets":{},"addresses":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"allowed_ips":["fd7a:115c:a1e0:472e:92d9:6fc4:b7f7:e4ef/128","fd7a:115c:a1e0:49d6:b259:b7ac:b1b2:48f4/128"],"endpoints":["95.217.228.124:60589","172.17.0.1:60589","172.20.0.6:60589"]} t.go:85: 2023-08-15 09:59:54.254 [debu] no client sockets; unable to send node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ptytest.go:131: 2023-08-15 09:59:54.270: cmd: "2023-08-15 09:59:54.270 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 95.217.228.124:60589 (68711b2d3c1ac129fa213860) in 16.352992ms" ptytest.go:131: 2023-08-15 09:59:54.406: cmd: "2023-08-15 09:59:54.406 [debu] net.tailnet.net.wgengine: netcheck: [v1] measuring ICMP latency of coder (999): no address for node 999b" t.go:85: 2023-08-15 09:59:54.406 [debu] GET host=localhost path=/derp/latency-check proto=HTTP/1.1 remote_addr=127.0.0.1 took=109.579µs status_code=200 latency_ms=0 request_id=fd45cfdc-5f12-4453-9c07-cbcd00d8596a ptytest.go:131: 2023-08-15 09:59:54.407: cmd: "2023-08-15 09:59:54.407 [debu] net.tailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest= hair=false portmap= v4a=95.217.228.124:60589 derp=999 derpdist=999v4:0s" ptytest.go:131: 2023-08-15 09:59:54.667: cmd: "2023-08-15 09:59:54.667 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:54.667: cmd: "2023-08-15 09:59:54.667 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:54.667: cmd: "2023-08-15 09:59:54.667 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 444 msec" ptytest.go:131: 2023-08-15 09:59:54.684: cmd: "2023-08-15 09:59:54.684 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 95.217.228.124:60589 (d18d257dd3f6590c64a66ed1) in 16.627142ms" ptytest.go:131: 2023-08-15 09:59:54.819: cmd: "2023-08-15 09:59:54.819 [debu] net.tailnet.net.wgengine: netcheck: [v1] measuring ICMP latency of coder (999): no address for node 999b" t.go:85: 2023-08-15 09:59:54.820 [debu] GET host=localhost path=/derp/latency-check proto=HTTP/1.1 remote_addr=127.0.0.1 took=102.816µs status_code=200 latency_ms=0 request_id=4ec89102-a82c-49fe-a6d2-205ff3491fca ptytest.go:131: 2023-08-15 09:59:54.820: cmd: "2023-08-15 09:59:54.820 [debu] net.tailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest= hair=false portmap= v4a=95.217.228.124:60589 derp=999 derpdist=999v4:0s" ptytest.go:131: 2023-08-15 09:59:55.111: cmd: "2023-08-15 09:59:55.111 [debu] net.tailnet.net.wgengine: derphttp.Client.Recv: connecting to derp-1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:55.112: cmd: "2023-08-15 09:59:55.111 [debu] net.tailnet.net.wgengine: magicsock: [0xc0602c6c80] derp.Recv(derp-1004): derphttp.Client.Recv connect to region 1004 (coder_stun_1004): no non-STUNOnly nodes for region 1004 (coder_stun_1004)" ptytest.go:131: 2023-08-15 09:59:55.112: cmd: "2023-08-15 09:59:55.111 [debu] net.tailnet.net.wgengine: derp-1004: [v1] backoff: 537 msec" ptytest.go:131: 2023-08-15 09:59:55.128: cmd: "2023-08-15 09:59:55.128 [debu] net.tailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 95.217.228.124:60589 (f2f9850aa944e31e5f31299e) in 16.462503ms" ptytest.go:131: 2023-08-15 09:59:55.241: cmd: "2023-08-15 09:59:55.241 [debu] reporting lifecycle state payload={\"state\":\"off\",\"changed_at\":\"2023-08-15T09:59:53.239558Z\"}" ptytest.go:131: 2023-08-15 09:59:55.241: cmd: "2023-08-15 09:59:55.241 [debu] sdk request method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle body=\"\"" t.go:85: 2023-08-15 09:59:55.242 [debu] workspace agent state report workspace_agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef workspace_id=84d76d39-a28f-4509-bec8-97732fb947e8 payload={"state":"off","changed_at":"2023-08-15T09:59:53.239558Z"} request_id=e2c94f0a-a3f5-4f6e-893f-8ccf5a45b2e6 t.go:85: 2023-08-15 09:59:55.242 [debu] POST host=localhost:38795 path=/api/v2/workspaceagents/me/report-lifecycle proto=HTTP/1.1 remote_addr=127.0.0.1 took=441.255µs status_code=204 latency_ms=0 request_id=e2c94f0a-a3f5-4f6e-893f-8ccf5a45b2e6 ptytest.go:131: 2023-08-15 09:59:55.242: cmd: "2023-08-15 09:59:55.242 [debu] sdk response method=POST url=http://localhost:38795/api/v2/workspaceagents/me/report-lifecycle status=204 body=\"\" trace_id=\"\" span_id=\"\"" ptytest.go:131: 2023-08-15 09:59:55.242: cmd: "2023-08-15 09:59:55.242 [debu] derp map pinger exited" ptytest.go:131: 2023-08-15 09:59:55.242: cmd: "2023-08-15 09:59:55.242 [info] ssh-server: stopped serving listener listen_addr={} ..." ptytest.go:131: 2023-08-15 09:59:55.242: cmd: " error= tailnet:" ptytest.go:131: 2023-08-15 09:59:55.242: cmd: " github.com/coder/coder/tailnet.(*listener).Accept" ptytest.go:131: 2023-08-15 09:59:55.242: cmd: " /home/coder/repos/coder/tailnet/conn.go:971" ptytest.go:131: 2023-08-15 09:59:55.242: cmd: " - use of closed network connection" ptytest.go:131: 2023-08-15 09:59:55.242: cmd: "2023-08-15 09:59:55.242 [debu] coordinate pinger exited" t.go:85: 2023-08-15 09:59:55.242 [debu] unable to read agent update, connection may be closed agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ... error= read json: github.com/coder/coder/tailnet.(*coordinator).handleNextAgentMessage /home/coder/repos/coder/tailnet/coordinator.go:552 - failed to get reader: failed to read frame header: EOF t.go:85: 2023-08-15 09:59:55.243 [debu] deleted agent socket and node agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef t.go:85: 2023-08-15 09:59:55.243 [debu] done sending updates agent_id=12492c07-3cc3-472e-92d9-6fc4b7f7e4ef ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.242 [debu] net.tailnet.net.wgengine: magicsock: disco: node [VPS/D] d:b7a07669535b1a7e now using DERP only (reset)" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: magicsock: closing connection to derp-1004 (conn-close), age 2s" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: magicsock: closing connection to derp-999 (conn-close), age 1s" t.go:85: 2023-08-15 09:59:55.243 [debu] GET host=localhost:38795 path=/api/v2/workspaceagents/me/coordinate proto=HTTP/1.1 remote_addr=127.0.0.1 took=4.250794464s status_code=101 latency_ms=4250 request_id=c6ffaf4d-7a14-4938-b8da-f33510efd20e ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=false mapvarydest= hair=false portmap= v4a=95.217.228.124:60589 derp=0" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: magicsock: 0 active derp conns" t.go:85: 2023-08-15 09:59:55.243 [debu] GET host=localhost path=/derp proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.141116164s status_code=0 latency_ms=1141 request_id=51ea20b4-a178-40ad-a0cd-76a8bb25afe3 ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: [v1] warning: fakeRouter.Close: not implemented." ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: wg: [v2] Device closing" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - stopped" ptytest.go:131: 2023-08-15 09:59:55.243: cmd: "2023-08-15 09:59:55.243 [debu] net.tailnet.net.wgengine: wg: [v2] Device closed" ptytest.go:95: 2023-08-15 09:59:55.243: cmd: closing expecter: PTY close ptytest.go:120: 2023-08-15 09:59:55.243: cmd: copy done: ptytest.go:121: 2023-08-15 09:59:55.243: cmd: closing out ptytest.go:123: 2023-08-15 09:59:55.243: cmd: closed out: ptytest.go:86: 2023-08-15 09:59:55.243: cmd: closing logw ptytest.go:88: 2023-08-15 09:59:55.243: cmd: closed logw: ptytest.go:86: 2023-08-15 09:59:55.243: cmd: closing logr ptytest.go:88: 2023-08-15 09:59:55.243: cmd: closed logr: ptytest.go:112: 2023-08-15 09:59:55.243: cmd: closed expecter t.go:85: 2023-08-15 09:59:55.243 [debu] provisionerd: closing server with error error= t.go:85: 2023-08-15 09:59:55.243 [info] inmem-provisionerd-sweet_meitner3: provisioner daemon disconnected error= t.go:85: 2023-08-15 09:59:55.243 [debu] GET host=localhost:38795 path=/api/v2/derp-map proto=HTTP/1.1 remote_addr=127.0.0.1 took=4.25169022s status_code=101 latency_ms=4251 request_id=f22a012e-1d1f-4306-820d-4a2d6c4fcf37 t.go:85: 2023-08-15 09:59:55.243 [debu] GET host=localhost:38795 path=/api/v2/derp-map proto=HTTP/1.1 remote_addr=127.0.0.1 took=4.057573143s status_code=101 latency_ms=4057 request_id=f7baea03-98c2-40a0-898d-8d37eeb51428