Closed
Description
c.f. https://github.com/coder/coder/actions/runs/4850979453/jobs/8644394182?pr=7345
=== 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).run deployment 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).run template 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).connect connected
t.go:81: 2023-05-01 12:19:54.350 [DEBUG] <github.com/coder/coder/coderd/httpmw/logger.go:63> Logger.func1.1.1 POST {"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.1 POST {"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.1 POST {"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.1 POST {"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.1 GET {"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.1 GET {"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).AcquireJob locked 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.1 GET {"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).acquireJob acquired 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).do unpacking 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).do extracted 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).do extracted 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).do extracted 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).do extracted 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).do extracted 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).do acquired 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).runTemplateImportParse parse 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).UpdateJob UpdateJob 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.1 GET {"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).runTemplateImportProvisionWithRichParameters template 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).runTemplateImportProvisionWithRichParameters parse 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).UpdateJob UpdateJob 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).runTemplateImportProvisionWithRichParameters template 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).runTemplateImportProvisionWithRichParameters parse 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.func2 cleaned 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).UpdateJob UpdateJob 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob inserted 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).UpdateJob published 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).Run sending 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).CompleteJob CompleteJob 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).CompleteJob inserting 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).CompleteJob inserting 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).CompleteJob marked 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).CompleteJob CompleteJob 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).Run sent 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.1 GET {"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.1 POST {"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.1 GET {"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).AcquireJob locked 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).acquireJob acquired 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).do unpacking 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).do extracted 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).do extracted 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).do extracted 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).do extracted 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).do extracted 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).do acquired 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).runTemplateImportProvisionWithRichParameters template 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).runTemplateImportProvisionWithRichParameters parse 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.func2 cleaned 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).UpdateJob UpdateJob 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).UpdateJob job 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).UpdateJob job 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).UpdateJob job 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).UpdateJob inserted 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.1 GET {"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.func1 subscribe 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.func1 subscribe 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.func1 subscribe 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).UpdateJob published 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).Run sending 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).CompleteJob CompleteJob 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).CompleteJob inserting 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).CompleteJob marked 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.func1 subscribe 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.func2 got 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).CompleteJob CompleteJob 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).Run sent 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.1 GET {"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.1 GET {"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.1 GET {"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).closeWithError closing server with error {"error": null}
stuntest.go:63: STUN server shutdown
The culprit appears to be #6824 which queries the database whether the job is completed and exits if it is after subscribing to any streamed logs, but before processing them. So, any streamed logs that come in can be dropped without being sent to the client.
Metadata
Metadata
Assignees
Labels
No labels