Skip to content

regression: querying logs while job is running can miss some #7371

Closed
@spikecurtis

Description

@spikecurtis

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
No labels

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions