Skip to content

fix: Race when writing to a closed pipe #1916

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.

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

Merged
merged 1 commit into from
Jun 1, 2022
Merged

fix: Race when writing to a closed pipe #1916

merged 1 commit into from
Jun 1, 2022

Conversation

kylecarbs
Copy link
Member

This is such an intermittent race it's difficult to track,
but regardless this is an improvement to the code.

==================
WARNING: DATA RACE
Write at 0x00c000502397 by goroutine 179:
  encoding/binary.bigEndian.PutUint16()
      /usr/local/goboring/src/encoding/binary/binary.go:108 +0x44c
  github.com/hashicorp/yamux.header.encode()
      /home/coder/projects/coder/coder/vendor/github.com/hashicorp/yamux/const.go:179 +0x3f1
  github.com/hashicorp/yamux.(*Stream).write()
      /home/coder/projects/coder/coder/vendor/github.com/hashicorp/yamux/stream.go:201 +0x349
  github.com/hashicorp/yamux.(*Stream).Write()
      /home/coder/projects/coder/coder/vendor/github.com/hashicorp/yamux/stream.go:158 +0x185
  storj.io/drpc/drpcwire.(*Writer).Flush()
      /home/coder/projects/coder/coder/vendor/storj.io/drpc/drpcwire/writer.go:85 +0xb9
  storj.io/drpc/drpcstream.(*Stream).sendPacket()
      /home/coder/projects/coder/coder/vendor/storj.io/drpc/drpcstream/stream.go:267 +0x227
  storj.io/drpc/drpcstream.(*Stream).Close()
      /home/coder/projects/coder/coder/vendor/storj.io/drpc/drpcstream/stream.go:478 +0x184
  github.com/coder/coder/peerbroker/proto.(*drpcPeerBroker_NegotiateConnectionClient).Close()
      <autogenerated>:1 +0x49
  github.com/coder/coder/peerbroker.Dial.func1.1()
      /home/coder/projects/coder/coder/peerbroker/dial.go:23 +0x48
  runtime.deferreturn()
      /usr/local/goboring/src/runtime/panic.go:436 +0x32

Previous read at 0x00c000502397 by goroutine 153:
  runtime.slicecopy()
      /usr/local/goboring/src/runtime/slice.go:295 +0x0
  io.(*pipe).read()
      /usr/local/goboring/src/io/pipe.go:59 +0x193
  io.(*PipeReader).Read()
      /usr/local/goboring/src/io/pipe.go:136 +0x64
  github.com/coder/coder/provisionersdk.(*readWriteCloser).Read()
      <autogenerated>:1 +0x76
  bufio.(*Reader).Read()
      /usr/local/goboring/src/bufio/bufio.go:236 +0x4da
  io.ReadAtLeast()
      /usr/local/goboring/src/io/io.go:331 +0xdd
  io.ReadFull()
      /usr/local/goboring/src/io/io.go:350 +0x12f
  github.com/hashicorp/yamux.(*Session).recvLoop()
      /home/coder/projects/coder/coder/vendor/github.com/hashicorp/yamux/session.go:483 +0xf1
  github.com/hashicorp/yamux.(*Session).recv()
      /home/coder/projects/coder/coder/vendor/github.com/hashicorp/yamux/session.go:462 +0x2e
  github.com/hashicorp/yamux.newSession.func1()
      /home/coder/projects/coder/coder/vendor/github.com/hashicorp/yamux/session.go:113 +0x39

@kylecarbs kylecarbs self-assigned this May 31, 2022
@kylecarbs kylecarbs requested a review from mafredri May 31, 2022 14:39
@kylecarbs kylecarbs force-pushed the readclose branch 3 times, most recently from cec2de3 to 8e61cac Compare May 31, 2022 15:03
@mafredri
Copy link
Member

To me it seems like this could actually be a bug in yamux.

From https://pkg.go.dev/io#Pipe:

It is safe to call Read and Write in parallel with each other or with Close. Parallel calls to Read and parallel calls to Write are also safe: the individual calls will be gated sequentially.

It doesn't sound like we need to guard Read/Write/Close.

And looking at the stack trace, it seems yamux session is doing slice mutations both at write and closeTimeout. The former is not protected by a mutex. The first stack trace hints at this but not the second, so that has me a bit confused atm.

https://github.com/hashicorp/yamux/blob/0bc27b27de87381b58e35462a8dcbd69040279c1/stream.go#L201

https://github.com/hashicorp/yamux/blob/0bc27b27de87381b58e35462a8dcbd69040279c1/stream.go#L365

There's one more use of sendHdr which might not be protected:

https://github.com/hashicorp/yamux/blob/0bc27b27de87381b58e35462a8dcbd69040279c1/session.go#L642

And .encode() mutates the slice itself: https://github.com/hashicorp/yamux/blob/0bc27b27de87381b58e35462a8dcbd69040279c1/const.go#L176-L182

@kylecarbs
Copy link
Member Author

Yup, I've come to the same conclusion! Thanks for the investigation @mafredri 🥳

@mafredri
Copy link
Member

No prob! And looks like I was wrong about write not being protected, it seems to be locked here: https://github.com/hashicorp/yamux/blob/0bc27b27de87381b58e35462a8dcbd69040279c1/stream.go#L154-L155, so that leaves the third use from session.

@kylecarbs
Copy link
Member Author

@mafredri if I change https://github.com/storj/drpc/blob/main/drpcwire/writer.go#L85 to copy the buffer with buf[:], it works!

This is such an intermittent race it's difficult to track,
but regardless this is an improvement to the code.
@kylecarbs
Copy link
Member Author

@mafredri I changed this to use net.Pipe (which is a cleaner impl), and I haven't been able to reproduce the race since 🤔🤔🤔

@kylecarbs
Copy link
Member Author

I ran this a lot without the failure..... seems to work!

Copy link
Member

@mafredri mafredri left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Awesome refactor, net.Pipe made this beautiful!

I think if you can't repro, this is good to 🚀.

Meanwhile, I did make a PR about that one discovery: hashicorp/yamux#100

@kylecarbs kylecarbs merged commit 1fa50a9 into main Jun 1, 2022
@kylecarbs kylecarbs deleted the readclose branch June 1, 2022 12:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants