flake: enterprise/coderd TestWorkspaceAutobuild/DormantNoAutostart #908
Description
Seen in: https://github.com/coder/coder/actions/runs/17042594929/job/48309938116#step:8:487
=== Failed
=== FAIL: enterprise/coderd TestWorkspaceAutobuild/DormantNoAutostart (1.76s)
t.go:106: 2025-08-18 13:59:35.288 [debu] pubsub: pubsub dialing postgres network=tcp address=127.0.0.1:5432 timeout_ms=0
t.go:106: 2025-08-18 13:59:35.288 [debu] pubsub: pubsub postgres TCP connection established network=tcp address=127.0.0.1:5432 timeout_ms=0 elapsed_ms=0
t.go:106: 2025-08-18 13:59:35.298 [debu] pubsub: pubsub connected to postgres
t.go:106: 2025-08-18 13:59:35.298 [debu] pubsub: pubsub has started
coderdenttest.go:85: coderdtest server listening on 127.0.0.1:43533
coderdenttest.go:85: coderdtest server started on http://127.0.0.1:43533/
t.go:106: 2025-08-18 13:59:35.327 [debu] coderd.dbrollup: rolling up data
t.go:106: 2025-08-18 13:59:35.337 [debu] coderd.metrics_cache: metrics refreshed name="template build times" interval=1h0m0s took=10.459065ms
t.go:106: 2025-08-18 13:59:35.341 [debu] coderd.metrics_cache: metrics refreshed name="deployment stats" interval=5m0s took=14.685015ms
t.go:106: 2025-08-18 13:59:35.346 [debu] coderd.dbrollup: rolled up data took=19.50222ms event={"template_usage_stats":true}
t.go:106: 2025-08-18 13:59:35.347 [debu] coderd.dbrollup: next rollup at next="2025-08-18T14:00:00Z"
t.go:106: 2025-08-18 13:59:35.349 [debu] coderd.keyrotator: no valid keys detected, inserting new key feature=workspace_apps_api_key
t.go:106: 2025-08-18 13:59:35.351 [debu] coderd.keyrotator: inserted new key for feature feature=workspace_apps_api_key
t.go:106: 2025-08-18 13:59:35.351 [debu] coderd.keyrotator: no valid keys detected, inserting new key feature=oidc_convert
t.go:106: 2025-08-18 13:59:35.352 [debu] coderd.keyrotator: inserted new key for feature feature=oidc_convert
t.go:106: 2025-08-18 13:59:35.352 [debu] coderd.keyrotator: no valid keys detected, inserting new key feature=tailnet_resume
t.go:106: 2025-08-18 13:59:35.352 [debu] coderd.keyrotator: inserted new key for feature feature=tailnet_resume
t.go:106: 2025-08-18 13:59:35.353 [debu] coderd.keyrotator: no valid keys detected, inserting new key feature=workspace_apps_token
t.go:106: 2025-08-18 13:59:35.353 [debu] coderd.keyrotator: inserted new key for feature feature=workspace_apps_token
t.go:106: 2025-08-18 13:59:35.353 [debu] coderd.keyrotator: ctx canceled, stopping key rotation
t.go:106: 2025-08-18 13:59:35.354 [debu] pubsub: started listening to event channel event=provisioner_job_posted
t.go:106: 2025-08-18 13:59:35.354 [debu] coderd.acquirer: subscribed to job postings
t.go:106: 2025-08-18 13:59:35.354 [warn] coderd.site: could not parse install.sh, it will be unavailable error="open install.sh: file does not exist"
t.go:106: 2025-08-18 13:59:35.354 [debu] coderd.servertailnet: network isolation configuration use_netns=false
t.go:106: 2025-08-18 13:59:35.355 [debu] coderd.servertailnet.net.wgengine: [v1] using fake (no-op) tun device
t.go:106: 2025-08-18 13:59:35.355 [debu] coderd.servertailnet.net.wgengine: [v1] using fake (no-op) OS network configurator
t.go:106: 2025-08-18 13:59:35.355 [debu] coderd.servertailnet.net.wgengine: [v1] using fake (no-op) DNS configurator
t.go:106: 2025-08-18 13:59:35.355 [debu] coderd.servertailnet.net.wgengine: dns: using dns.noopManager
t.go:106: 2025-08-18 13:59:35.355 [debu] coderd.servertailnet.net.wgengine: link state: interfaces.State{defaultRoute=enp39s0 ifs={docker0:[172.17.0.1/16] enp39s0:[10.20.44.16/19]} v4=true v6=false}
Warning: 106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: [warning] failed to force-set UDP read buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)
Warning: 106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: [warning] failed to force-set UDP write buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: dontfrag: success on [::]:57486
Warning: 106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: [warning] failed to force-set UDP read buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)
Warning: 106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: [warning] failed to force-set UDP write buffer size to 7340032: operation not permitted; using kernel default values (impacts throughput only)
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: dontfrag: success on 0.0.0.0:49762
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: [v1] couldn't create raw v4 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: [v1] couldn't create raw v6 disco listener, using regular listener instead: raw disco listening disabled, SO_MARK unavailable
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: magicsock: disco key = d:c9193a5b71167910
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: Creating WireGuard device...
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: Bringing WireGuard device up...
t.go:106: 2025-08-18 13:59:35.356 [debu] coderd.servertailnet.net.wgengine: wg: [v2] UDP bind has been updated
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - started
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: wg: [v2] Interface state was Down, requested Up, now Up
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: Bringing router up...
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Up: not implemented.
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: Clearing router settings...
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: Starting network monitor...
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet.net.wgengine: Engine created.
t.go:106: 2025-08-18 13:59:35.357 [debu] coderd.servertailnet: magicsock debug logging disabled, use CODER_MAGICSOCK_DEBUG_LOGGING=true to enable
t.go:106: 2025-08-18 13:59:35.358 [debu] coderd.servertailnet.net.wgengine: magicsock: SetPrivateKey called (init)
t.go:106: 2025-08-18 13:59:35.359 [debu] coderd.servertailnet: updating engine network map network_map="netmap: self: [357BW] auth=machine-unknown u=? [fd7a:115c:a1e0:4478:85cd:734b:f28b:288/128]\n"
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.servertailnet.net.wgengine: [v1] magicsock: got updated network map; 0 peers
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.servertailnet: skipped sending node; no node callback
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring userspace WireGuard config (with 0/0 peers)
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.workspaceapps.stats_collector: workspace app stats collector started
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.servertailnet.net.wgengine: wg: [v2] UAPI: Updating private key
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.coord: initPeer peer_id=9eeaab12-c878-443d-bd34-79ea04d7e25c peer_name=inmemory9eeaab12-c878-443d-bd34-79ea04d7e25c
t.go:106: 2025-08-18 13:59:35.360 [debu] coderd.coord: initial tunnel peers peer_id=9eeaab12-c878-443d-bd34-79ea04d7e25c peer_name=inmemory9eeaab12-c878-443d-bd34-79ea04d7e25c tunnel_peers=[]
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet: obtained tailnet API v2+ client
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring router
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet: serving coordinator
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring DNS
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet: skipped sending node; no PreferredDERP node="&{ID:nodeid:1c8cc474063561c7 AsOf:2025-08-18 13:59:35.361283 +0000 UTC Key:nodekey:df9ec15ad5aedba16b731615766798a1d7208d276e5654b744ea2253fbbde351 DiscoKey:discokey:c9193a5b711679109ceb6745d432a1271c1cb30cc56e8a7ef8d81ece4b80f067 PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4478:85cd:734b:f28b:288/128] AllowedIPs:[fd7a:115c:a1e0:4478:85cd:734b:f28b:288/128] Endpoints:[]}"
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[], cloud="aws"}
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet.net.wgengine: [v1] wgengine: Reconfig done
t.go:106: 2025-08-18 13:59:35.361 [debu] coderd.servertailnet: updating engine filter filter="&{logf:0x378ffa0 local:0xc032b3e000 logIPs:0xc032b3e018 matches4:[{IPProto:[6 17 1 58 132] Srcs:[{ip:{addr:{hi:0 lo:281470681743360} z:{value:0xc000238078}} bitsPlusOne:1}] Dsts:[{Net:{ip:{addr:{hi:0 lo:281470681743360} z:{value:0xc000238078}} bitsPlusOne:1} Ports:{First:0 Last:65535}}] Caps:[]}] matches6:[{IPProto:[6 17 1 58 132] Srcs:[{ip:{addr:{hi:0 lo:0} z:{value:0xc000238090}} bitsPlusOne:1}] Dsts:[{Net:{ip:{addr:{hi:0 lo:0} z:{value:0xc000238090}} bitsPlusOne:1} Ports:{First:0 Last:65535}}] Caps:[]}] cap4:[] cap6:[] state:0xc05f62e0a0 shieldsUp:false}"
t.go:106: 2025-08-18 13:59:35.370 [debu] pubsub: publish event=replica message_len=36
t.go:106: 2025-08-18 13:59:35.372 [debu] pubsub: started listening to event channel event=replica
t.go:106: 2025-08-18 13:59:35.375 [debu] coderd.provisionerd: dialing coderd
t.go:106: 2025-08-18 13:59:35.375 [debu] pubsub: started listening to event channel event=licenses
t.go:106: 2025-08-18 13:59:35.375 [debu] coderd: successfully subscribed to pubsub
t.go:106: 2025-08-18 13:59:35.375 [debu] coderd: syncing licensed entitlements
t.go:106: 2025-08-18 13:59:35.376 [debu] coderd: synced licensed entitlements
t.go:106: 2025-08-18 13:59:35.382 [debu] coderd: starting in-memory provisioner daemon name=test-daemon
t.go:106: 2025-08-18 13:59:35.382 [debu] coderd.provisionerd: successfully connected to coderd
t.go:106: 2025-08-18 13:59:35.382 [debu] coderd.provisionerd: start of acquireAndRunOne
t.go:106: 2025-08-18 13:59:35.382 [debu] coderd.acquirer: acquiring job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.382 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.386 [debu] coderd.acquirer: no job available organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.445 [info] coderd: refresh entitlements now request_id=78fcf2ba-be31-4c94-bd63-a3571cea42f1
t.go:106: 2025-08-18 13:59:35.447 [debu] pubsub: publish event=licenses message_len=7
t.go:106: 2025-08-18 13:59:35.447 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/users/first proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.383061867Z" requestor_name=System took=64.830115ms status_code=201 latency_ms=64 request_id=78fcf2ba-be31-4c94-bd63-a3571cea42f1
t.go:106: 2025-08-18 13:59:35.448 [debu] coderd: got pubsub update
t.go:106: 2025-08-18 13:59:35.448 [debu] coderd: syncing licensed entitlements
t.go:106: 2025-08-18 13:59:35.449 [debu] coderd: synced licensed entitlements
t.go:106: 2025-08-18 13:59:35.457 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/users/login proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.448911089Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=8.431651ms status_code=201 latency_ms=8 request_id=fb8bb262-f352-41fc-8a13-e13a1ff1040c
t.go:106: 2025-08-18 13:59:35.475 [debu] pubsub: publish event=licenses message_len=3
t.go:106: 2025-08-18 13:59:35.476 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/licenses proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.458530728Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=17.995219ms status_code=201 latency_ms=17 request_id=b09bb3f4-cc04-4d19-adb6-d1c9d90e03f5
t.go:106: 2025-08-18 13:59:35.476 [debu] coderd: got pubsub update
t.go:106: 2025-08-18 13:59:35.476 [debu] coderd: syncing licensed entitlements
t.go:106: 2025-08-18 13:59:35.478 [debu] coderd: synced licensed entitlements
t.go:106: 2025-08-18 13:59:35.483 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/files proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.477539845Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=6.077063ms status_code=201 latency_ms=6 request_id=bb2e6f61-a580-49d2-b5ee-a3fbb2ed3334
t.go:106: 2025-08-18 13:59:35.508 [debu] pubsub: publish event=provisioner_job_posted message_len=115
t.go:106: 2025-08-18 13:59:35.509 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/organizations/c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6/templateversions proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.484325863Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=25.02653ms status_code=201 latency_ms=25 params_organization=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 request_id=375db19e-4efb-46ef-9fb3-5b919eca54bd
t.go:106: 2025-08-18 13:59:35.509 [debu] coderd.acquirer: got job posting posting={"organization_id":"c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6","type":"echo","tags":{"owner":"","scope":"organization"}}
t.go:106: 2025-08-18 13:59:35.509 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
workspaces_test.go:1241: waiting for template version 79964d3c-e352-470a-9bd8-ab7c3d60fb04 build job to complete
t.go:106: 2025-08-18 13:59:35.511 [debu] coderd.acquirer: successfully acquired job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.511 [debu] coderd.inmem-provisionerd-test-daemon: locked job from database job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.516 [debu] coderd.inmem-provisionerd-test-daemon: closed stream error=<nil>
t.go:106: 2025-08-18 13:59:35.516 [debu] coderd.provisionerd: graceful acquire done job_id=456665e6-b328-4713-89b8-ed184c83d8bb error=<nil>
t.go:106: 2025-08-18 13:59:35.517 [debu] coderd.provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.517 [debu] coderd.provisionerd.runner: acquired job is template import job_id=456665e6-b328-4713-89b8-ed184c83d8bb user_variable_values=[]
t.go:106: 2025-08-18 13:59:35.517 [info] coderd.echo: unpacking template source archive session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 size_bytes=4096
t.go:106: 2025-08-18 13:59:35.517 [debu] coderd.echo: read archive entry session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 name=0.parse.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:35.518 [debu] coderd.echo: extracted file session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessione63ea81e-7f37-4ff9-8385-6c43aa8d8814/0.parse.protobuf mode=-rw-r--r-- checksum=392d622c
t.go:106: 2025-08-18 13:59:35.518 [debu] coderd.echo: read archive entry session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 name=0.apply.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:35.518 [debu] coderd.echo: extracted file session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessione63ea81e-7f37-4ff9-8385-6c43aa8d8814/0.apply.protobuf mode=-rw-r--r-- checksum=e66b54df
t.go:106: 2025-08-18 13:59:35.518 [debu] coderd.echo: read archive entry session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 name=0.plan.protobuf mod_time="1970-01-01T00:00:00Z" size=6
t.go:106: 2025-08-18 13:59:35.518 [debu] coderd.echo: extracted file session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 size_bytes=6 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessione63ea81e-7f37-4ff9-8385-6c43aa8d8814/0.plan.protobuf mode=-rw-r--r-- checksum=f35de715
t.go:106: 2025-08-18 13:59:35.518 [debu] coderd.echo: failed to parse readme (missing ok) session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814 error="open /tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessione63ea81e-7f37-4ff9-8385-6c43aa8d8814/README.md: no such file or directory"
t.go:106: 2025-08-18 13:59:35.519 [debu] coderd.provisionerd.runner: parse complete job_id=456665e6-b328-4713-89b8-ed184c83d8bb workspace_tags=null template_variables=[] readme_len=0 error=""
t.go:106: 2025-08-18 13:59:35.519 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.521 [info] coderd.provisionerd.runner: parse dry-run provision successful job_id=456665e6-b328-4713-89b8-ed184c83d8bb resource_count=0 resources=[]
t.go:106: 2025-08-18 13:59:35.521 [info] coderd.provisionerd.runner: parse dry-run provision successful job_id=456665e6-b328-4713-89b8-ed184c83d8bb resource_count=0 resources=[]
t.go:106: 2025-08-18 13:59:35.521 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.523 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=456665e6-b328-4713-89b8-ed184c83d8bb stage="Setting up" output=""
t.go:106: 2025-08-18 13:59:35.523 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=456665e6-b328-4713-89b8-ed184c83d8bb stage="Parsing template parameters" output=""
t.go:106: 2025-08-18 13:59:35.523 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=456665e6-b328-4713-89b8-ed184c83d8bb stage="Detecting persistent resources" output=""
t.go:106: 2025-08-18 13:59:35.523 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=456665e6-b328-4713-89b8-ed184c83d8bb stage="Detecting ephemeral resources" output=""
t.go:106: 2025-08-18 13:59:35.523 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=456665e6-b328-4713-89b8-ed184c83d8bb stage="Cleaning Up" output=""
t.go:106: 2025-08-18 13:59:35.524 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.525 [debu] pubsub: publish event=provisioner-log-logs:456665e6-b328-4713-89b8-ed184c83d8bb message_len=19
t.go:106: 2025-08-18 13:59:35.525 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.525 [debu] coderd.provisionerd.runner: sending CompletedJob job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.525 [info] coderd.echo: recv done on Session session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814
t.go:106: 2025-08-18 13:59:35.525 [debu] coderd.echo: cleaned up work directory session_id=e63ea81e-7f37-4ff9-8385-6c43aa8d8814
t.go:106: 2025-08-18 13:59:35.525 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob starting job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.531 [debu] coderd.inmem-provisionerd-test-daemon: marked import job as completed job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.532 [debu] pubsub: publish event=provisioner-log-logs:456665e6-b328-4713-89b8-ed184c83d8bb message_len=38
t.go:106: 2025-08-18 13:59:35.532 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob done job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.532 [debu] coderd.provisionerd.runner: sent CompletedJob job_id=456665e6-b328-4713-89b8-ed184c83d8bb
t.go:106: 2025-08-18 13:59:35.532 [debu] coderd.provisionerd: start of acquireAndRunOne
t.go:106: 2025-08-18 13:59:35.532 [debu] coderd.acquirer: acquiring job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.532 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.533 [debu] coderd.acquirer: no job available organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.768 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/templateversions/79964d3c-e352-470a-9bd8-ab7c3d60fb04 proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.761103749Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=6.894919ms status_code=200 latency_ms=6 params_templateversion=79964d3c-e352-470a-9bd8-ab7c3d60fb04 params_organization=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 request_id=2e1f934a-e71a-480d-89a5-bd9dc7179ccb
coderdtest.go:1078: template version job status: succeeded
workspaces_test.go:1241: template version 79964d3c-e352-470a-9bd8-ab7c3d60fb04 job has completed
t.go:106: 2025-08-18 13:59:35.789 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/organizations/c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6/templates proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.769119736Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=20.168855ms status_code=201 latency_ms=20 params_organization=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 request_id=b604915c-cf3e-4ed4-8540-c91757b94f2b
t.go:106: 2025-08-18 13:59:35.843 [debu] pubsub: publish event=provisioner_job_posted message_len=115
t.go:106: 2025-08-18 13:59:35.844 [debu] coderd.acquirer: got job posting posting={"organization_id":"c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6","type":"echo","tags":{"owner":"","scope":"organization"}}
t.go:106: 2025-08-18 13:59:35.844 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.868 [debu] coderd.acquirer: successfully acquired job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.868 [debu] coderd.inmem-provisionerd-test-daemon: locked job from database job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.893 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/users/me/workspaces proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:35.7905743Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=102.981469ms status_code=201 latency_ms=102 params_user=me request_id=1dc5be90-afea-4367-8e31-f5692c34dbac
workspaces_test.go:1251: waiting for workspace build job 4f6fcee1-68e6-4af4-bbb3-f8896eb32c35
t.go:106: 2025-08-18 13:59:35.902 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:35.910 [debu] coderd.inmem-provisionerd-test-daemon: closed stream error=<nil>
t.go:106: 2025-08-18 13:59:35.910 [debu] coderd.provisionerd: graceful acquire done job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 error=<nil>
t.go:106: 2025-08-18 13:59:35.910 [debu] coderd.provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 workspace_transition=START workspace_owner=testuser template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM prebuilt_workspace_build_stage=NONE
t.go:106: 2025-08-18 13:59:35.910 [debu] coderd.provisionerd.runner: acquired job is workspace provision job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start workspace_name=confident-rosalind5-tyM state_length=0 rich_parameter_values=[] variable_values=[]
t.go:106: 2025-08-18 13:59:35.911 [info] coderd.echo: unpacking template source archive session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 size_bytes=4096
t.go:106: 2025-08-18 13:59:35.911 [debu] coderd.echo: read archive entry session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 name=0.parse.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:35.911 [debu] coderd.echo: extracted file session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessionab22ddf1-2734-431f-8bd1-db371e34ca09/0.parse.protobuf mode=-rw-r--r-- checksum=392d622c
t.go:106: 2025-08-18 13:59:35.912 [debu] coderd.echo: read archive entry session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 name=0.apply.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:35.912 [debu] coderd.echo: extracted file session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessionab22ddf1-2734-431f-8bd1-db371e34ca09/0.apply.protobuf mode=-rw-r--r-- checksum=e66b54df
t.go:106: 2025-08-18 13:59:35.912 [debu] coderd.echo: read archive entry session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 name=0.plan.protobuf mod_time="1970-01-01T00:00:00Z" size=6
t.go:106: 2025-08-18 13:59:35.912 [debu] coderd.echo: extracted file session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09 size_bytes=6 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Sessionab22ddf1-2734-431f-8bd1-db371e34ca09/0.plan.protobuf mode=-rw-r--r-- checksum=f35de715
t.go:106: 2025-08-18 13:59:35.912 [info] coderd.provisionerd.runner: plan request successful job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start resource_count=0 resources=[]
t.go:106: 2025-08-18 13:59:35.913 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.915 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 stage="Setting up" output=""
t.go:106: 2025-08-18 13:59:35.916 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.916 [debu] pubsub: publish event=provisioner-log-logs:5be923a1-7a7f-45c5-b969-92572e75bf56 message_len=19
t.go:106: 2025-08-18 13:59:35.916 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.916 [debu] coderd.provisionerd.runner: committing quota job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start resources=[] cost=0
t.go:106: 2025-08-18 13:59:35.917 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.919 [info] coderd.provisionerd.runner: apply successful job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start resource_count=0 resources=[] state_len=0
t.go:106: 2025-08-18 13:59:35.920 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.922 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 stage="Starting workspace" output=""
t.go:106: 2025-08-18 13:59:35.922 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.923 [debu] pubsub: publish event=provisioner-log-logs:5be923a1-7a7f-45c5-b969-92572e75bf56 message_len=19
t.go:106: 2025-08-18 13:59:35.923 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.923 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.925 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 stage="Cleaning Up" output=""
t.go:106: 2025-08-18 13:59:35.926 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.926 [debu] pubsub: publish event=provisioner-log-logs:5be923a1-7a7f-45c5-b969-92572e75bf56 message_len=19
t.go:106: 2025-08-18 13:59:35.926 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.927 [info] coderd.echo: recv done on Session session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09
t.go:106: 2025-08-18 13:59:35.927 [debu] coderd.provisionerd.runner: sending CompletedJob job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start
t.go:106: 2025-08-18 13:59:35.927 [debu] coderd.echo: cleaned up work directory session_id=ab22ddf1-2734-431f-8bd1-db371e34ca09
t.go:106: 2025-08-18 13:59:35.927 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob starting job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.943 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:35.943 [debu] pubsub: publish event=provisioner-log-logs:5be923a1-7a7f-45c5-b969-92572e75bf56 message_len=38
t.go:106: 2025-08-18 13:59:35.943 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob done job_id=5be923a1-7a7f-45c5-b969-92572e75bf56
t.go:106: 2025-08-18 13:59:35.943 [debu] coderd.provisionerd.runner: sent CompletedJob job_id=5be923a1-7a7f-45c5-b969-92572e75bf56 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start
t.go:106: 2025-08-18 13:59:35.944 [debu] coderd.provisionerd: start of acquireAndRunOne
t.go:106: 2025-08-18 13:59:35.944 [debu] coderd.acquirer: acquiring job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.944 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:35.945 [debu] coderd.acquirer: no job available organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.153 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/workspacebuilds/4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.14608608Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=7.604495ms status_code=200 latency_ms=7 params_workspacebuild=4f6fcee1-68e6-4af4-bbb3-f8896eb32c35 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=a5c26fea-3b48-4526-af54-7d049cd42caf
workspaces_test.go:1251: got workspace build job 4f6fcee1-68e6-4af4-bbb3-f8896eb32c35
t.go:106: 2025-08-18 13:59:36.210 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/workspaces/9b56d0fe-1e7c-4214-9801-311c820cc43c proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.154718822Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=55.566069ms status_code=200 latency_ms=55 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=8dd41933-35e2-475d-8458-4ad640c1b2fb
t.go:106: 2025-08-18 13:59:36.238 [debu] pubsub: publish event=provisioner_job_posted message_len=115
t.go:106: 2025-08-18 13:59:36.238 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:36.238 [debu] coderd.acquirer: got job posting posting={"organization_id":"c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6","type":"echo","tags":{"owner":"","scope":"organization"}}
t.go:106: 2025-08-18 13:59:36.238 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.239 [debu] coderd: POST host=127.0.0.1:43533 path=/api/v2/workspaces/9b56d0fe-1e7c-4214-9801-311c820cc43c/builds proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.211381189Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=27.664278ms status_code=201 latency_ms=27 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=68e52f6e-3861-4bda-9c39-0189377af5cd
workspaces_test.go:1252: waiting for workspace build job acc8a04e-ffd6-447b-b167-3e9760c7d3e2
t.go:106: 2025-08-18 13:59:36.239 [debu] coderd.acquirer: successfully acquired job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.239 [debu] coderd.inmem-provisionerd-test-daemon: locked job from database job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.246 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:36.255 [debu] coderd.inmem-provisionerd-test-daemon: closed stream error=<nil>
t.go:106: 2025-08-18 13:59:36.255 [debu] coderd.provisionerd: graceful acquire done job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b error=<nil>
t.go:106: 2025-08-18 13:59:36.255 [debu] coderd.provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b workspace_transition=STOP workspace_owner=testuser template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM prebuilt_workspace_build_stage=NONE
t.go:106: 2025-08-18 13:59:36.255 [debu] coderd.provisionerd.runner: acquired job is workspace provision job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=stop workspace_name=confident-rosalind5-tyM state_length=0 rich_parameter_values=[] variable_values=[]
t.go:106: 2025-08-18 13:59:36.256 [info] coderd.echo: unpacking template source archive session_id=369257bd-5b12-47c2-af74-e092df59cc9e size_bytes=4096
t.go:106: 2025-08-18 13:59:36.256 [debu] coderd.echo: read archive entry session_id=369257bd-5b12-47c2-af74-e092df59cc9e name=0.parse.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:36.256 [debu] coderd.echo: extracted file session_id=369257bd-5b12-47c2-af74-e092df59cc9e size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Session369257bd-5b12-47c2-af74-e092df59cc9e/0.parse.protobuf mode=-rw-r--r-- checksum=392d622c
t.go:106: 2025-08-18 13:59:36.256 [debu] coderd.echo: read archive entry session_id=369257bd-5b12-47c2-af74-e092df59cc9e name=0.apply.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:36.256 [debu] coderd.echo: extracted file session_id=369257bd-5b12-47c2-af74-e092df59cc9e size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Session369257bd-5b12-47c2-af74-e092df59cc9e/0.apply.protobuf mode=-rw-r--r-- checksum=e66b54df
t.go:106: 2025-08-18 13:59:36.256 [debu] coderd.echo: read archive entry session_id=369257bd-5b12-47c2-af74-e092df59cc9e name=0.plan.protobuf mod_time="1970-01-01T00:00:00Z" size=6
t.go:106: 2025-08-18 13:59:36.257 [debu] coderd.echo: extracted file session_id=369257bd-5b12-47c2-af74-e092df59cc9e size_bytes=6 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Session369257bd-5b12-47c2-af74-e092df59cc9e/0.plan.protobuf mode=-rw-r--r-- checksum=f35de715
t.go:106: 2025-08-18 13:59:36.257 [info] coderd.provisionerd.runner: plan request successful job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=stop resource_count=0 resources=[]
t.go:106: 2025-08-18 13:59:36.257 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.260 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b stage="Setting up" output=""
t.go:106: 2025-08-18 13:59:36.261 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.261 [debu] pubsub: publish event=provisioner-log-logs:b0bf6b71-6980-4c4d-801a-796ac8cd448b message_len=19
t.go:106: 2025-08-18 13:59:36.261 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.262 [debu] coderd.provisionerd.runner: committing quota job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=stop resources=[] cost=0
t.go:106: 2025-08-18 13:59:36.262 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.264 [info] coderd.provisionerd.runner: apply successful job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=stop resource_count=0 resources=[] state_len=0
t.go:106: 2025-08-18 13:59:36.264 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.266 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b stage="Stopping workspace" output=""
t.go:106: 2025-08-18 13:59:36.267 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.267 [debu] pubsub: publish event=provisioner-log-logs:b0bf6b71-6980-4c4d-801a-796ac8cd448b message_len=19
t.go:106: 2025-08-18 13:59:36.268 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.268 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.270 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b stage="Cleaning Up" output=""
t.go:106: 2025-08-18 13:59:36.271 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.271 [debu] pubsub: publish event=provisioner-log-logs:b0bf6b71-6980-4c4d-801a-796ac8cd448b message_len=20
t.go:106: 2025-08-18 13:59:36.271 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.271 [info] coderd.echo: recv done on Session session_id=369257bd-5b12-47c2-af74-e092df59cc9e
t.go:106: 2025-08-18 13:59:36.271 [debu] coderd.provisionerd.runner: sending CompletedJob job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=stop
t.go:106: 2025-08-18 13:59:36.271 [debu] coderd.echo: cleaned up work directory session_id=369257bd-5b12-47c2-af74-e092df59cc9e
t.go:106: 2025-08-18 13:59:36.272 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob starting job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.282 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:36.282 [debu] pubsub: publish event=provisioner-log-logs:b0bf6b71-6980-4c4d-801a-796ac8cd448b message_len=38
t.go:106: 2025-08-18 13:59:36.282 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob done job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b
t.go:106: 2025-08-18 13:59:36.282 [debu] coderd.provisionerd.runner: sent CompletedJob job_id=b0bf6b71-6980-4c4d-801a-796ac8cd448b template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=stop
t.go:106: 2025-08-18 13:59:36.283 [debu] coderd.provisionerd: start of acquireAndRunOne
t.go:106: 2025-08-18 13:59:36.283 [debu] coderd.acquirer: acquiring job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.283 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.284 [debu] coderd.acquirer: no job available organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.498 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/workspacebuilds/acc8a04e-ffd6-447b-b167-3e9760c7d3e2 proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.491071225Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=7.073961ms status_code=200 latency_ms=7 params_workspacebuild=acc8a04e-ffd6-447b-b167-3e9760c7d3e2 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=bf55bdde-7b5b-4216-8a7d-40fb3b563e7b
workspaces_test.go:1252: got workspace build job acc8a04e-ffd6-447b-b167-3e9760c7d3e2
t.go:106: 2025-08-18 13:59:36.555 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/workspaces/9b56d0fe-1e7c-4214-9801-311c820cc43c proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.499202654Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=55.8971ms status_code=200 latency_ms=55 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=5391143f-8a12-478a-888e-f9d5c30e6b01
workspaces_test.go:1258: Updating provisioner efdf59e2-a614-4213-9edf-b9fddb10302b LastSeenAt to 2025-08-18 11:30:00 -0230 -0230
workspaces_test.go:1258: Successfully updated provisioner LastSeenAt
t.go:106: 2025-08-18 13:59:36.570 [debu] coderd.autobuild: hasValidProvisioner: found active provisioner tags={"owner":"","scope":"organization"} daemon_id=efdf59e2-a614-4213-9edf-b9fddb10302b
t.go:106: 2025-08-18 13:59:36.570 [debu] coderd.autobuild: auto building workspace workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM transition=start
t.go:106: 2025-08-18 13:59:36.587 [info] coderd.autobuild: scheduling workspace transition workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM transition=start reason=autostart
t.go:106: 2025-08-18 13:59:36.587 [debu] pubsub: publish event=provisioner_job_posted message_len=115
t.go:106: 2025-08-18 13:59:36.587 [debu] coderd.autobuild: run stats elapsed=0s transitions={"9b56d0fe-1e7c-4214-9801-311c820cc43c":"start"}
t.go:106: 2025-08-18 13:59:36.587 [debu] coderd.acquirer: got job posting posting={"organization_id":"c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6","type":"echo","tags":{"owner":"","scope":"organization"}}
t.go:106: 2025-08-18 13:59:36.588 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.588 [debu] coderd.acquirer: successfully acquired job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.589 [debu] coderd.inmem-provisionerd-test-daemon: locked job from database job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.639 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:36.649 [debu] coderd.inmem-provisionerd-test-daemon: closed stream error=<nil>
t.go:106: 2025-08-18 13:59:36.649 [debu] coderd.provisionerd: graceful acquire done job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 error=<nil>
t.go:106: 2025-08-18 13:59:36.649 [debu] coderd.provisionerd: acquired job initiator_username=testuser provisioner=echo job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 workspace_transition=START workspace_owner=testuser template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM prebuilt_workspace_build_stage=NONE
t.go:106: 2025-08-18 13:59:36.650 [debu] coderd.provisionerd.runner: acquired job is workspace provision job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start workspace_name=confident-rosalind5-tyM state_length=0 rich_parameter_values=[] variable_values=[]
t.go:106: 2025-08-18 13:59:36.650 [info] coderd.echo: unpacking template source archive session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 size_bytes=4096
t.go:106: 2025-08-18 13:59:36.650 [debu] coderd.echo: read archive entry session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 name=0.parse.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:36.650 [debu] coderd.echo: extracted file session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Session07f46b27-56ac-4bf1-944a-3c3c2abd7186/0.parse.protobuf mode=-rw-r--r-- checksum=392d622c
t.go:106: 2025-08-18 13:59:36.651 [debu] coderd.echo: read archive entry session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 name=0.apply.protobuf mod_time="1970-01-01T00:00:00Z" size=2
t.go:106: 2025-08-18 13:59:36.651 [debu] coderd.echo: extracted file session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 size_bytes=2 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Session07f46b27-56ac-4bf1-944a-3c3c2abd7186/0.apply.protobuf mode=-rw-r--r-- checksum=e66b54df
t.go:106: 2025-08-18 13:59:36.651 [debu] coderd.echo: read archive entry session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 name=0.plan.protobuf mod_time="1970-01-01T00:00:00Z" size=6
t.go:106: 2025-08-18 13:59:36.651 [debu] coderd.echo: extracted file session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186 size_bytes=6 path=/tmp/TestWorkspaceAutobuildDormantNoAutostart2551094927/002/Session07f46b27-56ac-4bf1-944a-3c3c2abd7186/0.plan.protobuf mode=-rw-r--r-- checksum=f35de715
t.go:106: 2025-08-18 13:59:36.651 [info] coderd.provisionerd.runner: plan request successful job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start resource_count=0 resources=[]
t.go:106: 2025-08-18 13:59:36.652 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.653 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/workspaces/9b56d0fe-1e7c-4214-9801-311c820cc43c proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.588265302Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=64.788435ms status_code=200 latency_ms=64 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=acd58d98-735b-4a2b-9348-7bd2b5623813
workspaces_test.go:1267: waiting for workspace build job d9adec50-9d38-4866-a61c-eb57ce9a5533
t.go:106: 2025-08-18 13:59:36.654 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 stage="Setting up" output=""
t.go:106: 2025-08-18 13:59:36.655 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.655 [debu] pubsub: publish event=provisioner-log-logs:da9ee502-7244-4039-8750-5e9f81ad63a3 message_len=20
t.go:106: 2025-08-18 13:59:36.655 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.655 [debu] coderd.provisionerd.runner: committing quota job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start resources=[] cost=0
t.go:106: 2025-08-18 13:59:36.656 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.658 [info] coderd.provisionerd.runner: apply successful job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start resource_count=0 resources=[] state_len=0
t.go:106: 2025-08-18 13:59:36.658 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.660 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 stage="Starting workspace" output=""
t.go:106: 2025-08-18 13:59:36.661 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.661 [debu] pubsub: publish event=provisioner-log-logs:da9ee502-7244-4039-8750-5e9f81ad63a3 message_len=20
t.go:106: 2025-08-18 13:59:36.661 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.662 [debu] coderd.inmem-provisionerd-test-daemon: stage UpdateJob starting job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.664 [debu] coderd.inmem-provisionerd-test-daemon: job log job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 stage="Cleaning Up" output=""
t.go:106: 2025-08-18 13:59:36.664 [debu] coderd.inmem-provisionerd-test-daemon: inserted job logs job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.664 [debu] pubsub: publish event=provisioner-log-logs:da9ee502-7244-4039-8750-5e9f81ad63a3 message_len=20
t.go:106: 2025-08-18 13:59:36.665 [debu] coderd.inmem-provisionerd-test-daemon: published job logs job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.665 [info] coderd.echo: recv done on Session session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186
t.go:106: 2025-08-18 13:59:36.665 [debu] coderd.provisionerd.runner: sending CompletedJob job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start
t.go:106: 2025-08-18 13:59:36.665 [debu] coderd.echo: cleaned up work directory session_id=07f46b27-56ac-4bf1-944a-3c3c2abd7186
t.go:106: 2025-08-18 13:59:36.665 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob starting job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.676 [debu] pubsub: publish event=workspace_owner:67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 message_len=77
t.go:106: 2025-08-18 13:59:36.676 [debu] pubsub: publish event=provisioner-log-logs:da9ee502-7244-4039-8750-5e9f81ad63a3 message_len=38
t.go:106: 2025-08-18 13:59:36.676 [debu] coderd.inmem-provisionerd-test-daemon: stage CompleteJob done job_id=da9ee502-7244-4039-8750-5e9f81ad63a3
t.go:106: 2025-08-18 13:59:36.677 [debu] coderd.provisionerd.runner: sent CompletedJob job_id=da9ee502-7244-4039-8750-5e9f81ad63a3 template_name=vigilant-tesla0-4GF template_version=great_bhabha7 workspace_build_id=d9adec50-9d38-4866-a61c-eb57ce9a5533 workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM workspace_owner=testuser workspace_transition=start
t.go:106: 2025-08-18 13:59:36.677 [debu] coderd.provisionerd: start of acquireAndRunOne
t.go:106: 2025-08-18 13:59:36.677 [debu] coderd.acquirer: acquiring job organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.677 [debu] coderd.acquirer: got clearance to call database organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.678 [debu] coderd.acquirer: no job available organization_id=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 worker_id=efdf59e2-a614-4213-9edf-b9fddb10302b provisioner_types=[echo] tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.911 [debu] coderd: GET host=127.0.0.1:43533 path=/api/v2/workspacebuilds/d9adec50-9d38-4866-a61c-eb57ce9a5533 proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.904979134Z" workspace_name=confident-rosalind5-tyM requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=6.96241ms status_code=200 latency_ms=6 params_workspacebuild=d9adec50-9d38-4866-a61c-eb57ce9a5533 params_workspace=9b56d0fe-1e7c-4214-9801-311c820cc43c request_id=0a077810-3d73-49e2-8eaa-db8ea89bac56
workspaces_test.go:1267: got workspace build job d9adec50-9d38-4866-a61c-eb57ce9a5533
t.go:106: 2025-08-18 13:59:36.937 [debu] coderd: PATCH host=127.0.0.1:43533 path=/api/v2/templates/e80dda39-b10f-4637-9a77-c4968085280e proto=HTTP/1.1 remote_addr=127.0.0.1 start="2025-08-18T13:59:36.913068572Z" requestor_id=67cd3a43-9eb7-40a1-bfd7-5450f84ee0c0 requestor_name=testuser requestor_email=testuser@coder.com took=24.838839ms status_code=200 latency_ms=24 params_template=e80dda39-b10f-4637-9a77-c4968085280e params_organization=c3a1ec56-1a40-4082-aba9-8eb0d82bc7c6 request_id=165e5390-d666-46ef-a4c2-0e21d3894095
workspaces_test.go:1280: Updating provisioner efdf59e2-a614-4213-9edf-b9fddb10302b LastSeenAt to 2025-08-18 11:30:00 -0230 -0230
workspaces_test.go:1280: Successfully updated provisioner LastSeenAt
t.go:106: 2025-08-18 13:59:36.948 [debu] coderd.autobuild: hasValidProvisioner: no active provisioners found tags={"owner":"","scope":"organization"}
t.go:106: 2025-08-18 13:59:36.948 [warn] coderd.autobuild: skipping autostart - no available provisioners workspace_id=9b56d0fe-1e7c-4214-9801-311c820cc43c workspace_name=confident-rosalind5-tyM
t.go:106: 2025-08-18 13:59:36.948 [debu] coderd.autobuild: run stats elapsed=0s transitions={}
workspaces_test.go:1284:
Error Trace: /home/runner/work/coder/coder/enterprise/coderd/workspaces_test.go:1284
Error: "map[]" should have 1 item(s), but has 0
Test: TestWorkspaceAutobuild/DormantNoAutostart
=== FAIL: enterprise/coderd TestWorkspaceAutobuild (0.00s)
Related to #256
Metadata
Metadata
Assignees
Labels
No labels