bug: test timeout waiting for builds #7403
Description
On macOS CI builds, I saw two tests time out waiting for template version builds. The builds start just fine, just take a long time.
We need either longer timeouts (right now it's 10s), less parallelism on our CI, or more powerful runners.
=== FAIL: coderd TestWorkspaceAgentListen/FailNonLatestBuild (13.58s)
t.go:81: 2023-05-03 08:28:11.468 [DEBUG] (metrics_cache) <github.com/coder/coder/coderd/metricscache/metricscache.go:272> (*Cache).run deployment stats metrics refreshed {"took": "12.503µs", "interval": "5m0s"}
t.go:81: 2023-05-03 08:28:11.468 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:201> (*Server).connect connected
t.go:81: 2023-05-03 08:28:11.470 [DEBUG] (metrics_cache) <github.com/coder/coder/coderd/metricscache/metricscache.go:272> (*Cache).run template daus metrics refreshed {"took": "1.703312ms", "interval": "1h0m0s"}
t.go:81: 2023-05-03 08:28:11.504 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/users/first", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.968109ms", "status_code": 201, "latency_ms": 5, "request_id": "60920831-b732-4904-b09a-37b2d279ef3f"}
t.go:81: 2023-05-03 08:28:11.507 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/users/login", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "2.771493ms", "status_code": 201, "latency_ms": 2, "request_id": "5cb6ea69-0ca1-4dff-9f57-c491267b445e"}
t.go:81: 2023-05-03 08:28:11.519 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/files", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.475533ms", "status_code": 201, "latency_ms": 3, "request_id": "7f5870d5-3bc4-49a7-8bf2-cff0d7d04e3c"}
t.go:81: 2023-05-03 08:28:11.525 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/organizations/1e84558c-d76f-47b8-968d-625d9d3251c5/templateversions", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.185027ms", "status_code": 201, "latency_ms": 5, "request_id": "e4c3c0da-ccd9-468c-ab67-522081af2472"}
t.go:81: 2023-05-03 08:28:11.531 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/organizations/1e84558c-d76f-47b8-968d-625d9d3251c5/templates", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.452217ms", "status_code": 201, "latency_ms": 5, "request_id": "8f2d6017-3fce-4e98-be99-2e2931996c9c"}
workspaceagents_test.go:358: waiting for template version job 98eb1753-9c4d-4f80-851a-b3f809be2658
t.go:81: 2023-05-03 08:28:11.582 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "6.200301ms", "status_code": 200, "latency_ms": 6, "request_id": "f5a591cf-87f7-43b4-8759-341612f4e639"}
t.go:81: 2023-05-03 08:28:11.612 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.992556ms", "status_code": 200, "latency_ms": 4, "request_id": "380c8057-ca59-4efc-89d4-c0014954e70c"}
t.go:81: 2023-05-03 08:28:11.631 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "7.3[433](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:434)88ms", "status_code": 200, "latency_ms": 7, "request_id": "0badd032-7e2f-4289-935b-144e2fdf31af"}
t.go:81: 2023-05-03 08:28:11.647 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.070877ms", "status_code": 200, "latency_ms": 5, "request_id": "a16c2502-3645-44e1-971b-6f10c4498abc"}
t.go:81: 2023-05-03 08:28:11.677 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.072995ms", "status_code": 200, "latency_ms": 4, "request_id": "577ab86b-03bf-4741-bf98-1c07d8a45ce5"}
t.go:81: 2023-05-03 08:28:11.690 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.430742ms", "status_code": 200, "latency_ms": 5, "request_id": "6f04228c-8a55-4042-8c5a-0a38e5ca2b23"}
t.go:81: 2023-05-03 08:28:11.724 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:105> (*Server).AcquireJob locked job from database {"id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.732 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:378> (*Server).acquireJob acquired job {"initiator_username": "testuser", "provisioner": "echo", "job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.733 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:[435](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:436)> (*Runner).do unpacking template source archive {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "size_bytes": 3072}
t.go:81: 2023-05-03 08:28:11.733 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.parse.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:11.733 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "size_bytes": 114, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:11.734 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:11.734 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:491> (*Runner).do acquired job is template import {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "user_variable_values": null}
t.go:81: 2023-05-03 08:28:11.732 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "14.764451ms", "status_code": 200, "latency_ms": 14, "request_id": "344f8993-299d-4d2c-a244-376fa37e5ada"}
t.go:81: 2023-05-03 08:28:11.735 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:723> (*Runner).runTemplateImportParse parse complete {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "parameter_schemas": null, "template_variables": null}
t.go:81: 2023-05-03 08:28:11.736 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.745 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:825> (*Runner).runTemplateImportProvisionWithRichParameters parse dry-run provision successful {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "resource_count": 0, "resources": null, "state_length": 0}
t.go:81: 2023-05-03 08:28:11.747 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:825> (*Runner).runTemplateImportProvisionWithRichParameters parse dry-run provision successful {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "resource_count": 0, "resources": null, "state_length": 0}
t.go:81: 2023-05-03 08:28:11.747 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:405> (*Runner).doCleanFinish.func2 cleaned up work directory {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.747 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.749 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "stage": "Setting up", "output": ""}
t.go:81: 2023-05-03 08:28:11.749 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "stage": "No README.md provided", "output": ""}
t.go:81: 2023-05-03 08:28:11.749 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "stage": "Parsing template parameters", "output": ""}
t.go:81: 2023-05-03 08:28:11.749 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "stage": "Detecting persistent resources", "output": ""}
t.go:81: 2023-05-03 08:28:11.750 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "stage": "Detecting ephemeral resources", "output": ""}
t.go:81: 2023-05-03 08:28:11.750 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094", "stage": "Cleaning Up", "output": ""}
t.go:81: 2023-05-03 08:28:11.750 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.750 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.750 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:230> (*Runner).Run sending CompletedJob {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.753 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:831> (*Server).CompleteJob CompleteJob starting {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.757 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:942> (*Server).CompleteJob marked import job as completed {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.759 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1191> (*Server).CompleteJob CompleteJob done {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.765 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:235> (*Runner).Run sent CompletedJob {"job_id": "f57ea9f8-cd9d-46ca-bd47-8942e865c094"}
t.go:81: 2023-05-03 08:28:11.778 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/98eb1753-9c4d-4f80-851a-b3f809be2658", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "7.965662ms", "status_code": 200, "latency_ms": 7, "request_id": "34d6d7bb-def8-4c19-9c59-2b7b8c71c281"}
workspaceagents_test.go:358: got template version job 98eb1753-9c4d-4f80-851a-b3f809be2658
t.go:81: 2023-05-03 08:28:11.840 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/organizations/1e84558c-d76f-47b8-968d-625d9d3251c5/members/me/workspaces", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "31.327999ms", "status_code": 201, "latency_ms": 31, "request_id": "5f6291fb-7837-44ac-8dd4-cd0aa8338e3f"}
workspaceagents_test.go:360: waiting for workspace build job c5e1d950-abfd-41d3-97fc-3179249ee589
t.go:81: 2023-05-03 08:28:11.996 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/workspacebuilds/c5e1d950-abfd-41d3-97fc-3179249ee589", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "9.514409ms", "status_code": 200, "latency_ms": 9, "request_id": "85003a94-450a-4cc1-88c5-03d5c7c80b75"}
t.go:81: 2023-05-03 08:28:12.370 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:105> (*Server).AcquireJob locked job from database {"id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.494 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/workspacebuilds/c5e1d950-abfd-41d3-97fc-3179249ee589", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "408.264696ms", "status_code": 200, "latency_ms": 408, "request_id": "58f21080-154f-4b0f-980c-b6d275e14a74"}
t.go:81: 2023-05-03 08:28:12.508 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/workspacebuilds/c5e1d950-abfd-41d3-97fc-3179249ee589", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.615827ms", "status_code": 200, "latency_ms": 4, "request_id": "a5309e46-da01-4d8c-ad66-a7c1c5d3d00c"}
t.go:81: 2023-05-03 08:28:12.511 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:378> (*Server).acquireJob acquired job {"initiator_username": "testuser", "provisioner": "echo", "job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "workspace_transition": "START", "workspace_owner": "testuser", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI"}
t.go:81: 2023-05-03 08:28:12.523 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:435> (*Runner).do unpacking template source archive {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "size_bytes": 3072}
t.go:81: 2023-05-03 08:28:12.525 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.parse.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:12.526 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "size_bytes": 114, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:12.527 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:12.528 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:509> (*Runner).do acquired job is workspace provision {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "workspace_name": "nervous-mirzakhani1-KmI", "state_length": 0, "parameters": null, "rich_parameter_values": null, "variable_values": null}
t.go:81: 2023-05-03 08:28:12.531 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:962> (*Runner).buildWorkspace provision successful {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "resource_count": 0, "resources": null, "state_length": 0}
t.go:81: 2023-05-03 08:28:12.532 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.536 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "stage": "Setting up", "output": ""}
t.go:81: 2023-05-03 08:28:12.539 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.539 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.540 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.542 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:962> (*Runner).buildWorkspace provision successful {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start", "resource_count": 1, "resources": [{"name": "example", "type": "aws_instance", "agents": [{"id": "4dc6dfa3-7315-4002-97b6-f2477d91c4f4", "name": "example", "Auth": {"Token": "2c1adc6f-aef0-4a60-b308-a2bc8fa394d9"}}]}], "state_length": 0}
t.go:81: 2023-05-03 08:28:12.548 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/workspacebuilds/c5e1d950-abfd-41d3-97fc-3179249ee589", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.137466ms", "status_code": 200, "latency_ms": 4, "request_id": "1fda2648-9f44-4a86-b993-d080c90682e7"}
t.go:81: 2023-05-03 08:28:12.559 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.561 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "stage": "Starting workspace", "output": ""}
t.go:81: 2023-05-03 08:28:12.561 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.561 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.562 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:405> (*Runner).doCleanFinish.func2 cleaned up work directory {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start"}
t.go:81: 2023-05-03 08:28:12.563 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.564 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "stage": "Cleaning Up", "output": ""}
t.go:81: 2023-05-03 08:28:12.565 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.565 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:12.565 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:230> (*Runner).Run sending CompletedJob {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start"}
t.go:81: 2023-05-03 08:28:12.566 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:831> (*Server).CompleteJob CompleteJob starting {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:13.194 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1056> (*Server).CompleteJob.func1 triggering workspace notification after agent timeout {"workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "timeout": "0s"}
t.go:81: 2023-05-03 08:28:13.196 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1191> (*Server).CompleteJob CompleteJob done {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba"}
t.go:81: 2023-05-03 08:28:13.201 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/workspacebuilds/c5e1d950-abfd-41d3-97fc-3179249ee589", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "635.319398ms", "status_code": 200, "latency_ms": 635, "request_id": "a8848cbc-d2b4-4131-bf28-73fd0dc06157"}
t.go:81: 2023-05-03 08:28:13.201 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:235> (*Runner).Run sent CompletedJob {"job_id": "b79435db-3624-4cbc-a569-15a7b672e5ba", "template_name": "inspiring-greider1-VMO", "template_version": "cranky_greider7", "workspace_build_id": "c5e1d950-abfd-41d3-97fc-3179249ee589", "workspace_id": "ea30137e-069f-4d6e-8f66-eadc179b861e", "workspace_name": "nervous-mirzakhani1-KmI", "workspace_owner": "testuser", "workspace_transition": "start"}
workspaceagents_test.go:360: got workspace build job c5e1d950-abfd-41d3-97fc-3179249ee589
t.go:81: 2023-05-03 08:28:13.257 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/files", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.857885ms", "status_code": 201, "latency_ms": 3, "request_id": "827d3b48-795e-45c0-8a6d-d4476d6d7605"}
t.go:81: 2023-05-03 08:28:13.379 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:51986", "path": "/api/v2/organizations/1e84558c-d76f-47b8-968d-625d9d3251c5/templateversions", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "9.945208ms", "status_code": 201, "latency_ms": 9, "request_id": "4ccfe5e8-eacd-4d56-9982-78e2c141638c"}
workspaceagents_test.go:382: waiting for template version job f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2
t.go:81: 2023-05-03 08:28:13.569 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.918653ms", "status_code": 200, "latency_ms": 3, "request_id": "8605e102-5e19-4b0d-9a4f-dba59d66fe36"}
t.go:81: 2023-05-03 08:28:14.494 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "834.686185ms", "status_code": 200, "latency_ms": 834, "request_id": "6bb8fb90-a8bb-4092-a580-a61068f98146"}
t.go:81: 2023-05-03 08:28:15.637 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:105> (*Server).AcquireJob locked job from database {"id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:16.037 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.3783113s", "status_code": 200, "latency_ms": 1378, "request_id": "90cf56a1-0f29-4b56-8fed-d0c51bed2559"}
t.go:81: 2023-05-03 08:28:17.503 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "245.788715ms", "status_code": 200, "latency_ms": 245, "request_id": "3ce435c9-9aa8-4b79-9fe7-77aa1d24fd77"}
t.go:81: 2023-05-03 08:28:17.504 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:378> (*Server).acquireJob acquired job {"initiator_username": "testuser", "provisioner": "echo", "job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:17.518 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:435> (*Runner).do unpacking template source archive {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "size_bytes": 3072}
t.go:81: 2023-05-03 08:28:17.519 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.parse.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:19.478 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:17.519 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "size_bytes": 105, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:20.316 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentListenFailNonLatestBuild841335209/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:20.317 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:491> (*Runner).do acquired job is template import {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "user_variable_values": null}
t.go:81: 2023-05-03 08:28:20.318 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:20.320 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "stage": "Setting up", "output": ""}
t.go:81: 2023-05-03 08:28:20.320 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:20.320 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:20.532 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:723> (*Runner).runTemplateImportParse parse complete {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "parameter_schemas": null, "template_variables": null}
t.go:81: 2023-05-03 08:28:20.533 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:20.534 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:825> (*Runner).runTemplateImportProvisionWithRichParameters parse dry-run provision successful {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "resource_count": 0, "resources": null, "state_length": 0}
t.go:81: 2023-05-03 08:28:21.932 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
workspaceagents_test.go:382:
Error Trace: /Users/runner/work/coder/coder/coderd/coderdtest/coderdtest.go:631
/Users/runner/work/coder/coder/coderd/workspaceagents_test.go:382
Error: Condition never satisfied
Test: TestWorkspaceAgentListen/FailNonLatestBuild
t.go:81: 2023-05-03 08:28:24.550 [WARN] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:51986", "path": "/api/v2/templateversions/f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.121884574s", "status_code": 500, "latency_ms": 1121, "request_id": "c5c37478-96dd-4f50-9f69-4b8ac927248a"} ...
"response_body": {
"message": "An internal error occurred. Please try again or contact the system administrator.",
"detail": "Internal error fetching API key by id. unauthorized: evaluate rego: context canceled"
}
coderdtest.go:634:
Error Trace: /Users/runner/work/coder/coder/coderd/coderdtest/coderdtest.go:634
/Users/runner/hostedtoolcache/go/1.20.3/x64/src/runtime/asm_amd64.s:1598
Error: Received unexpected error:
Get "http://localhost:51986/api/v2/templateversions/f43ad1d7-06d8-40a6-b3c0-f02ad4d77cc2": context canceled
Test: TestWorkspaceAgentListen/FailNonLatestBuild
t.go:81: 2023-05-03 08:28:24.897 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:24.899 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "stage": "No README.md provided", "output": ""}
t.go:81: 2023-05-03 08:28:24.899 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "stage": "Parsing template parameters", "output": ""}
t.go:81: 2023-05-03 08:28:24.899 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "stage": "Detecting persistent resources", "output": ""}
t.go:81: 2023-05-03 08:28:24.900 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1", "stage": "Detecting ephemeral resources", "output": ""}
t.go:81: 2023-05-03 08:28:24.900 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:24.900 [DEBUG] (provisionerd-friendly_chaum0) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "c723387e-6cde-48d5-ab4b-43d32cc972d1"}
t.go:81: 2023-05-03 08:28:24.921 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:552> (*Server).closeWithError closing server with error {"error": "context deadline exceeded"}
stuntest.go:63: STUN server shutdown
=== FAIL: coderd TestWorkspaceAgent/Timeout (12.53s)
t.go:81: 2023-05-03 08:28:12.582 [DEBUG] (metrics_cache) <github.com/coder/coder/coderd/metricscache/metricscache.go:272> (*Cache).run deployment stats metrics refreshed {"took": "12.952µs", "interval": "5m0s"}
t.go:81: 2023-05-03 08:28:12.583 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:201> (*Server).connect connected
t.go:81: 2023-05-03 08:28:13.188 [DEBUG] (metrics_cache) <github.com/coder/coder/coderd/metricscache/metricscache.go:272> (*Cache).run template daus metrics refreshed {"took": "600.632708ms", "interval": "1h0m0s"}
t.go:81: 2023-05-03 08:28:13.270 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:52028", "path": "/api/v2/users/first", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "46.292278ms", "status_code": 201, "latency_ms": 46, "request_id": "c8ccd7f8-d40c-4e32-ba00-9c6c862939b5"}
t.go:81: 2023-05-03 08:28:13.387 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:52028", "path": "/api/v2/users/login", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "6.72844ms", "status_code": 201, "latency_ms": 6, "request_id": "fa4d63bc-9389-4e1f-bde4-16fff2f86f13"}
t.go:81: 2023-05-03 08:28:13.406 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:52028", "path": "/api/v2/files", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.54929ms", "status_code": 201, "latency_ms": 4, "request_id": "d8c29d42-b82f-46d5-95dc-2b2fcb2ed145"}
t.go:81: 2023-05-03 08:28:13.460 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:52028", "path": "/api/v2/organizations/9bb3af06-f095-4fe0-9282-268e8bb03162/templateversions", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "14.151717ms", "status_code": 201, "latency_ms": 14, "request_id": "b0305bd3-aa95-4841-9333-97eb812efae5"}
t.go:81: 2023-05-03 08:28:13.500 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"host": "localhost:52028", "path": "/api/v2/organizations/9bb3af06-f095-4fe0-9282-268e8bb03162/templates", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "7.608695ms", "status_code": 201, "latency_ms": 7, "request_id": "42834b96-ce43-4658-a421-38dfc990c4e7"}
workspaceagents_test.go:156: waiting for template version job f238395a-9089-457c-be1d-bd3ed6c19[437](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:438)
t.go:81: 2023-05-03 08:28:14.496 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:105> (*Server).AcquireJob locked job from database {"id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:15.402 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:52028", "path": "/api/v2/templateversions/f238395a-9089-457c-be1d-bd3ed6c19437", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.814758005s", "status_code": 200, "latency_ms": 1814, "request_id": "59efaeb7-99e9-4865-8198-a1cbe14df50f"}
t.go:81: 2023-05-03 08:28:17.503 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:378> (*Server).acquireJob acquired job {"initiator_username": "testuser", "provisioner": "echo", "job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:17.505 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:435> (*Runner).do unpacking template source archive {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "size_bytes": 3072}
t.go:81: 2023-05-03 08:28:17.505 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentTimeout3597623717/002/0.parse.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:17.505 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "size_bytes": 234, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentTimeout3597623717/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:17.506 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:482> (*Runner).do extracted file {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestWorkspaceAgentTimeout3597623717/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}
t.go:81: 2023-05-03 08:28:17.508 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:491> (*Runner).do acquired job is template import {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "user_variable_values": null}
t.go:81: 2023-05-03 08:28:17.690 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:723> (*Runner).runTemplateImportParse parse complete {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "parameter_schemas": null, "template_variables": null}
t.go:81: 2023-05-03 08:28:17.692 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:17.694 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:825> (*Runner).runTemplateImportProvisionWithRichParameters parse dry-run provision successful {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "resource_count": 0, "resources": null, "state_length": 0}
t.go:81: 2023-05-03 08:28:19.583 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:52028", "path": "/api/v2/templateversions/f238395a-9089-457c-be1d-bd3ed6c19437", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.094794124s", "status_code": 200, "latency_ms": 3094, "request_id": "e80322e4-8d0a-4330-a43c-f449c7ab57fe"}
t.go:81: 2023-05-03 08:28:20.312 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:20.314 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:20.315 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "stage": "Setting up", "output": ""}
t.go:81: 2023-05-03 08:28:20.315 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "stage": "No README.md provided", "output": ""}
t.go:81: 2023-05-03 08:28:20.315 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "stage": "Parsing template parameters", "output": ""}
t.go:81: 2023-05-03 08:28:20.315 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "stage": "Detecting persistent resources", "output": ""}
t.go:81: 2023-05-03 08:28:20.316 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488> (*Server).UpdateJob job log {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "stage": "Detecting ephemeral resources", "output": ""}
t.go:81: 2023-05-03 08:28:20.316 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502> (*Server).UpdateJob inserted job logs {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:20.316 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514> (*Server).UpdateJob published job logs {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:21.915 [INFO] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:825> (*Runner).runTemplateImportProvisionWithRichParameters parse dry-run provision successful {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "resource_count": 0, "resources": null, "state_length": 0}
t.go:81: 2023-05-03 08:28:21.931 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:52028", "path": "/api/v2/templateversions/f238395a-9089-457c-be1d-bd3ed6c19437", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.388183058s", "status_code": 200, "latency_ms": 1388, "request_id": "53feeee6-948b-483a-a668-aa36d01d570e"}
workspaceagents_test.go:156:
Error Trace: /Users/runner/work/coder/coder/coderd/coderdtest/coderdtest.go:631
/Users/runner/work/coder/coder/coderd/workspaceagents_test.go:156
Error: Condition never satisfied
Test: TestWorkspaceAgent/Timeout
coderdtest.go:634:
Error Trace: /Users/runner/work/coder/coder/coderd/coderdtest/coderdtest.go:634
/Users/runner/hostedtoolcache/go/1.20.3/x64/src/runtime/asm_amd64.s:1598
Error: Received unexpected error:
Get "http://localhost:52028/api/v2/templateversions/f238395a-9089-457c-be1d-bd3ed6c19437": context deadline exceeded
Test: TestWorkspaceAgent/Timeout
t.go:81: 2023-05-03 08:28:24.659 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 GET {"host": "localhost:52028", "path": "/api/v2/templateversions/f238395a-9089-457c-be1d-bd3ed6c19437", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "1.233587603s", "status_code": 401, "latency_ms": 1233, "request_id": "9687b7eb-d388-[441](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:442)b-a7b2-021eb6ce4fd3"}
t.go:81: 2023-05-03 08:28:25.051 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:[451](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:452)> (*Server).UpdateJob UpdateJob starting {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:25.083 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/runner/runner.go:405> (*Runner).doCleanFinish.func2 cleaned up work directory {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:25.084 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451> (*Server).UpdateJob UpdateJob starting {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:25.086 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:[488](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:489)> (*Server).UpdateJob job log {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27", "stage": "Cleaning Up", "output": ""}
t.go:81: 2023-05-03 08:28:25.086 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:[502](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:503)> (*Server).UpdateJob inserted job logs {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:25.086 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:[514](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:515)> (*Server).UpdateJob published job logs {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:25.091 [DEBUG] (provisionerd-strange_gould5) <github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:680> (*Server).FailJob FailJob starting {"job_id": "e4facaf5-f46a-430c-bff6-b75a840aae27"}
t.go:81: 2023-05-03 08:28:25.092 [DEBUG] (provisionerd) <github.com/coder/coder/provisionerd/provisionerd.go:[552](https://github.com/coder/coder/actions/runs/4869822054/jobs/8684798107?pr=7387#step:9:553)> (*Server).closeWithError closing server with error {"error": null}
stuntest.go:63: STUN server shutdown