Skip to content

Test | TestProvisionerd race causing failure #424

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
greyscaled opened this issue Mar 13, 2022 · 3 comments · Fixed by #2883
Closed

Test | TestProvisionerd race causing failure #424

greyscaled opened this issue Mar 13, 2022 · 3 comments · Fixed by #2883
Labels
api Area: HTTP API
Milestone
V2 Alpha

Comments

@greyscaled
Copy link
Contributor

greyscaled commented Mar 13, 2022 •
edited
Loading

Overview

=== FAIL: provisionerd TestProvisionerd/WorkspaceBuild was observed in a very unrelated (no Go files) change on https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:88 (in #423).

Details

This was selectively seen on `test/go (ubuntu-latest).

Full log

=== FAIL: provisionerd TestProvisionerd/WorkspaceBuild (0.21s)
    t.go:56: 2022-03-13 21:32:55.328 [DEBUG]	(provisionerd)	<provisionerd.go:125>	connected
    t.go:56: 2022-03-13 21:32:55.380 [INFO]	(provisionerd)	<provisionerd.go:214>	acquired job	{"initiator_username": "", "provisioner": "someprovisioner", "id": "test"}
    t.go:56: 2022-03-13 21:32:55.381 [INFO]	(provisionerd)	<provisionerd.go:274>	unpacking project source archive	{"size_bytes": 1024}
    t.go:56: 2022-03-13 21:32:55.381 [DEBUG]	(provisionerd)	<provisionerd.go:324>	extracted file	{"size_bytes": 7, "path": "/tmp/TestProvisionerdWorkspaceBuild3027597200/001/test.txt", "mode": "-rw-------"}
    t.go:56: 2022-03-13 21:32:55.381 [DEBUG]	(provisionerd)	<provisionerd.go:338>	acquired job is workspace provision	{"workspace_name": "", "state_length": 0, "parameters": null}
    t.go:56: 2022-03-13 21:32:55.383 [DEBUG]	(provisionerd)	<provisionerd.go:537>	workspace provision job logged	{"level": "DEBUG", "output": "wow", "workspace_build_id": ""}
    t.go:56: 2022-03-13 21:32:55.384 [INFO]	(provisionerd)	<provisionerd.go:573>	provision successful; marking job as complete	{"resource_count": 0, "resources": null, "state_length": 0}
    t.go:56: 2022-03-13 21:32:55.385 [INFO]	(provisionerd)	<provisionerd.go:353>	completed job	{"id": "test"}
    t.go:56: 2022-03-13 21:32:55.385 [DEBUG]	(provisionerd)	<provisionerd.go:255>	cleaned up work directory	{"error": null}
    t.go:56: 2022-03-13 21:32:55.432 [DEBUG]	(provisionerd)	<provisionerd.go:206>	no jobs available
    t.go:56: 2022-03-13 21:32:55.432 [DEBUG]	(provisionerd)	<provisionerd.go:708>	closing server with error	{"error": null}
==================
WARNING: DATA RACE
Write at 0x00c000233003 by goroutine 103:
  storj.io/drpc/drpcwire.AppendVarint()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcwire/varint.go:32 +0x3ee
  storj.io/drpc/drpcwire.AppendFrame()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcwire/packet.go:141 +0x304
  storj.io/drpc/drpcwire.(*Writer).WriteFrame()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcwire/writer.go:70 +0x110
  storj.io/drpc/drpcstream.(*Stream).sendPacket()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcstream/stream.go:260 +0x20e
  storj.io/drpc/drpcstream.(*Stream).SendError()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcstream/stream.go:453 +0x1ed
  storj.io/drpc/drpcserver.(*Server).handleRPC()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:124 +0x86
  storj.io/drpc/drpcserver.(*Server).ServeOne()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:66 +0x2da
  storj.io/drpc/drpcserver.(*Server).Serve.func2()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:112 +0x76
  storj.io/drpc/drpcctx.(*Tracker).track()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcctx/transport.go:52 +0x3d
  storj.io/drpc/drpcctx.(*Tracker).Run·dwrap·1()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcctx/transport.go:47 +0x47

Previous read at 0x00c000233003 by goroutine 26:
  runtime.slicecopy()
      /opt/hostedtoolcache/go/1.17.7/x64/src/runtime/slice.go:284 +0x0
  io.(*pipe).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/pipe.go:59 +0x1[93](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:93)
  io.(*PipeReader).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/pipe.go:134 +0x64
  github.com/coder/coder/provisionersdk.(*readWriteCloser).Read()
      <autogenerated>:1 +0x7b
  bufio.(*Reader).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/bufio/bufio.go:227 +0x4da
  io.(*LimitedReader).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/io.go:473 +0xc5
  bytes.(*Buffer).ReadFrom()
      /opt/hostedtoolcache/go/1.17.7/x64/src/bytes/buffer.go:204 +0x112
  io.copyBuffer()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/io.go:409 +0x1c2
  io.Copy()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/io.go:382 +0x348
  github.com/hashicorp/yamux.(*Stream).readData()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/stream.go:476 +0x305
  github.com/hashicorp/yamux.(*Session).handleStreamMessage()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:550 +0x3e4
  github.com/hashicorp/yamux.(*Session).recvLoop()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:501 +0x1ef
  github.com/hashicorp/yamux.(*Session).recv()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:462 +0x2e
  github.com/hashicorp/yamux.newSession·dwrap·1()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:113 +0x39

Goroutine 103 (running) created at:
  storj.io/drpc/drpcctx.(*Tracker).Run()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcctx/transport.go:47 +0xf0
  storj.io/drpc/drpcserver.(*Server).Serve()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:111 +0x411
  github.com/coder/coder/provisionerd_test.createProvisionerDaemonClient.func2()
      /home/runner/work/coder/coder/provisionerd/provisionerd_test.go:537 +0x64

Goroutine 26 (finished) created at:
  github.com/hashicorp/yamux.newSession()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:113 +0x864
  github.com/hashicorp/yamux.Client()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/mux.go:113 +0x207
  github.com/coder/coder/provisionersdk.TransportPipe()
      /home/runner/work/coder/coder/provisionersdk/transport.go:18 +0x6b5
  github.com/coder/coder/provisionerd_test.createProvisionerDaemonClient()
      /home/runner/work/coder/coder/provisionerd/provisionerd_test.go:525 +0xc9
  github.com/coder/coder/provisionerd_test.TestProvisionerd.func9.1()
      /home/runner/work/coder/coder/provisionerd/provisionerd_test.go:306 +0x238
  github.com/coder/coder/provisionerd.(*Server).connect()
      /home/runner/work/coder/coder/provisionerd/provisionerd.go:111 +0x231
  github.com/coder/coder/provisionerd.New·dwrap·1()
      /home/runner/work/coder/coder/provisionerd/provisionerd.go:78 +0x58
==================
==================
WARNING: DATA RACE
Write at 0x00c000405[97](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:97)8 by goroutine 103:
  encoding/binary.bigEndian.PutUint32()
      /opt/hostedtoolcache/go/1.17.7/x64/src/encoding/binary/binary.go:118 +0x107
  github.com/hashicorp/yamux.header.encode()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-2021[102](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:102)8200310-0bc27b27de87/const.go:180 +0xdd
  github.com/hashicorp/yamux.(*Stream).write()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/stream.go:201 +0x3cd
  github.com/hashicorp/yamux.(*Stream).Write()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/stream.go:158 +0x18c
  storj.io/drpc/drpcwire.(*Writer).Flush()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcwire/writer.go:85 +0xb9
  storj.io/drpc/drpcstream.(*Stream).sendPacket()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcstream/stream.go:263 +0x231
  storj.io/drpc/drpcstream.(*Stream).SendError()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcstream/stream.go:453 +0x1ed
  storj.io/drpc/drpcserver.(*Server).handleRPC()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:124 +0x86
  storj.io/drpc/drpcserver.(*Server).ServeOne()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:66 +0x2da
  storj.io/drpc/drpcserver.(*Server).Serve.func2()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:112 +0x76
  storj.io/drpc/drpcctx.(*Tracker).track()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcctx/transport.go:52 +0x3d
  storj.io/drpc/drpcctx.(*Tracker).Run·dwrap·1()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcctx/transport.go:47 +0x47

Previous read at 0x00c000405978 by goroutine 26:
  runtime.slicecopy()
      /opt/hostedtoolcache/go/1.17.7/x64/src/runtime/slice.go:284 +0x0
  io.(*pipe).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/pipe.go:59 +0x193
  io.(*PipeReader).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/pipe.go:134 +0x64
  github.com/coder/coder/provisionersdk.(*readWriteCloser).Read()
      <autogenerated>:1 +0x7b
  bufio.(*Reader).Read()
      /opt/hostedtoolcache/go/1.17.7/x64/src/bufio/bufio.go:227 +0x4da
  io.ReadAtLeast()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/io.go:328 +0xdd
  io.ReadFull()
      /opt/hostedtoolcache/go/1.17.7/x64/src/io/io.go:347 +0x135
  github.com/hashicorp/yamux.(*Session).recvLoop()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:483 +0xfa
  github.com/hashicorp/yamux.(*Session).recv()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:462 +0x2e
  github.com/hashicorp/yamux.newSession·dwrap·1()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/session.go:113 +0x39

Goroutine [103](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:103) (running) created at:
  storj.io/drpc/drpcctx.(*Tracker).Run()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcctx/transport.go:47 +0xf0
  storj.io/drpc/drpcserver.(*Server).Serve()
      /home/runner/go/pkg/mod/storj.io/drpc@v0.0.29/drpcserver/server.go:111 +0x411
  github.com/coder/coder/provisionerd_test.createProvisionerDaemonClient.func2()
      /home/runner/work/coder/coder/provisionerd/provisionerd_test.go:537 +0x64

Goroutine 26 (finished) created at:
  github.com/hashicorp/yamux.newSession()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-202[110](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:110)28200310-0bc27b27de87/session.go:113 +0x864
  github.com/hashicorp/yamux.Client()
      /home/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/mux.go:113 +0x207
  github.com/coder/coder/provisionersdk.TransportPipe()
      /home/runner/work/coder/coder/provisionersdk/transport.go:18 +0x6b5
  github.com/coder/coder/provisionerd_test.createProvisionerDaemonClient()
      /home/runner/work/coder/coder/provisionerd/provisionerd_test.go:525 +0xc9
  github.com/coder/coder/provisionerd_test.TestProvisionerd.func9.1()
      /home/runner/work/coder/coder/provisionerd/provisionerd_test.go:306 +0x238
  github.com/coder/coder/provisionerd.(*Server).connect()
      /home/runner/work/coder/coder/provisionerd/provisionerd.go:[111](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:111) +0x231
  github.com/coder/coder/provisionerd.New·dwrap·1()
      /home/runner/work/coder/coder/provisionerd/provisionerd.go:78 +0x58
==================
    testing.go:[115](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:115)2: race detected during execution of test
    --- FAIL: TestProvisionerd/WorkspaceBuild (0.21s)

=== FAIL: provisionerd TestProvisionerd/RunningPeriodicUpdate (0.21s)
    t.go:56: 2022-03-13 21:32:55.469 [DEBUG]	(provisionerd)	<provisionerd.go:[125](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:125)>	connected
    t.go:56: 2022-03-13 21:32:55.521 [INFO]	(provisionerd)	<provisionerd.go:214>	acquired job	{"initiator_username": "", "provisioner": "someprovisioner", "id": "test"}
    t.go:56: 2022-03-13 21:32:55.522 [INFO]	(provisionerd)	<provisionerd.go:274>	unpacking project source archive	{"size_bytes": 1024}
    t.go:56: 2022-03-13 21:32:55.522 [DEBUG]	(provisionerd)	<provisionerd.go:324>	extracted file	{"size_bytes": 7, "path": "/tmp/TestProvisionerdRunningPeriodicUpdate2[126](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:126)973643/001/test.txt", "mode": "-rw-------"}
    t.go:56: 2022-03-13 21:32:55.522 [DEBUG]	(provisionerd)	<provisionerd.go:334>	acquired job is project import
    t.go:56: 2022-03-13 21:32:55.571 [DEBUG]	(provisionerd)	<provisionerd.go:186>	skipping acquire; job is already running
    t.go:56: 2022-03-13 21:32:55.576 [INFO]	(provisionerd)	<provisionerd.go:626>	failing running job	{"error_message": "provisioner daemon was shutdown gracefully", "job_id": "test"}
    t.go:56: 2022-03-13 21:32:55.578 [DEBUG]	(provisionerd)	<provisionerd.go:636>	marked running job as failed
    t.go:56: 2022-03-13 21:32:55.578 [WARN]	(provisionerd)	<provisionerd.go:621>	job has already been marked as failed	{"error_messsage": "run parse: recv parse source: context canceled"}
    t.go:56: 2022-03-13 21:32:55.578 [INFO]	(provisionerd)	<provisionerd.go:353>	completed job	{"id": "test"}
    t.go:56: 2022-03-13 21:32:55.578 [DEBUG]	(provisionerd)	<provisionerd.go:255>	cleaned up work directory	{"error": null}
    t.go:56: 2022-03-13 21:32:55.578 [DEBUG]	(provisionerd)	<provisionerd.go:708>	closing server with error	{"error": null}
    testing.go:1[152](https://github.com/coder/coder/runs/5529928585?check_suite_focus=true#step:7:152): race detected during execution of test
    --- FAIL: TestProvisionerd/RunningPeriodicUpdate (0.21s)

=== FAIL: provisionerd TestProvisionerd (0.00s)
@kylecarbs
Copy link
Member

I've seen this a few times, but need time to investigate 🕵.

@bryphe-coder bryphe-coder self-assigned this Mar 14, 2022
@greyscaled greyscaled mentioned this issue Mar 14, 2022
Closed
@bryphe-coder
Copy link
Contributor

Observed a somewhat similar data race here, too: https://github.com/coder/coder/runs/5541954475?check_suite_focus=true#step:7:55

With these as the originating goroutines for the race:

Goroutine 48 (running) created at:
  github.com/hashicorp/yamux.newSession()
      /Users/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-202[110](https://github.com/coder/coder/runs/5541954475?check_suite_focus=true#step:7:110)28200310-0bc27b27de87/session.go:113 +0x864
  github.com/hashicorp/yamux.Server()
      /Users/runner/go/pkg/mod/github.com/hashicorp/yamux@v0.0.0-20211028200310-0bc27b27de87/mux.go:100 +0x204
  github.com/coder/coder/provisionersdk.TransportPipe()
      /Users/runner/work/coder/coder/provisionersdk/transport.go:26 +0x775
  github.com/coder/coder/provisionerd_test.createProvisionerDaemonClient()
      /Users/runner/work/coder/coder/provisionerd/provisionerd_test.go:525 +0xc9
  github.com/coder/coder/provisionerd_test.TestProvisionerd.func9.1()
      /Users/runner/work/coder/coder/provisionerd/provisionerd_test.go:306 +0x238
  github.com/coder/coder/provisionerd.(*Server).connect()
      /Users/runner/work/coder/coder/provisionerd/provisionerd.go:[111](https://github.com/coder/coder/runs/5541954475?check_suite_focus=true#step:7:111) +0x231
  github.com/coder/coder/provisionerd.New·dwrap·1()
      /Users/runner/work/coder/coder/provisionerd/provisionerd.go:78 +0x58

Goroutine 100 (running) created at:
  github.com/coder/coder/provisionerd.(*Server).runJob()
      /Users/runner/work/coder/coder/provisionerd/provisionerd.go:224 +0x184
  github.com/coder/coder/provisionerd.(*Server).acquireJob·dwrap·4()
      /Users/runner/work/coder/coder/provisionerd/provisionerd.go:220 +0x64

This was referenced Mar 14, 2022
Merged
Merged
@misskniss
Copy link

@vapurrmaid I am closing this after a discussion in grooming. Feel free to reopen this if we see it again.

@misskniss misskniss added this to the V2 Alpha milestone May 3, 2022
@mafredri mafredri mentioned this issue Jul 11, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
api Area: HTTP API
Projects
None yet
Milestone
V2 Alpha
Development

Successfully merging a pull request may close this issue.

fix: Replace github.com/hashicorp/yamux with our fork coder/coder
4 participants
@misskniss @kylecarbs @greyscaled @bryphe-coder