Skip to content
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

bytes: panic from Read in (*Buffer).ReadFrom fills with 512 zero bytes #25435

Closed
forfuncsake opened this issue May 17, 2018 · 19 comments
Closed
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@forfuncsake
Copy link
Contributor

Please answer these questions before submitting your issue. Thanks!

What did you do?

I discovered this bug when testing an ssh client on go1.10. The client used a context.WithTimeout() to hang up and return after a defined timeout period. When checking the value of the *Buffer passed in to session.Stderr, I was presented with a 512-length slice of zero-value bytes any time the context timed out.

This bug only presents in go 1.10 and above.

I managed to recreate the issue directly with Buffer.ReadFrom(), the call to b.grow() causes the buffer to use a new slice of bytes with a length of 512 (MinRead), which is subsequently re-managed by the Reader.

Until the Reader completes its Read, the previously empty buffer remains "full":

https://play.golang.org/p/W-VEKbdsOfF

What did you expect to see?

An empty Buffer

What did you see instead?

A buffer filled with 512 zero-value bytes

System details

go version go1.10.2 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/forfuncsake/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/forfuncsake/go"
GORACE=""
GOROOT="/Users/forfuncsake/sdk/go1.10.2"
GOTMPDIR=""
GOTOOLDIR="/Users/forfuncsake/sdk/go1.10.2/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/7g/1681qtj95_31k480ygpsk_88xw4s06/T/go-build089491914=/tmp/go-build -gno-record-gcc-switches -fno-common"
GOROOT/bin/go version: go version go1.10.2 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.10.2
uname -v: Darwin Kernel Version 17.5.0: Fri Apr 13 19:32:32 PDT 2018; root:xnu-4570.51.2~1/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.13.4
BuildVersion:	17E202
lldb --version: lldb-902.0.79.2
  Swift-4.1
@gopherbot
Copy link

Change https://golang.org/cl/113495 mentions this issue: bytes: re-slice buffer to its previous length after call to grow()

@ghost
Copy link

ghost commented May 17, 2018

You have a data race in your example.

@forfuncsake
Copy link
Contributor Author

While true, the race doesn't have any impact on the proof (it's after the proof, in the final Println).
Regardless, here's a version with the race removed. Thanks for pointing it out.

https://play.golang.org/p/WVBBht422jH

@go101
Copy link

go101 commented May 17, 2018

A version without channels: https://play.golang.org/p/juW8Q47XRLA
Maybe it is not a bug, but the behavior should be mentioned in docs.

The fix #25436 should be valid.

@as
Copy link
Contributor

as commented May 17, 2018

A fix can only be valid if something is broken.

https://play.golang.org/p/Fmmki6ZLI_K

p = p[:0] has no-effect on the buffer. It's reslicing the slice descriptor for the local variable passed into Read. The real slice in buf is unaffected by this.

A bytes buffer is not safe for concurrent use. Accessing it within Read is probably a sign that a data race caused the originally-reported issue.

  • The original example only worked because the race happened in the first place.
  • The second example works because a co-routineish synchonization pattern is achieved to carefully instrument the logical equivalent of calling fmt.Println in the read function.
  • The third example from @go101 calls the buffer's methods in the function without the above instrumentation

That being said, the documentation clearly states that the buffer may resize itself as needed.

@ianlancetaylor
Copy link
Contributor

I don't understand why this is a bug. Don't examine a bytes.Buffer while you are executing a Read call on it. We don't provide any guarantees about concurrent calls to bytes.Buffer methods, even if you have arranged your Read method to avoid any data races.

@forfuncsake
Copy link
Contributor Author

I believe it's a bug because there was a change in behaviour between go1.9 and go1.10.

@as - The example provided is a contrived proof. Yes, the no-op re-slice in the example Read() is inconsequential to the Buffer.buf slice, and the re-slice in ReadFrom (after Read()) is the key to the final state of the buffer.
When a buffer is resizing itself (as allowed), I appreciate that could change its capacity, but should it also be allowed to change its length/content?

The original issue was discovered working with an ssh client (based on golang.org/x/crypto/ssh). The client passes a *bytes.Buffer as the io.Writer in Session.Stdout and Session.Stderr. The ssh package then starts io.Copy in a goroutine to write the stdout/err streams into the provided io.Writer (the *bytes.Buffer) here: https://github.com/golang/crypto/blob/master/ssh/session.go#L524.

We have wrapped the ssh.Run() call in a function with a context.WithTimeout and examine the buffers either when the ssh.Run returns, or the context times out.

In all such timeout cases, the Read() hasn't put anything in the buffer, as it is locked waiting for data from the ssh server.
In go 1.9 an prior, the buffers are empty on timeout.
In go 1.10+, the buffers are "full" (of zero) on timeout.

