test flake: TestPatchCancelWorkspaceBuild #9331
Description
Seen in: https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330
=== FAIL: coderd TestPatchCancelWorkspaceBuild/User_is_not_allowed_to_cancel (2.00s)
t.go:85: 2023-08-25 09:27:18.518 [debu] workspaceapps.stats_collector: workspace app stats collector started
t.go:85: 2023-08-25 09:27:18.522 [debu] provisionerd: successfully connected to coderd
t.go:85: 2023-08-25 09:27:18.529 [debu] metrics_cache: deployment stats metrics refreshed took=11.236888ms interval=5m0s
t.go:85: 2023-08-25 09:27:18.572 [debu] metrics_cache: template daus metrics refreshed took=54.565245ms interval=1h0m0s
t.go:85: 2023-08-25 09:27:18.577 [debu] POST host=localhost:36613 path=/api/v2/users/first proto=HTTP/1.1 remote_addr=127.0.0.1 took=56.731121ms status_code=201 latency_ms=56 request_id=94f2b3c0-60de-474b-928b-f4421a4245e6
t.go:85: 2023-08-25 09:27:18.592 [debu] POST host=localhost:36613 path=/api/v2/users/login proto=HTTP/1.1 remote_addr=127.0.0.1 took=13.958847ms status_code=201 latency_ms=13 request_id=85bd0fc4-d9c8-4341-8586-8586beb30d67
t.go:85: 2023-08-25 09:27:18.608 [debu] POST host=localhost:36613 path=/api/v2/files proto=HTTP/1.1 remote_addr=127.0.0.1 took=16.65122ms status_code=201 latency_ms=16 request_id=1925d724-1943-496e-a67e-0b3c60747582
t.go:85: 2023-08-25 09:27:18.656 [debu] POST host=localhost:36613 path=/api/v2/organizations/6714fa77-fca9-40a0-83e7-030b323e98c7/templateversions proto=HTTP/1.1 remote_addr=127.0.0.1 took=47.149692ms status_code=201 latency_ms=47 request_id=44fa8160-91ee-438d-ad27-251f067da71b
workspacebuilds_test.go:426: waiting for template version job 27bc9ac0-d2b4-4067-baeb-f170debd428b
t.go:85: 2023-08-25 09:27:18.704 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=22.624523ms status_code=200 latency_ms=22 request_id=cd1cc5ee-1bf1-4990-aab3-5f729a87cc4a
t.go:85: 2023-08-25 09:27:18.722 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=14.500303ms status_code=200 latency_ms=14 request_id=e7731d82-a36e-4d22-832a-8e62c1533127
t.go:85: 2023-08-25 09:27:18.746 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=14.570366ms status_code=200 latency_ms=14 request_id=475a22b7-464a-452d-9111-9f9e98515df0
t.go:85: 2023-08-25 09:27:18.783 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=23.673239ms status_code=200 latency_ms=23 request_id=a870d183-f2df-4d21-802d-eb00c111ed3b
t.go:85: 2023-08-25 09:27:18.819 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=32.828863ms status_code=200 latency_ms=32 request_id=81960cc7-ac8a-470f-82d0-23e65d2f78d3
t.go:85: 2023-08-25 09:27:18.839 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=19.656181ms status_code=200 latency_ms=19 request_id=f6adc2bb-68d5-4ed6-96f4-3c9a741dffbb
t.go:85: 2023-08-25 09:27:18.886 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=46.22388ms status_code=200 latency_ms=46 request_id=1c57fa16-f270-44a8-9887-8887d0c07f2d
t.go:85: 2023-08-25 09:27:18.938 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=52.08111ms status_code=200 latency_ms=52 request_id=fc6039ae-4bc1-4135-ad2a-1b98d3dd44b8
t.go:85: 2023-08-25 09:27:18.969 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=31.170839ms status_code=200 latency_ms=31 request_id=c119b4cb-0de7-4a8d-b8ef-97153c6c6aff
t.go:85: 2023-08-25 09:27:18.999 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=29.109685ms status_code=200 latency_ms=29 request_id=9eed2d6b-4656-4060-8a3a-9c27358d3995
t.go:85: 2023-08-25 09:27:19.033 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=33.831[281](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:282)ms status_code=200 latency_ms=33 request_id=7db46ed8-255c-4a9f-8658-4d89bcb61e58
t.go:85: 2023-08-25 09:27:19.062 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=28.170749ms status_code=200 latency_ms=28 request_id=86b8c1b6-d9e0-47ae-b2e5-8079a248e899
t.go:85: 2023-08-25 09:27:19.083 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=18.506702ms status_code=200 latency_ms=18 request_id=a9e14960-e5af-4d49-b58a-97fd652a709e
t.go:85: 2023-08-25 09:27:19.102 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=17.001403ms status_code=200 latency_ms=17 request_id=649ce8a6-eb1a-475d-97a0-a62eec99c151
t.go:85: 2023-08-25 09:27:19.121 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=14.483175ms status_code=200 latency_ms=14 request_id=e0a36d2c-cb17-46fa-9eef-e290f8892149
t.go:85: 2023-08-25 09:27:19.141 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=8.065019ms status_code=200 latency_ms=8 request_id=5cf07e3e-624a-4431-9f07-170414a85fd3
t.go:85: 2023-08-25 09:27:19.194 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=36.905368ms status_code=200 latency_ms=36 request_id=0f44d4c9-82b2-4772-b502-6b01ad072c57
t.go:85: 2023-08-25 09:27:19.238 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=43.570709ms status_code=200 latency_ms=43 request_id=b5c9a405-a9a5-4434-8425-7d7b3b99bb25
t.go:85: 2023-08-25 09:27:19.[283](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:284) [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=45.359521ms status_code=200 latency_ms=45 request_id=2256f08e-8570-46d4-b530-aaf833c6a021
t.go:85: 2023-08-25 09:27:19.377 [debu] provisionerd-nifty_babbage9: locked job from database job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.385 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=101.594795ms status_code=200 latency_ms=101 request_id=b224f018-7055-464b-be34-84794dbea943
t.go:85: 2023-08-25 09:27:19.404 [debu] provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.404 [debu] provisionerd.runner: acquired job is template import job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 user_variable_values=[]
t.go:85: 2023-08-25 09:27:19.404 [info] echo: unpacking template source archive session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a size_bytes=3072
t.go:85: 2023-08-25 09:27:19.404 [debu] echo: extracted file session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a size_bytes=2 path=/tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Sessione1b223d9-8a12-462f-b821-96509c4c8d3a/0.parse.protobuf mode=-rw-r--r--
t.go:85: 2023-08-25 09:27:19.404 [debu] echo: extracted file session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a size_bytes=2 path=/tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Sessione1b223d9-8a12-462f-b821-96509c4c8d3a/0.apply.protobuf mode=-rw-r--r--
t.go:85: 2023-08-25 09:27:19.404 [debu] echo: extracted file session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a size_bytes=2 path=/tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Sessione1b223d9-8a12-462f-b821-96509c4c8d3a/0.plan.protobuf mode=-rw-r--r--
t.go:85: 2023-08-25 09:27:19.405 [debu] echo: failed to parse readme (missing ok) session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a error="open /tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Sessione1b223d9-8a12-462f-b821-96509c4c8d3a/README.md: no such file or directory"
t.go:85: 2023-08-25 09:27:19.405 [debu] provisionerd.runner: parse complete job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 template_variables=[] readme_len=0 error=""
t.go:85: 2023-08-25 09:27:19.405 [debu] provisionerd-nifty_babbage9: stage UpdateJob starting job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.423 [info] provisionerd.runner: parse dry-run provision successful job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 resource_count=0 resources=[]
t.go:85: 2023-08-25 09:27:19.423 [info] provisionerd.runner: parse dry-run provision successful job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 resource_count=0 resources=[]
t.go:85: 2023-08-25 09:27:19.423 [debu] provisionerd-nifty_babbage9: stage UpdateJob starting job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.434 [debu] provisionerd-nifty_babbage9: job log job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 stage="Setting up" output=""
t.go:85: 2023-08-25 09:27:19.434 [debu] provisionerd-nifty_babbage9: job log job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 stage="Parsing template parameters" output=""
t.go:85: 2023-08-25 09:27:19.434 [debu] provisionerd-nifty_babbage9: job log job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 stage="Detecting persistent resources" output=""
t.go:85: 2023-08-25 09:27:19.434 [debu] provisionerd-nifty_babbage9: job log job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 stage="Detecting ephemeral resources" output=""
t.go:85: 2023-08-25 09:27:19.434 [debu] provisionerd-nifty_babbage9: job log job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5 stage="Cleaning Up" output=""
t.go:85: 2023-08-25 09:27:19.437 [debu] provisionerd-nifty_babbage9: inserted job logs job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.441 [debu] provisionerd-nifty_babbage9: published job logs job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.441 [debu] provisionerd.runner: sending CompletedJob job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.441 [info] echo: recv done on Session session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a error=EOF
t.go:85: 2023-08-25 09:27:19.441 [debu] echo: cleaned up work directory session_id=e1b223d9-8a12-462f-b821-96509c4c8d3a
t.go:85: 2023-08-25 09:27:19.441 [debu] provisionerd-nifty_babbage9: stage CompleteJob starting job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.450 [debu] provisionerd-nifty_babbage9: marked import job as completed job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.450 [debu] provisionerd-nifty_babbage9: stage CompleteJob done job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.451 [debu] provisionerd.runner: sent CompletedJob job_id=e995eea1-efd2-440a-b077-e8e8a03efcb5
t.go:85: 2023-08-25 09:27:19.470 [debu] GET host=localhost:36613 path=/api/v2/templateversions/27bc9ac0-d2b4-4067-baeb-f170debd428b proto=HTTP/1.1 remote_addr=127.0.0.1 took=84.154683ms status_code=200 latency_ms=84 request_id=3d977060-6962-4814-8799-73db033e9d6e
workspacebuilds_test.go:426: got template version job 27bc9ac0-d2b4-4067-baeb-f170debd428b
t.go:85: 2023-08-25 09:27:19.517 [debu] POST host=localhost:36613 path=/api/v2/organizations/6714fa77-fca9-40a0-83e7-030b323e98c7/templates proto=HTTP/1.1 remote_addr=127.0.0.1 took=46.800146ms status_code=201 latency_ms=46 request_id=a7afda8a-f933-4cf1-872a-c1121190cc16
t.go:85: 2023-08-25 09:27:19.534 [debu] POST host=localhost:36613 path=/api/v2/users proto=HTTP/1.1 remote_addr=127.0.0.1 took=16.249484ms status_code=201 latency_ms=16 request_id=6f99a436-40b5-4240-8cb1-a803742cc7ec
t.go:85: 2023-08-25 09:27:19.545 [debu] POST host=localhost:36613 path=/api/v2/users/login proto=HTTP/1.1 remote_addr=127.0.0.1 took=10.417468ms status_code=201 latency_ms=10 request_id=86570b23-886d-49a2-b8e7-539c051d08cd
t.go:85: 2023-08-25 09:27:19.552 [debu] GET host=localhost:36613 path=/api/v2/users/dazzling-margulis7-F8W proto=HTTP/1.1 remote_addr=127.0.0.1 took=7.197789ms status_code=200 latency_ms=7 request_id=56790257-1ce3-44b9-8348-ec938c[293](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:294)0f2
t.go:85: 2023-08-25 09:27:19.623 [debu] POST host=localhost:36613 path=/api/v2/organizations/6714fa77-fca9-40a0-83e7-030b323e98c7/members/me/workspaces proto=HTTP/1.1 remote_addr=127.0.0.1 took=67.926689ms status_code=201 latency_ms=67 request_id=6aa09d0f-379f-4604-a565-d4ad5d35137c
t.go:85: 2023-08-25 09:27:19.660 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=10.93666ms status_code=200 latency_ms=10 request_id=ba4c645b-a390-4dfd-8141-7b88e2cccf74
t.go:85: 2023-08-25 09:27:19.699 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=24.730728ms status_code=200 latency_ms=24 request_id=46[300](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:301)8a2-b097-43d9-9500-4f69a486fa4d
t.go:85: 2023-08-25 09:27:19.755 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=55.671476ms status_code=200 latency_ms=55 request_id=4f2c97c1-942e-4ee4-b6f4-bed4d3b41a76
t.go:85: 2023-08-25 09:27:19.796 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=40.535602ms status_code=200 latency_ms=40 request_id=69635ccc-1fea-4743-9754-6b8aa3dcc90b
t.go:85: 2023-08-25 09:27:19.812 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=15.13946ms status_code=200 latency_ms=15 request_id=2a586315-1084-4eb9-b9f7-1a1a1f3863f0
t.go:85: 2023-08-25 09:27:19.825 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=10.306977ms status_code=200 latency_ms=10 request_id=3d943fe9-5d3f-469a-909c-d43c973363f4
t.go:85: 2023-08-25 09:27:19.833 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=8.373378ms status_code=200 latency_ms=8 request_id=a25a2bdc-fbaa-4ed9-97d8-00ee8b0ea408
t.go:85: 2023-08-25 09:27:19.882 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=32.163386ms status_code=200 latency_ms=32 request_id=8ed422fc-4109-4f3e-9afe-82cc02358f80
t.go:85: 2023-08-25 09:27:19.944 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=62.07146ms status_code=200 latency_ms=62 request_id=ca71c3a2-e69e-45a5-a7a5-69267d703b8d
t.go:85: 2023-08-25 09:27:19.972 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=27.271869ms status_code=200 latency_ms=27 request_id=53d52be2-c2f0-47ae-ba2b-f18488de50c6
t.go:85: 2023-08-25 09:27:20.027 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=54.743308ms status_code=200 latency_ms=54 request_id=c70014c9-16c6-4e7e-8385-72be6ac8b3ef
t.go:85: 2023-08-25 09:27:20.052 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=24.353[302](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:303)ms status_code=200 latency_ms=24 request_id=91960d2a-e6c0-466a-ae9a-e40d230e01c5
t.go:85: 2023-08-25 09:27:20.086 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=32.674172ms status_code=200 latency_ms=32 request_id=10c25be7-3736-459d-adca-dc3af8e83dfe
t.go:85: 2023-08-25 09:27:20.099 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=12.600182ms status_code=200 latency_ms=12 request_id=16e18f98-63c7-41de-936f-552a4b4b6962
t.go:85: 2023-08-25 09:27:20.106 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=6.559141ms status_code=200 latency_ms=6 request_id=7d4a9048-94dc-42c1-93f1-11fca1ff120b
t.go:85: 2023-08-25 09:27:20.131 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=5.11543ms status_code=200 latency_ms=5 request_id=d4f22ca0-eed7-4cfc-a17b-7e8aba1aefd1
t.go:85: 2023-08-25 09:27:20.166 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=16.314743ms status_code=200 latency_ms=16 request_id=ef92e351-0fac-4b29-86a0-8aaf18a0a673
t.go:85: 2023-08-25 09:27:20.206 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=32.266052ms status_code=200 latency_ms=32 request_id=49516aad-4266-480c-b1c8-9a953e121d5c
t.go:85: 2023-08-25 09:27:20.230 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=23.105217ms status_code=200 latency_ms=23 request_id=454705bd-487b-48c2-81f7-8c40c22064ab
t.go:85: 2023-08-25 09:27:20.261 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=30.486268ms status_code=200 latency_ms=30 request_id=b350540e-7836-4818-9a9f-0e33478dccf3
t.go:85: 2023-08-25 09:27:20.309 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=47.004121ms status_code=200 latency_ms=47 request_id=10e5654c-d96c-4792-bb64-9678c25eaf07
t.go:85: 2023-08-25 09:27:20.351 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=41.965557ms status_code=200 latency_ms=41 request_id=0fa05f7a-2426-433f-a165-aebd6055d6dd
t.go:85: 2023-08-25 09:27:20.352 [debu] provisionerd-nifty_babbage9: locked job from database job_id=4d745213-806e-446f-b185-a09148e3ebc9
t.go:85: 2023-08-25 09:27:20.388 [debu] GET host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414 proto=HTTP/1.1 remote_addr=127.0.0.1 took=36.43868ms status_code=200 latency_ms=36 request_id=1167e6b1-a236-419c-ac66-52268567602c
t.go:85: 2023-08-25 09:27:20.401 [debu] provisionerd: acquired job initiator_username=dazzling-margulis7-F8W provisioner=echo job_id=4d745213-806e-446f-b185-a09148e3ebc9 workspace_transition=START workspace_owner=dazzling-margulis7-F8W template_name=pedantic-dirac1-kHj template_version=beautiful_dewdney3 workspace_build_id=702c90e8-26af-412d-8687-2190a0bab414 workspace_id=f7233dd4-ffb1-47e9-8bbe-77dfe5203741 workspace_name=priceless-torvalds4-25c
t.go:85: 2023-08-25 09:27:20.401 [debu] provisionerd.runner: acquired job is workspace provision job_id=4d745213-806e-446f-b185-a09148e3ebc9 template_name=pedantic-dirac1-kHj template_version=beautiful_dewdney3 workspace_build_id=702c90e8-26af-412d-8687-2190a0bab414 workspace_id=f7233dd4-ffb1-47e9-8bbe-77dfe5203741 workspace_name=priceless-torvalds4-25c workspace_owner=dazzling-margulis7-F8W workspace_transition=start workspace_name=priceless-torvalds4-25c state_length=0 rich_parameter_values=[] variable_values=[]
t.go:85: 2023-08-25 09:27:20.401 [info] echo: unpacking template source archive session_id=5920f84e-f7ce-481b-a9ed-2edeb8320183 size_bytes=[307](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:308)2
t.go:85: 2023-08-25 09:27:20.401 [debu] echo: extracted file session_id=5920f84e-f7ce-481b-a9ed-2edeb8[320](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:321)183 size_bytes=2 path=/tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Session5920f84e-f7ce-481b-a9ed-2edeb8320183/0.parse.protobuf mode=-rw-r--r--
t.go:85: 2023-08-25 09:27:20.402 [debu] echo: extracted file session_id=5920f84e-f7ce-481b-a9ed-2edeb8320183 size_bytes=2 path=/tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Session5920f84e-f7ce-481b-a9ed-2edeb8320183/0.apply.protobuf mode=-rw-r--r--
t.go:85: 2023-08-25 09:27:20.402 [debu] echo: extracted file session_id=5920f84e-f7ce-481b-a9ed-2edeb8320183 size_bytes=2 path=/tmp/TestPatchCancelWorkspaceBuildUser_is_not_allowed_to_cancel2227389711/002/Session5920f84e-f7ce-481b-a9ed-2edeb8320183/0.plan.protobuf mode=-rw-r--r--
t.go:85: 2023-08-25 09:27:20.402 [info] provisionerd.runner: plan request successful job_id=4d745213-806e-446f-b185-a09148e3ebc9 template_name=pedantic-dirac1-kHj template_version=beautiful_dewdney3 workspace_build_id=702c90e8-26af-412d-8687-2190a0bab414 workspace_id=f7233dd4-ffb1-47e9-8bbe-77dfe5203741 workspace_name=priceless-torvalds4-25c workspace_owner=dazzling-margulis7-F8W workspace_transition=start resource_count=0 resources=[]
t.go:85: 2023-08-25 09:27:20.402 [debu] provisionerd-nifty_babbage9: stage UpdateJob starting job_id=4d745213-806e-446f-b185-a09148e3ebc9
t.go:85: 2023-08-25 09:27:20.405 [debu] PATCH host=localhost:36613 path=/api/v2/workspacebuilds/702c90e8-26af-412d-8687-2190a0bab414/cancel proto=HTTP/1.1 remote_addr=127.0.0.1 took=16.611851ms status_code=403 latency_ms=16 request_id=a1c1bb50-fa44-4cfd-828a-82[345](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:346)9f64647
t.go:85: 2023-08-25 09:27:20.415 [debu] provisionerd-nifty_babbage9: job log job_id=4d745213-806e-446f-b185-a09148e3ebc9 stage="Setting up" output=""
t.go:85: 2023-08-25 09:27:20.417 [debu] provisionerd-nifty_babbage9: inserted job logs job_id=4d745213-806e-446f-b185-a09148e3ebc9
t.go:85: 2023-08-25 09:27:20.418 [debu] provisionerd-nifty_babbage9: published job logs job_id=4d745213-806e-446f-b185-a09148e3ebc9
t.go:85: 2023-08-25 09:27:20.418 [debu] provisionerd.runner: committing quota job_id=4d745213-806e-446f-b185-a09148e3ebc9 template_name=pedantic-dirac1-kHj template_version=beautiful_dewdney3 workspace_build_id=702c90e8-26af-412d-8687-2190a0bab414 workspace_id=f7233dd4-ffb1-47e9-8bbe-77dfe520[374](https://github.com/coder/coder/actions/runs/5974225410/job/16207962514?pr=9330#step:5:375)1 workspace_name=priceless-torvalds4-25c workspace_owner=dazzling-margulis7-F8W workspace_transition=start resources=[] cost=0
t.go:85: 2023-08-25 09:27:20.418 [debu] provisionerd-nifty_babbage9: stage UpdateJob starting job_id=4d745213-806e-446f-b185-a09148e3ebc9
t.go:85: 2023-08-25 09:27:20.426 [debu] provisionerd-nifty_babbage9: stage FailJob starting job_id=4d745213-806e-446f-b185-a09148e3ebc9
t.go:85: 2023-08-25 09:27:20.481 [debu] provisionerd: closing server with error error=<nil>
t.go:85: 2023-08-25 09:27:20.482 [debu] drpc server error ...
error= context canceled
storj.io/drpc/drpcserver.(*Server).ServeOne:64
storj.io/drpc/drpcserver.(*Server).Serve.func2:114
storj.io/drpc/drpcctx.(*Tracker).track:35
t.go:85: 2023-08-25 09:27:20.482 [debu] workspaceapps.stats_collector: flushing workspace app stats
t.go:85: 2023-08-25 09:27:20.482 [debu] workspaceapps.stats_collector: flushed workspace app stats
t.go:85: 2023-08-25 09:27:20.482 [debu] workspaceapps.stats_collector: workspace app stats collector stopped
t.go:90: 2023-08-25 09:27:20.482 [erro] echo: failed to transmit log session_id=5920f84e-f7ce-481b-a9ed-2edeb8320183 level=TRACE output=""
t.go:85: 2023-08-25 09:27:20.482 [info] echo: recv done on Session session_id=5920f84e-f7ce-481b-a9ed-2edeb8320183 error="context canceled"
t.go:85: 2023-08-25 09:27:20.482 [debu] echo: cleaned up work directory session_id=5920f84e-f7ce-481b-a9ed-2edeb8320183
stuntest.go:63: STUN server shutdown
=== FAIL: coderd TestPatchCancelWorkspaceBuild (0.00s)