Overview

In PRs that don't touch the data layer (for example A FE-only PR#1623), we're seeing thattest/go/postgres often fails.

Truncated Log

The full log is too long, please see the actual action run.

=== Failed
=== FAIL: cli TestTTL/ShowOK (2.00s)
t.go:56: 2022-05-20 15:25:54.871 [DEBUG]coderd.go:372POST /api/v2/users/first
t.go:56: 2022-05-20 15:25:54.904 [DEBUG]coderd.go:372POST /api/v2/users/login
t.go:56: 2022-05-20 15:25:54.919 [DEBUG]coderd.go:372POST /api/v2/files
t.go:56: 2022-05-20 15:25:54.932 [DEBUG]coderd.go:372POST /api/v2/organizations/d0d2209f-c686-4baf-b53f-956c0454ca64/templateversions
t.go:56: 2022-05-20 15:25:54.989 [DEBUG](provisionerd)provisionerd.go:128connected
t.go:56: 2022-05-20 15:25:55.012 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.036 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.048 [DEBUG](provisionerd-cranky_gauss6)provisionerdaemons.go:142locked job from database{"id": "5e425b34-7615-473a-bb7c-378590f051b6"}
t.go:56: 2022-05-20 15:25:55.054 [INFO](provisionerd)provisionerd.go:239acquired job{"initiator_username": "testuser", "provisioner": "echo", "id": "5e425b34-7615-473a-bb7c-378590f051b6"}
t.go:56: 2022-05-20 15:25:55.062 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.073 [INFO](provisionerd)provisionerd.go:353unpacking template source archive{"size_bytes": 3072}
t.go:56: 2022-05-20 15:25:55.075 [DEBUG](provisionerd)provisionerd.go:403extracted file{"size_bytes": 2, "path": "/tmp/TestTTLShowOK2129889090/001/0.parse.protobuf", "mode": "-rw-------"}
t.go:56: 2022-05-20 15:25:55.079 [DEBUG](provisionerd)provisionerd.go:403extracted file{"size_bytes": 2, "path": "/tmp/TestTTLShowOK2129889090/001/0.provision.protobuf", "mode": "-rw-------"}
t.go:56: 2022-05-20 15:25:55.080 [DEBUG](provisionerd)provisionerd.go:403extracted file{"size_bytes": 2, "path": "/tmp/TestTTLShowOK2129889090/001/0.provision.dry.protobuf", "mode": "-rw-------"}
t.go:56: 2022-05-20 15:25:55.082 [DEBUG](provisionerd)provisionerd.go:413acquired job is template import
t.go:56: 2022-05-20 15:25:55.086 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.091 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.111 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.134 [INFO](provisionerd)provisionerd.go:640parse complete{"parameter_schemas": null}
t.go:56: 2022-05-20 15:25:55.140 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.142 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.166 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.187 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.195 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.206 [INFO](provisionerd)provisionerd.go:722parse dry-run provision successful{"resource_count": 0, "resources": null, "state_length": 0}
t.go:56: 2022-05-20 15:25:55.213 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.243 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.244 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.242 [INFO](provisionerd)provisionerd.go:722parse dry-run provision successful{"resource_count": 0, "resources": null, "state_length": 0}
t.go:56: 2022-05-20 15:25:55.269 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.290 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.290 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.332 [DEBUG]coderd.go:372GET /api/v2/templateversions/8f5d7b3c-10e8-4f14-a801-81c689ab668c
t.go:56: 2022-05-20 15:25:55.342 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.339 [DEBUG](provisionerd-cranky_gauss6)provisionerdaemons.go:527marked import job as completed{"job_id": "5e425b34-7615-473a-bb7c-378590f051b6"}
t.go:56: 2022-05-20 15:25:55.350 [DEBUG]coderd.go:372POST /api/v2/organizations/d0d2209f-c686-4baf-b53f-956c0454ca64/templates
t.go:56: 2022-05-20 15:25:55.375 [INFO](provisionerd)provisionerd.go:451completed job{"id": "5e425b34-7615-473a-bb7c-378590f051b6"}
t.go:56: 2022-05-20 15:25:55.375 [DEBUG](provisionerd)provisionerd.go:315cleaned up work directory{"error": null}
t.go:56: 2022-05-20 15:25:55.382 [DEBUG]provisionerdaemons.go:88drpc server error ...
"error": stream closed
storj.io/drpc/drpcstream.(*Stream).sendPacket:268
storj.io/drpc/drpcstream.(*Stream).CloseSend:501
storj.io/drpc/drpcserver.(*Server).handleRPC:126
storj.io/drpc/drpcserver.(*Server).ServeOne:66
storj.io/drpc/drpcserver.(*Server).Serve.func2:112
storj.io/drpc/drpcctx.(*Tracker).track:52
t.go:56: 2022-05-20 15:25:55.411 [DEBUG]coderd.go:372POST /api/v2/organizations/d0d2209f-c686-4baf-b53f-956c0454ca64/workspaces
t.go:56: 2022-05-20 15:25:55.455 [DEBUG]coderd.go:372PUT /api/v2/workspaces/418ac39d-f91c-4dfa-a594-ed4453eb81e7/ttl
t.go:56: 2022-05-20 15:25:55.510 [DEBUG](provisionerd-cranky_gauss6)provisionerdaemons.go:142locked job from database{"id": "4436132f-47b5-4bc8-8856-de2465dd049a"}
t.go:56: 2022-05-20 15:25:55.530 [DEBUG]coderd.go:372GET /api/v2/users/me/organizations
t.go:56: 2022-05-20 15:25:55.566 [DEBUG]coderd.go:372GET /api/v2/organizations/d0d2209f-c686-4baf-b53f-956c0454ca64/workspaces/me/nostalgic-bassi
t.go:56: 2022-05-20 15:25:55.595 [INFO](provisionerd)provisionerd.go:239acquired job{"initiator_username": "testuser", "provisioner": "echo", "id": "4436132f-47b5-4bc8-8856-de2465dd049a"}
t.go:56: 2022-05-20 15:25:55.599 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.625 [INFO](provisionerd)provisionerd.go:353unpacking template source archive{"size_bytes": 3072}
t.go:56: 2022-05-20 15:25:55.628 [DEBUG](provisionerd)provisionerd.go:403extracted file{"size_bytes": 2, "path": "/tmp/TestTTLShowOK2129889090/001/0.parse.protobuf", "mode": "-rw-------"}
t.go:56: 2022-05-20 15:25:55.629 [DEBUG](provisionerd)provisionerd.go:403extracted file{"size_bytes": 2, "path": "/tmp/TestTTLShowOK2129889090/001/0.provision.protobuf", "mode": "-rw-------"}
t.go:56: 2022-05-20 15:25:55.630 [INFO](provisionerd)provisionerd.go:910failing running job{"error_message": "provisioner daemon was shutdown gracefully", "job_id": "4436132f-47b5-4bc8-8856-de2465dd049a"}
t.go:56: 2022-05-20 15:25:55.632 [DEBUG](provisionerd)provisionerd.go:403extracted file{"size_bytes": 2, "path": "/tmp/TestTTLShowOK2129889090/001/0.provision.dry.protobuf", "mode": "-rw-------"}
t.go:56: 2022-05-20 15:25:55.633 [DEBUG](provisionerd)provisionerd.go:418acquired job is workspace provision{"workspace_name": "nostalgic-bassi", "state_length": 0, "parameters": null}
t.go:56: 2022-05-20 15:25:55.691 [DEBUG](provisionerd)provisionerd.go:931marked running job as failed
t.go:56: 2022-05-20 15:25:55.694 [DEBUG](provisionerd)provisionerd.go:206skipping acquire; job is already running
t.go:56: 2022-05-20 15:25:55.695 [DEBUG](provisionerd)provisionerd.go:905job has already been marked as failed{"error_messsage": "write log: context canceled"}
t.go:56: 2022-05-20 15:25:55.698 [DEBUG](provisionerd)provisionerd.go:905job has already been marked as failed{"error_messsage": "write log: context canceled"}
t.go:56: 2022-05-20 15:25:55.704 [DEBUG](provisionerd)provisionerd.go:315cleaned up work directory{"error": null}
t.go:56: 2022-05-20 15:25:55.712 [DEBUG](provisionerd)provisionerd.go:1000closing server with error{"error": null}
testing.go:1312: race detected during execution of test
--- FAIL: TestTTL/ShowOK (2.00s)

Full Action Attempt

https://github.com/coder/coder/actions/runs/2359166491/attempts/1

Impact

This check is required (as it should be). We don't want to get into bad habits of either ignoring a failing CI check, or having it constantly fail and hold up PRs (especially those that don't touch the data layer). Lastly, we want to be certain it's catching true positives in the data layer.