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

[forfuncsake]

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]

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

[ghost]

You have a data race in your example.

[forfuncsake]

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

[zigo101]

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]

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]

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]

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]

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]

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]

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.

[zigo101]

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]

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]

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.

[zigo101]

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

[zigo101]

@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]

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.

[zigo101]

@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]

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.

[bradfitz]

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.