=== FAIL: coderd TestTemplateVersionDryRun/OK (1.38s)    t.go:81: 2023-05-01 12:19:54.285 [DEBUG](metrics_cache)<github.com/coder/coder/coderd/metricscache/metricscache.go:272>(*Cache).rundeployment stats metrics refreshed{"took": "14.616µs", "interval": "5m0s"}    t.go:81: 2023-05-01 12:19:54.286 [DEBUG](metrics_cache)<github.com/coder/coder/coderd/metricscache/metricscache.go:272>(*Cache).runtemplate daus metrics refreshed{"took": "1.555448ms", "interval": "1h0m0s"}    t.go:81: 2023-05-01 12:19:54.286 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/provisionerd.go:201>(*Server).connectconnected    t.go:81: 2023-05-01 12:19:54.350 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1POST{"host": "localhost:51157", "path": "/api/v2/users/first", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "13.683748ms", "status_code": 201, "latency_ms": 13, "request_id": "fbf273b4-ca7d-4aac-8cb7-8e853916f0d2"}    t.go:81: 2023-05-01 12:19:54.377 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1POST{"host": "localhost:51157", "path": "/api/v2/users/login", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.217674ms", "status_code": 201, "latency_ms": 4, "request_id": "00904531-a63e-42ba-bd86-800ae01dc302"}    t.go:81: 2023-05-01 12:19:54.386 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1POST{"host": "localhost:51157", "path": "/api/v2/files", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "6.113548ms", "status_code": 201, "latency_ms": 6, "request_id": "c9e40225-9f80-4a31-9c00-0594454811d8"}    t.go:81: 2023-05-01 12:19:54.404 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1POST{"host": "localhost:51157", "path": "/api/v2/organizations/f8d87e07-e564-4ded-839a-7b5d5aa18672/templateversions", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.873786ms", "status_code": 201, "latency_ms": 4, "request_id": "11550114-f85d-4d9e-b267-e372495141c4"}    templateversions_test.go:753: waiting for template version job cc38a2db-053d-4228-9da6-98e2f2819afa    t.go:81: 2023-05-01 12:19:54.457 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.33283ms", "status_code": 200, "latency_ms": 3, "request_id": "37316d36-de95-4913-bd86-96ca1e55f0ce"}    t.go:81: 2023-05-01 12:19:54.482 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "6.064603ms", "status_code": 200, "latency_ms": 6, "request_id": "a53847ea-e75a-43c9-99d0-cdac3235d71d"}    t.go:81: 2023-05-01 12:19:54.494 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:105>(*Server).AcquireJoblocked job from database{"id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.506 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.728631ms", "status_code": 200, "latency_ms": 3, "request_id": "2900b668-e1f3-4c0d-9f87-812dedf9237c"}    t.go:81: 2023-05-01 12:19:54.509 [INFO](provisionerd)<github.com/coder/coder/provisionerd/provisionerd.go:378>(*Server).acquireJobacquired job{"initiator_username": "testuser", "provisioner": "echo", "job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.509 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:435>(*Runner).dounpacking template source archive{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "size_bytes": 5120}    t.go:81: 2023-05-01 12:19:54.509 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK22[234](https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345#step:9:235)70262/002/0.parse.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:54.509 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:54.509 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "size_bytes": 39, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/1.provision.apply.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:54.510 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:54.510 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "size_bytes": 39, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/1.provision.plan.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:54.510 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:491>(*Runner).doacquired job is template import{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "user_variable_values": null}    t.go:81: 2023-05-01 12:19:54.511 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:723>(*Runner).runTemplateImportParseparse complete{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "parameter_schemas": null, "template_variables": null}    t.go:81: 2023-05-01 12:19:54.514 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451>(*Server).UpdateJobUpdateJob starting{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.524 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.574133ms", "status_code": 200, "latency_ms": 3, "request_id": "19644477-9e70-4bf1-b312-5141d579c18d"}    t.go:81: 2023-05-01 12:19:54.688 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:805>(*Runner).runTemplateImportProvisionWithRichParameterstemplate import provision job logged{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "level": "TRACE", "output": ""}    t.go:81: 2023-05-01 12:19:54.732 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:825>(*Runner).runTemplateImportProvisionWithRichParametersparse dry-run provision successful{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "resource_count": 1, "resources": [{"name": "cool-resource", "type": "cool_resource_type"}], "state_length": 0}    t.go:81: 2023-05-01 12:19:54.825 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451>(*Server).UpdateJobUpdateJob starting{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.904 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:805>(*Runner).runTemplateImportProvisionWithRichParameterstemplate import provision job logged{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "level": "TRACE", "output": ""}    t.go:81: 2023-05-01 12:19:54.904 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:825>(*Runner).runTemplateImportProvisionWithRichParametersparse dry-run provision successful{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "resource_count": 1, "resources": [{"name": "cool-resource", "type": "cool_resource_type"}], "state_length": 0}    t.go:81: 2023-05-01 12:19:54.904 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:405>(*Runner).doCleanFinish.func2cleaned up work directory{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.914 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451>(*Server).UpdateJobUpdateJob starting{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.915 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Setting up", "output": ""}    t.go:81: 2023-05-01 12:19:54.915 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "No README.md provided", "output": ""}    t.go:81: 2023-05-01 12:19:54.915 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Parsing template parameters", "output": ""}    t.go:81: 2023-05-01 12:19:54.915 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Detecting persistent resources", "output": ""}    t.go:81: 2023-05-01 12:19:54.915 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Detecting persistent resources", "output": ""}    t.go:81: 2023-05-01 12:19:54.916 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Detecting ephemeral resources", "output": ""}    t.go:81: 2023-05-01 12:19:54.916 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Detecting ephemeral resources", "output": ""}    t.go:81: 2023-05-01 12:19:54.916 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "stage": "Cleaning Up", "output": ""}    t.go:81: 2023-05-01 12:19:54.916 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502>(*Server).UpdateJobinserted job logs{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.916 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514>(*Server).UpdateJobpublished job logs{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.919 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:230>(*Runner).Runsending CompletedJob{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.924 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:831>(*Server).CompleteJobCompleteJob starting{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.927 [INFO](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:857>(*Server).CompleteJobinserting template import job resource{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "resource_name": "cool-resource", "resource_type": "cool_resource_type", "transition": "start"}    t.go:81: 2023-05-01 12:19:54.928 [INFO](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:857>(*Server).CompleteJobinserting template import job resource{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5", "resource_name": "cool-resource", "resource_type": "cool_resource_type", "transition": "stop"}    t.go:81: 2023-05-01 12:19:54.930 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:942>(*Server).CompleteJobmarked import job as completed{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.930 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1191>(*Server).CompleteJobCompleteJob done{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.930 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:[235](https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345#step:9:236)>(*Runner).Runsent CompletedJob{"job_id": "b738a3c5-55b7-474a-bd95-64ce44511bc5"}    t.go:81: 2023-05-01 12:19:54.938 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "43.054[238](https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345#step:9:239)ms", "status_code": 200, "latency_ms": 43, "request_id": "73fad902-a49a-49fe-bea8-8ce315ff6980"}    templateversions_test.go:753: got template version job cc38a2db-053d-4228-9da6-98e2f2819afa    t.go:81: 2023-05-01 12:19:54.959 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1POST{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa/dry-run", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "4.825914ms", "status_code": 201, "latency_ms": 4, "request_id": "9a14c458-c179-4862-a5a0-899e4be5a81e"}    t.go:81: 2023-05-01 12:19:54.992 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa/dry-run/ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.159726ms", "status_code": 200, "latency_ms": 5, "request_id": "621e4c18-67f4-483e-8d7e-040042d0895f"}    t.go:81: 2023-05-01 12:19:55.099 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:105>(*Server).AcquireJoblocked job from database{"id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.102 [INFO](provisionerd)<github.com/coder/coder/provisionerd/provisionerd.go:378>(*Server).acquireJobacquired job{"initiator_username": "testuser", "provisioner": "echo", "job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.102 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:435>(*Runner).dounpacking template source archive{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "size_bytes": 5120}    t.go:81: 2023-05-01 12:19:55.102 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/0.parse.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/0.provision.apply.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "size_bytes": 39, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/1.provision.apply.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "size_bytes": 2, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/0.provision.plan.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:482>(*Runner).doextracted file{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "size_bytes": 39, "path": "/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/TestTemplateVersionDryRunOK2223470262/002/1.provision.plan.protobuf", "mode": "-rw-r--r--"}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:501>(*Runner).doacquired job is template dry-run{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "workspace_name": "", "parameters": null, "rich_parameter_values": null, "variable_values": null}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:805>(*Runner).runTemplateImportProvisionWithRichParameterstemplate import provision job logged{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "level": "TRACE", "output": ""}    t.go:81: 2023-05-01 12:19:55.103 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:825>(*Runner).runTemplateImportProvisionWithRichParametersparse dry-run provision successful{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "resource_count": 1, "resources": [{"name": "cool-resource", "type": "cool_resource_type"}], "state_length": 0}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:405>(*Runner).doCleanFinish.func2cleaned up work directory{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.103 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:451>(*Server).UpdateJobUpdateJob starting{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.111 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Setting up", "output": ""}    t.go:81: 2023-05-01 12:19:55.111 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Detecting persistent resources", "output": ""}    t.go:81: 2023-05-01 12:19:55.111 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:488>(*Server).UpdateJobjob log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Cleaning Up", "output": ""}    t.go:81: 2023-05-01 12:19:55.111 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:502>(*Server).UpdateJobinserted job logs{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.112 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa/dry-run/ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "3.017301ms", "status_code": 200, "latency_ms": 3, "request_id": "cf696557-3b91-45ed-a7fc-61e9ef4ee9f8"}    t.go:81: 2023-05-01 12:19:55.113 [DEBUG]<github.com/coder/coder/coderd/provisionerjobs.go:385>(*API).followProvisionerJobLogs.func1subscribe buffered log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Setting up"}    t.go:81: 2023-05-01 12:19:55.113 [DEBUG]<github.com/coder/coder/coderd/provisionerjobs.go:385>(*API).followProvisionerJobLogs.func1subscribe buffered log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Detecting persistent resources"}    t.go:81: 2023-05-01 12:19:55.113 [DEBUG]<github.com/coder/coder/coderd/provisionerjobs.go:385>(*API).followProvisionerJobLogs.func1subscribe buffered log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Cleaning Up"}    t.go:81: 2023-05-01 12:19:55.113 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:514>(*Server).UpdateJobpublished job logs{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.113 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:230>(*Runner).Runsending CompletedJob{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.114 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:831>(*Server).CompleteJobCompleteJob starting{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.115 [INFO](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1146>(*Server).CompleteJobinserting template dry-run job resource{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "resource_name": "cool-resource", "resource_type": "cool_resource_type"}    t.go:81: 2023-05-01 12:19:55.116 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1168>(*Server).CompleteJobmarked template dry-run job as completed{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.117 [DEBUG]<github.com/coder/coder/coderd/provisionerjobs.go:385>(*API).followProvisionerJobLogs.func1subscribe buffered log{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490", "stage": "Cleaning Up"}    t.go:81: 2023-05-01 12:19:55.117 [DEBUG]<github.com/coder/coder/coderd/provisionerjobs.go:446>(*API).followProvisionerJobLogs.func2got End of Logs{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.117 [DEBUG](provisionerd-admiring_lamport9)<github.com/coder/coder/coderd/provisionerdserver/provisionerdserver.go:1191>(*Server).CompleteJobCompleteJob done{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    t.go:81: 2023-05-01 12:19:55.117 [INFO](provisionerd)<github.com/coder/coder/provisionerd/runner/runner.go:235>(*Runner).Runsent CompletedJob{"job_id": "ce9ef2f3-bd3b-4b30-ac9d-d797e9425490"}    templateversions_test.go:782:         Error Trace:/Users/runner/work/coder/coder/coderd/templateversions_test.go:782                    /Users/runner/hostedtoolcache/go/1.20.3/x64/src/runtime/asm_amd64.s:1598        Error:      "0" is not greater than or equal to "1"        Test:       TestTemplateVersionDryRun/OK        Messages:   unexpected log count    t.go:81: 2023-05-01 12:19:55.117 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa/dry-run/ce9ef2f3-bd3b-4b30-ac9d-d797e9425490/logs", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "79.606[241](https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345#step:9:242)ms", "status_code": 101, "latency_ms": 79, "request_id": "de661b12-b0a7-406f-97c3-85218985c13b"}    t.go:81: 2023-05-01 12:19:55.189 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f2819afa/dry-run/ce9ef2f3-bd3b-4b30-ac9d-d797e94[254](https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345#step:9:255)90", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "5.581955ms", "status_code": 200, "latency_ms": 5, "request_id": "a66aa1f4-f25f-4764-b0c0-070962066ee6"}    t.go:81: 2023-05-01 12:19:55.340 [DEBUG]<github.com/coder/coder/coderd/httpmw/logger.go:63>Logger.func1.1.1GET{"host": "localhost:51157", "path": "/api/v2/templateversions/cc38a2db-053d-4228-9da6-98e2f[281](https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345#step:9:282)9afa/dry-run/ce9ef2f3-bd3b-4b30-ac9d-d797e9425490/resources", "proto": "HTTP/1.1", "remote_addr": "127.0.0.1", "took": "133.475845ms", "status_code": 200, "latency_ms": 133, "request_id": "3b8b9474-636a-4159-bf24-b54ade15a7c4"}    t.go:81: 2023-05-01 12:19:55.346 [DEBUG](provisionerd)<github.com/coder/coder/provisionerd/provisionerd.go:552>(*Server).closeWithErrorclosing server with error{"error": null}    stuntest.go:63: STUN server shutdown