=== FAIL: coderd TestWorkspaceAgent_Metadata_CatchMemoryLeak (0.06s)
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.acquirer: subscribed to job postings
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.metrics_cache: metrics refreshed  name="deployment stats"  interval=5m0s  took=21.945µs
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.servertailnet.net.wgengine: [v1] using fake (no-op) tun device
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.servertailnet.net.wgengine: [v1] using fake (no-op) OS network configurator
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.servertailnet.net.wgengine: [v1] using fake (no-op) DNS configurator
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.dbrollup: rolling up data
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: dns: using dns.noopManager
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: link state: interfaces.State{defaultRoute=eth0 ifs={docker0:[172.17.0.1/16] eth0:[192.168.100.243/24]} v4=true v6=false}
Warning: 99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: magicsock: [warning] failed to force-set UDP read buffer size to 7[340](https://github.com/coder/coder/actions/runs/9479363424/job/26117743021?pr=13536#step:5:341)032: operation not permitted; using kernel default values (impacts throughput only)
Warning: 99: 2024-06-12 08:37:41.950 [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)
Warning: 99: 2024-06-12 08:37:41.950 [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: 99: 2024-06-12 08:37:41.950 [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:99: 2024-06-12 08:37:41.950 [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:99: 2024-06-12 08:37:41.950 [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:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: magicsock: disco key = d:29556cbf6570c6cf
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Creating WireGuard device...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Bringing WireGuard device up...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] UDP bind has been updated
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Interface state was Down, requested Up, now Up
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Bringing router up...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Up: not implemented.
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Clearing router settings...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Starting network monitor...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Engine created.
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet: magicsock debug logging disabled, use CODER_MAGICSOCK_DEBUG_LOGGING=true to enable
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: magicsock: SetPrivateKey called (init)
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - started
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.coord: initPeer  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  peer_name=475d835a-2ba1-439b-af3e-21e67d945f19
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.coord: initial tunnel peers  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  peer_name=475d835a-2ba1-439b-af3e-21e67d945f19  tunnel_peers=[]
    t.go:99: 2024-06-12 08:37:41.951 [info]  coderd.servertailnet: updating engine DERP map  derp_map="{\"Regions\":{\"1000\":{\"EmbeddedRelay\":false,\"RegionID\":1000,\"RegionCode\":\"coder_stun_1000\",\"RegionName\":\"Coder STUN 1000\",\"Nodes\":[{\"Name\":\"1000stun0\",\"RegionID\":1000,\"HostName\":\"127.0.0.1\",\"STUNPort\":56117,\"STUNOnly\":true}]},\"999\":{\"EmbeddedRelay\":true,\"RegionID\":999,\"RegionCode\":\"coder\",\"RegionName\":\"Coder Embedded Relay\",\"Nodes\":[{\"Name\":\"999b\",\"RegionID\":999,\"HostName\":\"\",\"IPv4\":\"127.0.0.1\",\"STUNPort\":-1,\"DERPPort\":45601,\"InsecureForTests\":true,\"ForceHTTP\":true}]}}}"
    t.go:99: 2024-06-12 08:37:41.951 [info]  coderd.servertailnet: updating engine network map  network_map="netmap: self: [DBcOr] auth=machine-unknown u=? [fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128]\n"
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: [v1] magicsock: got updated network map; 0 peers
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.netstack: [v2] netstack: registered IP fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: magicsock: endpoints changed: 172.17.0.1:56143 (local), 192.168.100.243:56143 (local)
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring userspace WireGuard config (with 0/0 peers)
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] UAPI: Updating private key
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring router
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring DNS
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.metrics_cache: metrics refreshed  name="template build times"  interval=1h0m0s  took=2.532257ms
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet: wireguard status  status="&{AsOf:2024-06-12 08:37:41.951877339 +0000 UTC m=+10.634862584 Peers:[] LocalAddrs:[{Addr:172.17.0.1:56143 Type:local} {Addr:192.168.100.243:56143 Type:local}] DERPs:0}"  error=<nil>
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet: skipped sending node; no PreferredDERP  node="&{ID:nodeid:60b8c014fba00222 AsOf:2024-06-12 08:37:41.952313 +0000 UTC Key:nodekey:0c170eac2533505f730a03184f10b51e397fabfbb2a17c81c6253b46d932af6e DiscoKey:discokey:29556cbf6570c6cf29939bdb74c99eb7aec60a1a963b71a752e8112090306a6b PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] AllowedIPs:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] Endpoints:[]}"
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.workspaceapps.stats_collector: workspace app stats collector started
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet: skipped sending node; no PreferredDERP  node="&{ID:nodeid:60b8c014fba00222 AsOf:2024-06-12 08:37:41.952391 +0000 UTC Key:nodekey:0c170eac2533505f730a03184f10b51e397fabfbb2a17c81c6253b46d932af6e DiscoKey:discokey:29556cbf6570c6cf29939bdb74c99eb7aec60a1a963b71a752e8112090306a6b PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] AllowedIPs:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] Endpoints:[172.17.0.1:56143 192.168.100.243:56143]}"
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.dbrollup: rolled up data  took=2.557537ms  event={"template_usage_stats":true}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.dbrollup: next rollup at  next="2024-06-12T08:40:00Z"
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:56143 (43825097223ee413b2f9ca36) in 134.757µs
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:56143 (f9ee983633d7402f374e8896) in 127.604µs
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:56143 (ca8b2055f61aa573561e0805) in 143.695µs
    t.go:99: 2024-06-12 08:37:41.953 [debu]  coderd.provisionerd: dialing coderd
    t.go:99: 2024-06-12 08:37:41.954 [info]  coderd: starting in-memory provisioner daemon  name=test
    t.go:99: 2024-06-12 08:37:41.954 [info]  coderd.provisionerd: successfully connected to coderd
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.provisionerd: start of acquireAndRunOne
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.acquirer: acquiring job  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.acquirer: got clearance to call database  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.acquirer: no job available  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}
    t.go:99: 2024-06-12 08:37:41.955 [debu]  coderd: entitlements will not be refreshed  request_id=2a52fff5-52c6-4473-a76e-d8fa7a5c987d
    t.go:99: 2024-06-12 08:37:41.956 [debu]  coderd.servertailnet.net.wgengine: [v1] wgengine: Reconfig done
    t.go:99: 2024-06-12 08:37:41.956 [info]  coderd.servertailnet: updating engine filter  filter="&{logf:0x1da8e60 local:0xc04dabc150 logIPs:0xc04dabc168 matches4:[{IPProto:[6 17 1 58 132] Srcs:[{ip:{addr:{hi:0 lo:281470681743360} z:0xc0001260a8} bitsPlusOne:1}] Dsts:[{Net:{ip:{addr:{hi:0 lo:281470681743360} z:0xc0001260a8} bitsPlusOne:1} Ports:{First:0 Last:65535}}] Caps:[]}] matches6:[{IPProto:[6 17 1 58 132] Srcs:[{ip:{addr:{hi:0 lo:0} z:0xc0001260c0} bitsPlusOne:1}] Dsts:[{Net:{ip:{addr:{hi:0 lo:0} z:0xc0001260c0} bitsPlusOne:1} Ports:{First:0 Last:65535}}] Caps:[]}] cap4:[] cap6:[] state:0xc046b460e0 shieldsUp:false}"
    t.go:99: 2024-06-12 08:37:41.956 [debu]  coderd: POST  host=localhost:45601  path=/api/v2/users/first  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.954247628Z"  took=2.041504ms  status_code=201  latency_ms=2  request_id=2a52fff5-52c6-4473-a76e-d8fa7a5c987d
    t.go:99: 2024-06-12 08:37:41.957 [debu]  coderd: POST  host=localhost:45601  path=/api/v2/users/login  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.956610274Z"  took=1.057802ms  status_code=201  latency_ms=1  request_id=0e57f1da-7b83-4c79-8f67-74540fd4d282
    t.go:99: 2024-06-12 08:37:41.966 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaces/c7997669-009a-4768-ad89-b63facce0533  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.958185928Z"  took=8.008113ms  status_code=200  latency_ms=8  request_id=17834be5-a552-407d-98b6-0e0257a20c5b
    t.go:99: 2024-06-12 08:37:41.968 [debu]  coderd.agentrpc: accepting agent RPC connection  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78  agent={"id":"d155ce7e-f32c-405b-856e-b4015b9bb167","created_at":"2024-06-12T08:37:41.958078Z","updated_at":"2024-06-12T08:37:41.958078Z","name":"","first_connected_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"last_connected_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"disconnected_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"resource_id":"0e42006a-69ec-4349-a288-8ef5f5b1ad26","auth_token":"72938252-22b4-4abb-93f8-d920fed77bd9","auth_instance_id":{"String":"","Valid":false},"architecture":"","environment_variables":{"RawMessage":null,"Valid":false},"operating_system":"","instance_metadata":{"RawMessage":null,"Valid":false},"resource_metadata":{"RawMessage":null,"Valid":false},"directory":"","version":"","last_connected_replica_id":null,"connection_timeout_seconds":0,"troubleshooting_url":"","motd_file":"","lifecycle_state":"created","expanded_directory":"","logs_length":0,"logs_overflowed":false,"started_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"ready_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"subsystems":null,"display_apps":null,"api_version":"","display_order":0}
    t.go:99: 2024-06-12 08:37:41.972 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaces/c7997669-009a-4768-ad89-b63facce0533  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.968788787Z"  took=3.585105ms  status_code=200  latency_ms=3  request_id=5b5f7c16-da47-4f8a-b73e-84c32d21100d
    t.go:99: 2024-06-12 08:37:41.972 [debu]  coderd.workspace_metadata_watcher: got initial metadata  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86  num=2
    t.go:99: 2024-06-12 08:37:41.972 [debu]  coderd.workspace_metadata_watcher: sending metadata  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86  num=2
    t.go:99: 2024-06-12 08:37:41.973 [debu]  coderd.agentrpc: accepted metadata report  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78  collected_at="2024-06-12T08:37:41.97[342](https://github.com/coder/coder/actions/runs/9479363424/job/26117743021?pr=13536#step:5:343)2Z"  key=foo1  value=hi
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspace_metadata_watcher: received metadata update  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86  payload={"collected_at":"2024-06-12T08:37:41.973422Z","keys":["foo1"]}
    t.go:102: 2024-06-12 08:37:41.974 [erro]  coderd.workspace_metadata_watcher: failed to get metadata  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86 ...
        error= test error:
                   github.com/coder/coder/v2/coderd_test.TestWorkspaceAgent_Metadata_CatchMemoryLeak
                       /home/runner/actions-runner/_work/coder/coder/coderd/workspaceagents_test.go:1386
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaceagents/d155ce7e-f32c-405b-856e-b4015b9bb167/watch-metadata  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.972629426Z"  took=1.695663ms  status_code=200  latency_ms=1  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86
    workspaceagents_test.go:1419: 
        	Error Trace:	/home/runner/actions-runner/_work/coder/coder/coderd/workspaceagents_test.go:1419
        	            				/home/runner/actions-runner/_work/coder/coder/testutil/go.go:18
        	            				/opt/hostedtoolcache/go/1.22.3/x64/src/runtime/asm_amd64.s:1695
        	Error:      	Received unexpected error:
        	            	session shutdown
        	Test:       	TestWorkspaceAgent_Metadata_CatchMemoryLeak
        	Messages:   	post metadata foo1
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd: agent connection monitor is closing connection  workspace_id=c7997669-009a-4768-ad89-b63facce0533  agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=77f95cfb-823d-4d01-a484-2e368568de78  reason=canceled
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.provisionerd: attempting graceful shutdown
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: sending acquire job cancel
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.agentrpc: drpc server error  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78 ...
        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:99: 2024-06-12 08:37:41.974 [info]  coderd.agentrpc.yamux.stdlib: [ERR] yamux: Failed to read header: failed to get reader: failed to read frame header: EOF  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.acquirer: acquiring job canceled  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}  error="context canceled"
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.inmem-provisionerd-test: successful cancel
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.inmem-provisionerd-test: closed stream  error=<nil>
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaceagents/me/rpc  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.966772657Z"  took=7.8[356](https://github.com/coder/coder/actions/runs/9479363424/job/26117743021?pr=13536#step:5:357)67ms  status_code=101  latency_ms=7  request_id=77f95cfb-823d-4d01-a484-2e368568de78
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: graceful acquire done  job_id=""  error=<nil>
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: acquire job successfully canceled
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: exiting acquire; provisionerd is shutting down
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: acquire loop exited
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.provisionerd: gracefully shutdown
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.provisionerd: closing provisionerd
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: waiting for goroutines to exit
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: connect loop exited
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: closing server with error  error=<nil>
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.inmem-provisionerd-test: provisioner daemon disconnected ...
        error= InmemoryListener is already closed: use of closed network connection
               	storj.io/drpc/drpcserver.(*Server).Serve:109
               	github.com/coder/coder/v2/coderd.(*API).CreateInMemoryTaggedProvisionerDaemon.func3:1457
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.inmem-provisionerd-test: heartbeat loop canceled
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspaceapps.stats_collector: flushing workspace app stats
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspaceapps.stats_collector: flushed workspace app stats
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspaceapps.stats_collector: workspace app stats collector stopped
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord: got tunnel peers  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  tunnel_peers=[]
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord.multiagent: v1RespLoop done reading responses  client_id=475d835a-2ba1-439b-af3e-21e67d945f19  error=EOF
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord: peerReadLoop got request  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  peer_name=475d835a-2ba1-439b-af3e-21e67d945f19
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord: lostPeer  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.servertailnet: closing tailnet Conn
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.servertailnet: closing configMaps configLoop
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.servertailnet: closing nodeUpdater updateLoop
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.servertailnet: closed netstack
    t.go:99: 2024-06-12 08:37:41.975 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped
    t.go:99: 2024-06-12 08:37:41.975 [debu]  coderd.servertailnet.net.wgengine: portmapper: createOrGetMapping: read udp4 0.0.0.0:55721: use of closed network connection
    t.go:99: 2024-06-12 08:37:41.975 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest=false hair= portmap= v4a=127.0.0.1:56143 derp=0
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: magicsock: home is now derp-999 (coder)
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet: new preferred DERP  preferred_derp=999
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: magicsock: endpoints changed: 127.0.0.1:56143 (stun), 172.17.0.1:56143 (local), 192.168.100.243:56143 (local)
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet: wireguard status  status=<nil>  error="engine closing; no status"
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Close: not implemented.
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Device closing
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - stopped
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Device closed
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.workspace_usage_tracker: workspace usage tracker loop exited
    stuntest.go:63: STUN server shutdown=== FAIL: coderd TestWorkspaceAgent_Metadata_CatchMemoryLeak (0.06s)
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.acquirer: subscribed to job postings
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.metrics_cache: metrics refreshed  name="deployment stats"  interval=5m0s  took=21.945µs
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.servertailnet.net.wgengine: [v1] using fake (no-op) tun device
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.servertailnet.net.wgengine: [v1] using fake (no-op) OS network configurator
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.servertailnet.net.wgengine: [v1] using fake (no-op) DNS configurator
    t.go:99: 2024-06-12 08:37:41.949 [debu]  coderd.dbrollup: rolling up data
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: dns: using dns.noopManager
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: link state: interfaces.State{defaultRoute=eth0 ifs={docker0:[172.17.0.1/16] eth0:[192.168.100.243/24]} v4=true v6=false}
Warning: 99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: magicsock: [warning] failed to force-set UDP read buffer size to 7[340](https://github.com/coder/coder/actions/runs/9479363424/job/26117743021?pr=13536#step:5:341)032: operation not permitted; using kernel default values (impacts throughput only)
Warning: 99: 2024-06-12 08:37:41.950 [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)
Warning: 99: 2024-06-12 08:37:41.950 [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: 99: 2024-06-12 08:37:41.950 [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:99: 2024-06-12 08:37:41.950 [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:99: 2024-06-12 08:37:41.950 [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:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: magicsock: disco key = d:29556cbf6570c6cf
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Creating WireGuard device...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Bringing WireGuard device up...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] UDP bind has been updated
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Interface state was Down, requested Up, now Up
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Bringing router up...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Up: not implemented.
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Clearing router settings...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Starting network monitor...
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: Engine created.
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet: magicsock debug logging disabled, use CODER_MAGICSOCK_DEBUG_LOGGING=true to enable
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: magicsock: SetPrivateKey called (init)
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - started
    t.go:99: 2024-06-12 08:37:41.950 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - started
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.coord: initPeer  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  peer_name=475d835a-2ba1-439b-af3e-21e67d945f19
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.coord: initial tunnel peers  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  peer_name=475d835a-2ba1-439b-af3e-21e67d945f19  tunnel_peers=[]
    t.go:99: 2024-06-12 08:37:41.951 [info]  coderd.servertailnet: updating engine DERP map  derp_map="{\"Regions\":{\"1000\":{\"EmbeddedRelay\":false,\"RegionID\":1000,\"RegionCode\":\"coder_stun_1000\",\"RegionName\":\"Coder STUN 1000\",\"Nodes\":[{\"Name\":\"1000stun0\",\"RegionID\":1000,\"HostName\":\"127.0.0.1\",\"STUNPort\":56117,\"STUNOnly\":true}]},\"999\":{\"EmbeddedRelay\":true,\"RegionID\":999,\"RegionCode\":\"coder\",\"RegionName\":\"Coder Embedded Relay\",\"Nodes\":[{\"Name\":\"999b\",\"RegionID\":999,\"HostName\":\"\",\"IPv4\":\"127.0.0.1\",\"STUNPort\":-1,\"DERPPort\":45601,\"InsecureForTests\":true,\"ForceHTTP\":true}]}}}"
    t.go:99: 2024-06-12 08:37:41.951 [info]  coderd.servertailnet: updating engine network map  network_map="netmap: self: [DBcOr] auth=machine-unknown u=? [fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128]\n"
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: [v1] magicsock: got updated network map; 0 peers
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.netstack: [v2] netstack: registered IP fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: magicsock: endpoints changed: 172.17.0.1:56143 (local), 192.168.100.243:56143 (local)
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring userspace WireGuard config (with 0/0 peers)
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] UAPI: Updating private key
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring router
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Set: not implemented.
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: wgengine: Reconfig: configuring DNS
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: dns: Set: {DefaultResolvers:[] Routes:{} SearchDomains:[] Hosts:0}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: dns: Resolvercfg: {Routes:{} Hosts:0 LocalDomains:[]}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: dns: OScfg: {Nameservers:[] SearchDomains:[] MatchDomains:[] Hosts:[]}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.metrics_cache: metrics refreshed  name="template build times"  interval=1h0m0s  took=2.532257ms
    t.go:99: 2024-06-12 08:37:41.951 [debu]  coderd.servertailnet: wireguard status  status="&{AsOf:2024-06-12 08:37:41.951877339 +0000 UTC m=+10.634862584 Peers:[] LocalAddrs:[{Addr:172.17.0.1:56143 Type:local} {Addr:192.168.100.243:56143 Type:local}] DERPs:0}"  error=<nil>
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet: skipped sending node; no PreferredDERP  node="&{ID:nodeid:60b8c014fba00222 AsOf:2024-06-12 08:37:41.952313 +0000 UTC Key:nodekey:0c170eac2533505f730a03184f10b51e397fabfbb2a17c81c6253b46d932af6e DiscoKey:discokey:29556cbf6570c6cf29939bdb74c99eb7aec60a1a963b71a752e8112090306a6b PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] AllowedIPs:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] Endpoints:[]}"
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.workspaceapps.stats_collector: workspace app stats collector started
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet: skipped sending node; no PreferredDERP  node="&{ID:nodeid:60b8c014fba00222 AsOf:2024-06-12 08:37:41.952391 +0000 UTC Key:nodekey:0c170eac2533505f730a03184f10b51e397fabfbb2a17c81c6253b46d932af6e DiscoKey:discokey:29556cbf6570c6cf29939bdb74c99eb7aec60a1a963b71a752e8112090306a6b PreferredDERP:0 DERPLatency:map[] DERPForcedWebsocket:map[] Addresses:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] AllowedIPs:[fd7a:115c:a1e0:4dda:8184:d18a:edf0:35f0/128] Endpoints:[172.17.0.1:56143 192.168.100.243:56143]}"
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.dbrollup: rolled up data  took=2.557537ms  event={"template_usage_stats":true}
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.dbrollup: next rollup at  next="2024-06-12T08:40:00Z"
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:56143 (43825097223ee413b2f9ca36) in 134.757µs
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:56143 (f9ee983633d7402f374e8896) in 127.604µs
    t.go:99: 2024-06-12 08:37:41.952 [debu]  coderd.servertailnet.net.wgengine: netcheck: netcheck.runProbe: got STUN response for 1000stun0 from 127.0.0.1:56143 (ca8b2055f61aa573561e0805) in 143.695µs
    t.go:99: 2024-06-12 08:37:41.953 [debu]  coderd.provisionerd: dialing coderd
    t.go:99: 2024-06-12 08:37:41.954 [info]  coderd: starting in-memory provisioner daemon  name=test
    t.go:99: 2024-06-12 08:37:41.954 [info]  coderd.provisionerd: successfully connected to coderd
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.provisionerd: start of acquireAndRunOne
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.acquirer: acquiring job  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.acquirer: got clearance to call database  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}
    t.go:99: 2024-06-12 08:37:41.954 [debu]  coderd.acquirer: no job available  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}
    t.go:99: 2024-06-12 08:37:41.955 [debu]  coderd: entitlements will not be refreshed  request_id=2a52fff5-52c6-4473-a76e-d8fa7a5c987d
    t.go:99: 2024-06-12 08:37:41.956 [debu]  coderd.servertailnet.net.wgengine: [v1] wgengine: Reconfig done
    t.go:99: 2024-06-12 08:37:41.956 [info]  coderd.servertailnet: updating engine filter  filter="&{logf:0x1da8e60 local:0xc04dabc150 logIPs:0xc04dabc168 matches4:[{IPProto:[6 17 1 58 132] Srcs:[{ip:{addr:{hi:0 lo:281470681743360} z:0xc0001260a8} bitsPlusOne:1}] Dsts:[{Net:{ip:{addr:{hi:0 lo:281470681743360} z:0xc0001260a8} bitsPlusOne:1} Ports:{First:0 Last:65535}}] Caps:[]}] matches6:[{IPProto:[6 17 1 58 132] Srcs:[{ip:{addr:{hi:0 lo:0} z:0xc0001260c0} bitsPlusOne:1}] Dsts:[{Net:{ip:{addr:{hi:0 lo:0} z:0xc0001260c0} bitsPlusOne:1} Ports:{First:0 Last:65535}}] Caps:[]}] cap4:[] cap6:[] state:0xc046b460e0 shieldsUp:false}"
    t.go:99: 2024-06-12 08:37:41.956 [debu]  coderd: POST  host=localhost:45601  path=/api/v2/users/first  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.954247628Z"  took=2.041504ms  status_code=201  latency_ms=2  request_id=2a52fff5-52c6-4473-a76e-d8fa7a5c987d
    t.go:99: 2024-06-12 08:37:41.957 [debu]  coderd: POST  host=localhost:45601  path=/api/v2/users/login  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.956610274Z"  took=1.057802ms  status_code=201  latency_ms=1  request_id=0e57f1da-7b83-4c79-8f67-74540fd4d282
    t.go:99: 2024-06-12 08:37:41.966 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaces/c7997669-009a-4768-ad89-b63facce0533  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.958185928Z"  took=8.008113ms  status_code=200  latency_ms=8  request_id=17834be5-a552-407d-98b6-0e0257a20c5b
    t.go:99: 2024-06-12 08:37:41.968 [debu]  coderd.agentrpc: accepting agent RPC connection  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78  agent={"id":"d155ce7e-f32c-405b-856e-b4015b9bb167","created_at":"2024-06-12T08:37:41.958078Z","updated_at":"2024-06-12T08:37:41.958078Z","name":"","first_connected_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"last_connected_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"disconnected_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"resource_id":"0e42006a-69ec-4349-a288-8ef5f5b1ad26","auth_token":"72938252-22b4-4abb-93f8-d920fed77bd9","auth_instance_id":{"String":"","Valid":false},"architecture":"","environment_variables":{"RawMessage":null,"Valid":false},"operating_system":"","instance_metadata":{"RawMessage":null,"Valid":false},"resource_metadata":{"RawMessage":null,"Valid":false},"directory":"","version":"","last_connected_replica_id":null,"connection_timeout_seconds":0,"troubleshooting_url":"","motd_file":"","lifecycle_state":"created","expanded_directory":"","logs_length":0,"logs_overflowed":false,"started_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"ready_at":{"Time":"0001-01-01T00:00:00Z","Valid":false},"subsystems":null,"display_apps":null,"api_version":"","display_order":0}
    t.go:99: 2024-06-12 08:37:41.972 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaces/c7997669-009a-4768-ad89-b63facce0533  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.968788787Z"  took=3.585105ms  status_code=200  latency_ms=3  request_id=5b5f7c16-da47-4f8a-b73e-84c32d21100d
    t.go:99: 2024-06-12 08:37:41.972 [debu]  coderd.workspace_metadata_watcher: got initial metadata  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86  num=2
    t.go:99: 2024-06-12 08:37:41.972 [debu]  coderd.workspace_metadata_watcher: sending metadata  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86  num=2
    t.go:99: 2024-06-12 08:37:41.973 [debu]  coderd.agentrpc: accepted metadata report  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78  collected_at="2024-06-12T08:37:41.97[342](https://github.com/coder/coder/actions/runs/9479363424/job/26117743021?pr=13536#step:5:343)2Z"  key=foo1  value=hi
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspace_metadata_watcher: received metadata update  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86  payload={"collected_at":"2024-06-12T08:37:41.973422Z","keys":["foo1"]}
    t.go:102: 2024-06-12 08:37:41.974 [erro]  coderd.workspace_metadata_watcher: failed to get metadata  workspace_agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86 ...
        error= test error:
                   github.com/coder/coder/v2/coderd_test.TestWorkspaceAgent_Metadata_CatchMemoryLeak
                       /home/runner/actions-runner/_work/coder/coder/coderd/workspaceagents_test.go:1386
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaceagents/d155ce7e-f32c-405b-856e-b4015b9bb167/watch-metadata  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.972629426Z"  took=1.695663ms  status_code=200  latency_ms=1  request_id=d050f598-d6ec-4711-ad8b-d932575d3c86
    workspaceagents_test.go:1419: 
        	Error Trace:	/home/runner/actions-runner/_work/coder/coder/coderd/workspaceagents_test.go:1419
        	            				/home/runner/actions-runner/_work/coder/coder/testutil/go.go:18
        	            				/opt/hostedtoolcache/go/1.22.3/x64/src/runtime/asm_amd64.s:1695
        	Error:      	Received unexpected error:
        	            	session shutdown
        	Test:       	TestWorkspaceAgent_Metadata_CatchMemoryLeak
        	Messages:   	post metadata foo1
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd: agent connection monitor is closing connection  workspace_id=c7997669-009a-4768-ad89-b63facce0533  agent_id=d155ce7e-f32c-405b-856e-b4015b9bb167  request_id=77f95cfb-823d-4d01-a484-2e368568de78  reason=canceled
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.provisionerd: attempting graceful shutdown
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: sending acquire job cancel
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.agentrpc: drpc server error  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78 ...
        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:99: 2024-06-12 08:37:41.974 [info]  coderd.agentrpc.yamux.stdlib: [ERR] yamux: Failed to read header: failed to get reader: failed to read frame header: EOF  owner=testuser  workspace_name=happy_kirch8  agent_name=""  request_id=77f95cfb-823d-4d01-a484-2e368568de78
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.acquirer: acquiring job canceled  organization_id=d967ad02-942c-4c5a-967d-31a09968dc4e  worker_id=d6fa6c7a-9187-48f0-9b20-6ba495ad49b5  provisioner_types=[echo]  tags={"owner":"","scope":"organization"}  error="context canceled"
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.inmem-provisionerd-test: successful cancel
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.inmem-provisionerd-test: closed stream  error=<nil>
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd: GET  host=localhost:45601  path=/api/v2/workspaceagents/me/rpc  proto=HTTP/1.1  remote_addr=127.0.0.1  start="2024-06-12T08:37:41.966772657Z"  took=7.8[356](https://github.com/coder/coder/actions/runs/9479363424/job/26117743021?pr=13536#step:5:357)67ms  status_code=101  latency_ms=7  request_id=77f95cfb-823d-4d01-a484-2e368568de78
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: graceful acquire done  job_id=""  error=<nil>
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: acquire job successfully canceled
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: exiting acquire; provisionerd is shutting down
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: acquire loop exited
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.provisionerd: gracefully shutdown
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.provisionerd: closing provisionerd
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: waiting for goroutines to exit
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: connect loop exited
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.provisionerd: closing server with error  error=<nil>
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.inmem-provisionerd-test: provisioner daemon disconnected ...
        error= InmemoryListener is already closed: use of closed network connection
               	storj.io/drpc/drpcserver.(*Server).Serve:109
               	github.com/coder/coder/v2/coderd.(*API).CreateInMemoryTaggedProvisionerDaemon.func3:1457
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.inmem-provisionerd-test: heartbeat loop canceled
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspaceapps.stats_collector: flushing workspace app stats
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspaceapps.stats_collector: flushed workspace app stats
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.workspaceapps.stats_collector: workspace app stats collector stopped
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord: got tunnel peers  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  tunnel_peers=[]
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord.multiagent: v1RespLoop done reading responses  client_id=475d835a-2ba1-439b-af3e-21e67d945f19  error=EOF
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord: peerReadLoop got request  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19  peer_name=475d835a-2ba1-439b-af3e-21e67d945f19
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.coord: lostPeer  peer_id=475d835a-2ba1-439b-af3e-21e67d945f19
    t.go:99: 2024-06-12 08:37:41.974 [info]  coderd.servertailnet: closing tailnet Conn
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.servertailnet: closing configMaps configLoop
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.servertailnet: closing nodeUpdater updateLoop
    t.go:99: 2024-06-12 08:37:41.974 [debu]  coderd.servertailnet: closed netstack
    t.go:99: 2024-06-12 08:37:41.975 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped
    t.go:99: 2024-06-12 08:37:41.975 [debu]  coderd.servertailnet.net.wgengine: portmapper: createOrGetMapping: read udp4 0.0.0.0:55721: use of closed network connection
    t.go:99: 2024-06-12 08:37:41.975 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming mkReceiveFunc - stopped
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: netcheck: [v1] report: udp=true v6=false v6os=true mapvarydest=false hair= portmap= v4a=127.0.0.1:56143 derp=0
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: magicsock: home is now derp-999 (coder)
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet: new preferred DERP  preferred_derp=999
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: magicsock: endpoints changed: 127.0.0.1:56143 (stun), 172.17.0.1:56143 (local), 192.168.100.243:56143 (local)
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet: wireguard status  status=<nil>  error="engine closing; no status"
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: [v1] warning: fakeRouter.Close: not implemented.
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Device closing
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Routine: receive incoming receiveDERP - stopped
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.servertailnet.net.wgengine: wg: [v2] Device closed
    t.go:99: 2024-06-12 08:37:42.003 [debu]  coderd.workspace_usage_tracker: workspace usage tracker loop exited
    stuntest.go:63: STUN server shutdown