The fix proposed in #25436 simply keeps the buffer empty after it is "grown", using the same logic as in the exported Grow() method: https://github.com/golang/go/blob/master/src/bytes/buffer.go#L159

@ianlancetaylor
Copy link
Contributor

The mere fact of a behavior change between 1.9 and 1.10 doesn't necessarily indicate a bug. We are allowed to change behavior that the caller is not expected to observe.

Looking only at your description, it sounds like there is a data race in the code you are describing. After the context has timed out, but before the Read method has returned, the Read method might wake up at any time and modify the buffer. If you can write a test case that shows the problem and does not cause an error when built with go test -race, then we should consider it.

A more interesting question is: why do you want to do this?

@forfuncsake
Copy link
Contributor Author

Thanks @ianlancetaylor, some background info on the "why":

  • The ssh client package is tested with a mock ssh server
  • The test that identified this change in behaviour is specifically a timeout test
  • The mock server in this test will not terminate on SIGHUP (sent when the context expires)
  • A subsequent call to ssh session.Close() is made before we return

As such, after the session is closed, i thought it reasonable to inspect the Buffer.
Given that I know my server didn't send anything (fact of the test), I also thought it reasonable to expect that the buffer would remain "empty" (regardless of any adjustments to its runtime size/capacity).

It does still seem to be racy, as I can find the Buffer.buf is truncated again (by ReadFrom) if i sleep for as low as 150us after the Close() call (ew!).
Without this sleep, I don't see a way to both inspect the state of the Buffer (the ReadFrom may have piped some useful data into the Buffer from the ssh stream before we timed out) and completely avoid a data race in this case.

The test I wrote in my patch does not trigger the race detector and manages concurrent access to the Buffer with the explicit control channel between the Reader and the main goroutine. So while a raw bytes.Buffer is not guaranteed to be safe for concurrent access, the control channel makes it "safe enough" in this case (unless I'm wrong?).

tl;dr: After timing out and Close()ing an ssh session, I want to inspect the Buffers that I gave the session for Stdout and Stderr.

@davecheney
Copy link
Contributor

tl;dr: After timing out and Close()ing an ssh session, I want to inspect the Buffers that I gave the session for Stdout and Stderr.

If a reference to this buffer has passed to a goroutine which has not yet stopped, this is not safe.

@go101
Copy link

go101 commented May 18, 2018

The current ReadFrom implement really expects the method Read of the passed argument will never panic. If this is not true, the result would be unexpected.

package main

import (
	"fmt"
	"bytes"
	"io"
)

type T struct{}
func (T) Read(p []byte) (n int, err error) {
	panic(nil)
	return 0, io.EOF
}

func main() {
	var b bytes.Buffer
	defer func() {
		recover()
		fmt.Println(b.Len(), b.Cap()) // 512 512
	}()
	fmt.Println(b.Len(), b.Cap()) // 0 0
	b.ReadFrom(T{})
}

@davecheney
Copy link
Contributor

davecheney commented May 18, 2018

The current ReadFrom implement really expects the method Read of the passed argument will never panic

Can you please cite your source for this assertion.

@davecheney
Copy link
Contributor

fmt.Println(b.Len(), b.Cap()) // 512 512

At best this is an implementation detail. More realistically these values are undefined in the presence of a panic.

@go101
Copy link

go101 commented May 18, 2018

Yes, this may be not a bug. But op's PR is really an improvement.

@go101
Copy link

go101 commented May 18, 2018

@davecheney

Can you please cite your source for this assertion.

See my last example please. Yes, if that unexpected result is allowed, the ReadFrom docs should mention an unrecovered panic in a Read method would lead the Buffer to an undefined state.

@ianlancetaylor
Copy link
Contributor

I'm willing to consider the change if someone writes a test case showing the behavior of panic in a Read, especially if that behavior changed from 1.9 to 1.10.

@go101
Copy link

go101 commented May 18, 2018

@forfuncsake you can use my last example in your test case: https://go-review.googlesource.com/c/go/+/113495/2/src/bytes/buffer_test.go

@forfuncsake
Copy link
Contributor Author

Thanks all - I've pushed a new commit with TestReadFromPanicReader to replace the other test.
I verified that this test passes on release-branch.go1.9, fails on master and passes again with the added re-slice.

@bcmills bcmills changed the title bytes: ReadFrom causes a nil Buffer to be filled with 512 zero bytes bytes: panic from Read in (*Buffer).ReadFrom fills with 512 zero bytes May 23, 2018
@bcmills bcmills added this to the Go1.11 milestone May 23, 2018
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 23, 2018
@bradfitz
Copy link
Contributor

I'm willing to consider the change if someone writes a test case showing the behavior of panic in a Read, especially if that behavior changed from 1.9 to 1.10.

@ianlancetaylor, I confirm that the test shows the behavior change from 1.9 to 1.10.

Will approve and submit.

@golang golang locked and limited conversation to collaborators May 29, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

8 participants