test flake: TestWorkspaceFilterManual #9665
Description
Seen here: https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652
Failure output:
=== FAIL: coderd TestWorkspaceFilterManual/FilterQuery (1.77s)
t.go:85: 2023-09-13 14:05:47.081 [debu] metrics_cache: deployment stats metrics refreshed took=12.13µs interval=5m0s
t.go:85: 2023-09-13 14:05:47.081 [debu] workspaceapps.stats_collector: workspace app stats collector started
t.go:85: 2023-09-13 14:05:47.084 [info] inmem-provisionerd-zen_williamson8: starting in-memory provisioner daemon
t.go:85: 2023-09-13 14:05:47.085 [debu] metrics_cache: template daus metrics refreshed took=4.194314ms interval=1h0m0s
t.go:85: 2023-09-13 14:05:47.089 [debu] provisionerd: successfully connected to coderd
t.go:85: 2023-09-13 14:05:47.108 [debu] POST host=localhost:52569 path=/api/v2/users/first proto=HTTP/1.1 remote_addr=127.0.0.1 took=17.771721ms status_code=201 latency_ms=17 request_id=bb3990fa-29d7-460e-9d5b-1d4740072b3d
t.go:85: 2023-09-13 14:05:47.110 [debu] POST host=localhost:52569 path=/api/v2/users/login proto=HTTP/1.1 remote_addr=127.0.0.1 took=2.26201ms status_code=201 latency_ms=2 request_id=9ac53c10-58ff-480b-b9c5-16d7a0e189c0
t.go:85: 2023-09-13 14:05:47.114 [debu] POST host=localhost:52569 path=/api/v2/files proto=HTTP/1.1 remote_addr=127.0.0.1 took=3.091718ms status_code=201 latency_ms=3 request_id=99b9d2a4-d033-4608-bf50-41bc30bbc95d
t.go:85: 2023-09-13 14:05:47.123 [debu] POST host=localhost:52569 path=/api/v2/organizations/b2860d31-9376-4ee6-856f-458d60f39869/templateversions proto=HTTP/1.1 remote_addr=127.0.0.1 took=8.783422ms status_code=201 latency_ms=8 request_id=353e4cef-a9aa-4363-b2c4-4270f6bbfc7c
t.go:85: 2023-09-13 14:05:47.124 [debu] POST host=localhost:52569 path=/api/v2/files proto=HTTP/1.1 remote_addr=127.0.0.1 took=[300](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:301).719µs status_code=200 latency_ms=0 request_id=1078d909-2e15-464d-b906-6af345c0c110
t.go:85: 2023-09-13 14:05:47.126 [debu] POST host=localhost:52569 path=/api/v2/organizations/b2860d31-9376-4ee6-856f-458d60f39869/templateversions proto=HTTP/1.1 remote_addr=127.0.0.1 took=570.479µs status_code=201 latency_ms=0 request_id=c5f5138c-b677-47aa-8201-5b35f3540645
workspaces_test.go:1283: waiting for template version job 2d63a526-f79c-4b28-9dff-844713a137a5
t.go:85: 2023-09-13 14:05:47.145 [debu] inmem-provisionerd-zen_williamson8: locked job from database job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.149 [debu] provisionerd: called AcquireJob on client job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d error=
t.go:85: 2023-09-13 14:05:47.149 [debu] provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.150 [debu] provisionerd.runner: acquired job is template import job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d user_variable_values=[]
t.go:85: 2023-09-13 14:05:47.151 [info] echo: unpacking template source archive session_id=965fe349-f974-4281-8c60-4e204a9a95ad size_bytes=3072
t.go:85: 2023-09-13 14:05:47.153 [debu] echo: extracted file session_id=965fe349-f974-4281-8c60-4e204a9a95ad size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Session965fe349-f974-4281-8c60-4e204a9a95ad/0.parse.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:47.154 [debu] echo: extracted file session_id=965fe349-f974-4281-8c60-4e204a9a95ad size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Session965fe349-f974-4281-8c60-4e204a9a95ad/0.apply.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:47.154 [debu] GET host=localhost:52569 path=/api/v2/templateversions/2d63a526-f79c-4b28-9dff-844713a137a5 proto=HTTP/1.1 remote_addr=127.0.0.1 took=625.344µs status_code=200 latency_ms=0 request_id=b4a87076-4942-4c99-92cb-4bcc5966010c
t.go:85: 2023-09-13 14:05:47.154 [debu] echo: extracted file session_id=965fe349-f974-4281-8c60-4e204a9a95ad size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Session965fe349-f974-4281-8c60-4e204a9a95ad/0.plan.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:47.161 [debu] echo: failed to parse readme (missing ok) session_id=965fe349-f974-4281-8c60-4e204a9a95ad error="open /var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Session965fe349-f974-4281-8c60-4e204a9a95ad/README.md: no such file or directory"
t.go:85: 2023-09-13 14:05:47.161 [debu] provisionerd.runner: parse complete job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d template_variables=[] readme_len=0 error=""
t.go:85: 2023-09-13 14:05:47.161 [debu] inmem-provisionerd-zen_williamson8: stage UpdateJob starting job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.177 [debu] GET host=localhost:52569 path=/api/v2/templateversions/2d63a526-f79c-4b28-9dff-844713a137a5 proto=HTTP/1.1 remote_addr=127.0.0.1 took=318.846µs status_code=200 latency_ms=0 request_id=93917ffc-1bda-40ed-a53e-da3486f10350
t.go:85: 2023-09-13 14:05:47.184 [info] provisionerd.runner: parse dry-run provision successful job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d resource_count=0 resources=[]
t.go:85: 2023-09-13 14:05:47.194 [info] provisionerd.runner: parse dry-run provision successful job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d resource_count=0 resources=[]
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: stage UpdateJob starting job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: job log job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d stage="Setting up" output=""
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: job log job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d stage="Parsing template parameters" output=""
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: job log job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d stage="Detecting persistent resources" output=""
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: job log job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d stage="Detecting ephemeral resources" output=""
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: job log job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d stage="Cleaning Up" output=""
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: inserted job logs job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.195 [debu] inmem-provisionerd-zen_williamson8: published job logs job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.195 [debu] provisionerd.runner: sending CompletedJob job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.195 [info] echo: recv done on Session session_id=965fe349-f974-4281-8c60-4e204a9a95ad error=EOF
t.go:85: 2023-09-13 14:05:47.196 [debu] inmem-provisionerd-zen_williamson8: stage CompleteJob starting job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.196 [debu] echo: cleaned up work directory session_id=965fe349-f974-4281-8c60-4e204a9a95ad
t.go:85: 2023-09-13 14:05:47.198 [debu] inmem-provisionerd-zen_williamson8: marked import job as completed job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.199 [debu] inmem-provisionerd-zen_williamson8: stage CompleteJob done job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.199 [debu] provisionerd.runner: sent CompletedJob job_id=91a4feca-df55-4d46-a1a9-7c2bc382073d
t.go:85: 2023-09-13 14:05:47.203 [debu] GET host=localhost:52569 path=/api/v2/templateversions/2d63a526-f79c-4b28-9dff-844713a137a5 proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.21567ms status_code=200 latency_ms=1 request_id=5a732ad7-11ed-462e-84ac-8df80dad86dc
workspaces_test.go:1283: got template version job 2d63a526-f79c-4b28-9dff-844713a137a5
workspaces_test.go:1284: waiting for template version job 101e19df-bf0f-49e8-97ac-d44cb7e092dd
t.go:85: 2023-09-13 14:05:47.230 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=413.843µs status_code=200 latency_ms=0 request_id=91350d17-103d-4f7f-bf0d-8791cc8bc4f5
t.go:85: 2023-09-13 14:05:47.256 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=430.07µs status_code=200 latency_ms=0 request_id=aff2df05-f5e5-4a0d-9a43-22696c7b10a3
t.go:85: 2023-09-13 14:05:47.[302](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:303) [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=4.285118ms status_code=200 latency_ms=4 request_id=53ce5c64-040a-4c4d-aeec-c5c26e1f0c3b
t.go:85: 2023-09-13 14:05:47.311 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=349.552µs status_code=200 latency_ms=0 request_id=da7ada1d-40ff-4871-9a20-66ab853a6939
t.go:85: 2023-09-13 14:05:47.345 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=320.218µs status_code=200 latency_ms=0 request_id=410c6207-3de6-4e91-a415-077035092fd8
t.go:85: 2023-09-13 14:05:47.359 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=4.23983ms status_code=200 latency_ms=4 request_id=9138a88b-c9c1-409b-b792-c60c6037e4cd
t.go:85: 2023-09-13 14:05:47.380 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=705.225µs status_code=200 latency_ms=0 request_id=f8d00ce4-9dcd-43f8-ac21-a480e41183e2
t.go:85: 2023-09-13 14:05:47.405 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=324.762µs status_code=200 latency_ms=0 request_id=3cdb722b-397d-447d-ac34-160f05a45c5e
t.go:85: 2023-09-13 14:05:47.432 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=935.977µs status_code=200 latency_ms=0 request_id=f422afda-36d5-4d5d-80c0-f2a3c28eec82
t.go:85: 2023-09-13 14:05:47.455 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=551.174µs status_code=200 latency_ms=0 request_id=e3a7cdba-c3ab-4c8d-bb35-f64c7c953aa2
t.go:85: 2023-09-13 14:05:47.480 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=643.229µs status_code=200 latency_ms=0 request_id=838d29ac-bb47-4ec4-9ef5-86641e7a3127
t.go:85: 2023-09-13 14:05:47.505 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=344.966µs status_code=200 latency_ms=0 request_id=0e0c34dc-86bb-4a86-87a9-1154ffbb0d14
t.go:85: 2023-09-13 14:05:47.533 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=298.65µs status_code=200 latency_ms=0 request_id=c8e85c14-8a24-45d4-9d66-0b672009882d
t.go:85: 2023-09-13 14:05:47.573 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=373.891µs status_code=200 latency_ms=0 request_id=130ae294-bd84-4271-9f68-72508cc63eff
t.go:85: 2023-09-13 14:05:47.603 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=660.751µs status_code=200 latency_ms=0 request_id=5bab01fe-36cc-4db6-842a-70b6177626c4
t.go:85: 2023-09-13 14:05:47.605 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=327.801µs status_code=200 latency_ms=0 request_id=3a851ba1-8781-41d0-b201-275c94c16c61
t.go:85: 2023-09-13 14:05:47.699 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=372.512µs status_code=200 latency_ms=0 request_id=7f04b967-2753-4a12-9f98-0c860ca1fd81
t.go:85: 2023-09-13 14:05:47.700 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=201.782µs status_code=200 latency_ms=0 request_id=c[305](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:306)5779-4372-44b2-a995-b03f5bd56e80
t.go:85: 2023-09-13 14:05:47.707 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=400.345µs status_code=200 latency_ms=0 request_id=4c9b7eaf-a480-4e40-9376-e4cbccf40f78
t.go:85: 2023-09-13 14:05:47.729 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=341.12µs status_code=200 latency_ms=0 request_id=4959e23f-5fd3-48d7-b070-b80afa977825
t.go:85: 2023-09-13 14:05:47.792 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.780517ms status_code=200 latency_ms=1 request_id=1156a8ac-9567-477d-9326-85cbcfccc47c
t.go:85: 2023-09-13 14:05:47.794 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=1.036576ms status_code=200 latency_ms=1 request_id=71a8341d-9657-4c7f-8963-50a9345c0e44
t.go:85: 2023-09-13 14:05:47.806 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=454.051µs status_code=200 latency_ms=0 request_id=ee2ef683-c0b2-46ee-9955-ebe1bd99ad5e
t.go:85: 2023-09-13 14:05:47.840 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=757.302µs status_code=200 latency_ms=0 request_id=b7d034bc-8d63-4f7b-be8a-34ebfe6d85d1
t.go:85: 2023-09-13 14:05:47.895 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=513.669µs status_code=200 latency_ms=0 request_id=fb0c5f20-3d10-4df2-9752-391847fffc17
t.go:85: 2023-09-13 14:05:47.905 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=414.474µs status_code=200 latency_ms=0 request_id=e9fa2194-20e6-47d0-8ce2-1d760419e569
t.go:85: 2023-09-13 14:05:47.930 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=672.406µs status_code=200 latency_ms=0 request_id=951f9280-dba3-4047-a478-9c073ab1a34d
t.go:85: 2023-09-13 14:05:48.119 [debu] inmem-provisionerd-zen_williamson8: locked job from database job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.126 [debu] provisionerd: called AcquireJob on client job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b error=
t.go:85: 2023-09-13 14:05:48.126 [debu] provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.126 [debu] provisionerd.runner: acquired job is template import job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b user_variable_values=[]
t.go:85: 2023-09-13 14:05:48.136 [info] echo: unpacking template source archive session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121 size_bytes=3072
t.go:85: 2023-09-13 14:05:48.136 [debu] echo: extracted file session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121 size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Sessiond6d0f3f8-99fb-4183-ae15-d9d7479c3121/0.parse.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:48.139 [debu] echo: extracted file session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121 size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Sessiond6d0f3f8-99fb-4183-ae15-d9d7479c3121/0.apply.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:48.141 [debu] echo: extracted file session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121 size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Sessiond6d0f3f8-99fb-4183-ae15-d9d7479c3121/0.plan.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:48.146 [debu] echo: failed to parse readme (missing ok) session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121 error="open /var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Sessiond6d0f3f8-99fb-4183-ae15-d9d7479c3121/README.md: no such file or directory"
t.go:85: 2023-09-13 14:05:48.146 [debu] provisionerd.runner: parse complete job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b template_variables=[] readme_len=0 error=""
t.go:85: 2023-09-13 14:05:48.148 [debu] inmem-provisionerd-zen_williamson8: stage UpdateJob starting job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.150 [info] provisionerd.runner: parse dry-run provision successful job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b resource_count=0 resources=[]
t.go:85: 2023-09-13 14:05:48.154 [info] provisionerd.runner: parse dry-run provision successful job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b resource_count=0 resources=[]
t.go:85: 2023-09-13 14:05:48.156 [debu] inmem-provisionerd-zen_williamson8: stage UpdateJob starting job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.157 [debu] inmem-provisionerd-zen_williamson8: job log job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b stage="Setting up" output=""
t.go:85: 2023-09-13 14:05:48.157 [debu] inmem-provisionerd-zen_williamson8: job log job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b stage="Parsing template parameters" output=""
t.go:85: 2023-09-13 14:05:48.158 [debu] inmem-provisionerd-zen_williamson8: job log job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b stage="Detecting persistent resources" output=""
t.go:85: 2023-09-13 14:05:48.159 [debu] inmem-provisionerd-zen_williamson8: job log job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b stage="Detecting ephemeral resources" output=""
t.go:85: 2023-09-13 14:05:48.160 [debu] inmem-provisionerd-zen_williamson8: job log job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b stage="Cleaning Up" output=""
t.go:85: 2023-09-13 14:05:48.160 [debu] inmem-provisionerd-zen_williamson8: inserted job logs job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.161 [debu] inmem-provisionerd-zen_williamson8: published job logs job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.166 [debu] provisionerd.runner: sending CompletedJob job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.166 [info] echo: recv done on Session session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121 error=EOF
t.go:85: 2023-09-13 14:05:48.166 [debu] inmem-provisionerd-zen_williamson8: stage CompleteJob starting job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.169 [debu] inmem-provisionerd-zen_williamson8: marked import job as completed job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.169 [debu] inmem-provisionerd-zen_williamson8: stage CompleteJob done job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.170 [debu] provisionerd.runner: sent CompletedJob job_id=5cea1dab-dd94-47be-977a-0575c83f8a1b
t.go:85: 2023-09-13 14:05:48.175 [debu] echo: cleaned up work directory session_id=d6d0f3f8-99fb-4183-ae15-d9d7479c3121
t.go:85: 2023-09-13 14:05:48.468 [debu] GET host=localhost:52569 path=/api/v2/templateversions/101e19df-bf0f-49e8-97ac-d44cb7e092dd proto=HTTP/1.1 remote_addr=127.0.0.1 took=231.298137ms status_code=200 latency_ms=231 request_id=b0093825-1b6f-4eae-9ade-06c4e8ea51cf
workspaces_test.go:1284: got template version job 101e19df-bf0f-49e8-97ac-d44cb7e092dd
t.go:85: 2023-09-13 14:05:48.496 [debu] POST host=localhost:52569 path=/api/v2/organizations/b2860d31-9376-4ee6-856f-458d60f39869/templates proto=HTTP/1.1 remote_addr=127.0.0.1 took=22.786488ms status_code=201 latency_ms=22 request_id=05cc3b6d-af31-4053-b09d-ba556bdf39f2
t.go:85: 2023-09-13 14:05:48.505 [debu] POST host=localhost:52569 path=/api/v2/organizations/b2860d31-9376-4ee6-856f-458d60f39869/templates proto=HTTP/1.1 remote_addr=127.0.0.1 took=8.181229ms status_code=201 latency_ms=8 request_id=2a551a02-7c05-4778-b4bd-9f2ed8d89a5b
t.go:85: 2023-09-13 14:05:48.578 [debu] POST host=localhost:52569 path=/api/v2/organizations/b2860d31-9376-4ee6-856f-458d60f39869/members/me/workspaces proto=HTTP/1.1 remote_addr=127.0.0.1 took=67.847233ms status_code=201 latency_ms=67 request_id=c8ce4cfb-91d6-4a24-be43-3f8d1b2138ca
t.go:85: 2023-09-13 14:05:48.726 [debu] POST host=localhost:52569 path=/api/v2/organizations/b2860d31-9376-4ee6-856f-458d60f39869/members/me/workspaces proto=HTTP/1.1 remote_addr=127.0.0.1 took=141.907707ms status_code=201 latency_ms=141 request_id=ade491fb-02b9-4ea4-93c2-0331a30a8c14
t.go:85: 2023-09-13 14:05:48.727 [debu] inmem-provisionerd-zen_williamson8: locked job from database job_id=3c5464a7-1904-41f9-8d43-878b59e66fd3
t.go:85: 2023-09-13 14:05:48.789 [debu] GET host=localhost:52569 path=/api/v2/workspaces proto=HTTP/1.1 remote_addr=127.0.0.1 took=61.670211ms status_code=200 latency_ms=61 request_id=[306](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:307)aaef4-d7ff-4c1e-968c-34e0bbb6b5f5
t.go:85: 2023-09-13 14:05:48.791 [debu] provisionerd: called AcquireJob on client job_id=3c5464a7-1904-41f9-8d43-878b59e66fd3 error=
t.go:85: 2023-09-13 14:05:48.791 [debu] provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=3c5464a7-1904-41f9-8d43-878b59e66fd3 workspace_transition=START workspace_owner=testuser template_name=agitated-bassi5-cuq template_version=laughing_euler8 workspace_build_id=748256c4-48ff-44cb-8859-3f1c5d6cea05 workspace_id=40e9c0c5-861c-4e86-9a39-7be45da72c33 workspace_name=keen-thompson2-SPD
t.go:85: 2023-09-13 14:05:48.791 [debu] provisionerd.runner: acquired job is workspace provision job_id=3c5464a7-1904-41f9-8d43-878b59e66fd3 template_name=agitated-bassi5-cuq template_version=laughing_euler8 workspace_build_id=748256c4-48ff-44cb-8859-3f1c5d6cea05 workspace_id=40e9c0c5-861c-4e86-9a39-7be45da72c33 workspace_name=keen-thompson2-SPD workspace_owner=testuser workspace_transition=start workspace_name=keen-thompson2-SPD state_length=0 rich_parameter_values=[] variable_values=[]
t.go:85: 2023-09-13 14:05:48.807 [debu] inmem-provisionerd-zen_williamson8: stage FailJob starting job_id=3c5464a7-1904-41f9-8d43-878b59e66fd3
t.go:85: 2023-09-13 14:05:48.811 [debu] provisionerd: closing server with error error=
t.go:85: 2023-09-13 14:05:48.811 [info] inmem-provisionerd-zen_williamson8: provisioner daemon disconnected error=
t.go:85: 2023-09-13 14:05:48.817 [debu] workspaceapps.stats_collector: flushing workspace app stats
t.go:85: 2023-09-13 14:05:48.817 [debu] workspaceapps.stats_collector: flushed workspace app stats
t.go:85: 2023-09-13 14:05:48.817 [debu] workspaceapps.stats_collector: workspace app stats collector stopped
t.go:85: 2023-09-13 14:05:48.818 [info] echo: unpacking template source archive session_id=9cda4cfb-51c3-4e35-9680-bc248d81b50d size_bytes=[307](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:308)2
t.go:85: 2023-09-13 14:05:48.818 [debu] echo: extracted file session_id=9cda4cfb-51c3-4e35-9680-bc248d81b50d size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery333[329](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:330)1468/002/Session9cda4cfb-51c3-4e35-9680-bc248d81b50d/0.parse.protobuf mode=-rw-r--r--
t.go:85: 2023-09-13 14:05:48.818 [debu] echo: extracted file session_id=9cda4cfb-51c3-4e35-9680-bc248d81b50d size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery33[332](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:333)91468/002/Session9cda4cfb-51c3-4e35-9680-bc248d81b50d/0.apply.protobuf mode=-rw-r--r--
testing.go:1206: TempDir RemoveAll cleanup: unlinkat /var/folders/42/msf_n1dd6hzgpbvl1mdw0bm40000gn/T/TestWorkspaceFilterManualFilterQuery[333](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:334)3291468/002/Session9cda4cfb-51c3-4e35-9680-bc248d81b50d: directory not empty
t.go:85: 2023-09-13 14:05:48.833 [debu] echo: extracted file session_id=9cda4cfb-51c3-4e35-9680-bc248d81b50d size_bytes=2 path=/var/folders/42/msf_n1dd6hzgpbvl1mdw0bm[400](https://github.com/coder/coder/actions/runs/6173558359/job/16756210316?pr=9652#step:5:401)00gn/T/TestWorkspaceFilterManualFilterQuery3333291468/002/Session9cda4cfb-51c3-4e35-9680-bc248d81b50d/0.plan.protobuf mode=-rw-r--r--
stuntest.go:63: STUN server shutdown
=== FAIL: coderd TestWorkspaceFilterManual (0.00s)