io: race condition with use of Pipe #67633

aliaksein-orca · 2024-05-24T14:40:43Z

Go version

go version go1.22.3 darwin/arm64

Output of `go env` in your module/workspace:

GO111MODULE='on'
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/aliakseinovikau/Library/Caches/go-build'
GOENV='/Users/aliakseinovikau/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/aliakseinovikau/go/pkg/mod'
GONOPROXY='github.com/orcasecurity/*'
GONOSUMDB='github.com/orcasecurity/*'
GOOS='darwin'
GOPATH='/Users/aliakseinovikau/go'
GOPRIVATE='github.com/orcasecurity/*'
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/opt/go/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/opt/go/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.3'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/Users/aliakseinovikau/Projects/secret-detector/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/wx/brjmy6md5fs02h2yw1szl1c00000gn/T/go-build3222794054=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

There is the race condition when we concurrently try to close the writer and fmt.Printf the reader like in the snippet test below. It was working without the race condition in v1.21.7.

package io

import (
	"fmt"
	"io"
	"testing"
)

func TestIoPipeConcurrency(t *testing.T) {
	r, w := io.Pipe()
	go func() {
		w.Write([]byte("hello"))
		w.Close()
	}()
	fmt.Printf("(%[1]T=%[1]v)", r)
	buf := make([]byte, 5)
	n, err := r.Read(buf)
	if err != nil {
		t.Fatalf("unexpected error: %v", err)
	}
	if n != 5 {
		t.Fatalf("unexpected number of bytes read: %d", n)
	}
	if string(buf) != "hello" {
		t.Fatalf("unexpected read content: %s", buf)
	}
}

What did you see happen?

=== RUN   TestIoPipeConcurrency
==================
WARNING: DATA RACE
Read at 0x00c0000a6180 by goroutine 6:
  reflect.typedmemmove()
      /opt/homebrew/opt/go/libexec/src/runtime/mbarrier.go:203 +0x0
  reflect.packEface()
      /opt/homebrew/opt/go/libexec/src/reflect/value.go:135 +0xa4
  reflect.valueInterface()
      /opt/homebrew/opt/go/libexec/src/reflect/value.go:1526 +0x148
  reflect.Value.Interface()
      /opt/homebrew/opt/go/libexec/src/reflect/value.go:1496 +0x74
  fmt.(*pp).printValue()
      /opt/homebrew/opt/go/libexec/src/fmt/print.go:769 +0x80
  fmt.(*pp).printValue()
      /opt/homebrew/opt/go/libexec/src/fmt/print.go:921 +0xf88
  fmt.(*pp).printArg()
      /opt/homebrew/opt/go/libexec/src/fmt/print.go:759 +0x8a0
  fmt.(*pp).doPrintf()
      /opt/homebrew/opt/go/libexec/src/fmt/print.go:1174 +0xc38
  fmt.Fprintf()
      /opt/homebrew/opt/go/libexec/src/fmt/print.go:224 +0x58
  fmt.Printf()
      /opt/homebrew/opt/go/libexec/src/fmt/print.go:233 +0x1e8
  github.com/orcasecurity/secret-detector/pkg/tools/io.TestIoPipeConcurrency()
      /Users/aliakseinovikau/Projects/secret-detector/pkg/tools/io/pipe_test.go:15 +0x194
  testing.tRunner()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:1742 +0x40

Previous write at 0x00c0000a6180 by goroutine 7:
  ??()
      -:0 +0x102eef688
  sync/atomic.CompareAndSwapInt32()
      <autogenerated>:1 +0x18
  io.(*pipe).write()
      /opt/homebrew/opt/go/libexec/src/io/pipe.go:81 +0x70
  io.(*PipeWriter).Write()
      /opt/homebrew/opt/go/libexec/src/io/pipe.go:161 +0x80
  github.com/orcasecurity/secret-detector/pkg/tools/io.TestIoPipeConcurrency.func1()
      /Users/aliakseinovikau/Projects/secret-detector/pkg/tools/io/pipe_test.go:12 +0x28

Goroutine 6 (running) created at:
  testing.(*T).Run()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:1742 +0x5e4
  testing.runTests.func1()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:2161 +0x80
  testing.tRunner()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:1689 +0x180
  testing.runTests()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:2159 +0x6e0
  testing.(*M).Run()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:2027 +0xb74
  main.main()
      _testmain.go:47 +0x294

Goroutine 7 (running) created at:
  github.com/orcasecurity/secret-detector/pkg/tools/io.TestIoPipeConcurrency()
      /Users/aliakseinovikau/Projects/secret-detector/pkg/tools/io/pipe_test.go:11 +0x190
  testing.tRunner()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:1689 +0x180
  testing.(*T).Run.gowrap1()
      /opt/homebrew/opt/go/libexec/src/testing/testing.go:1742 +0x40
==================
(*io.PipeReader=&{{{1 0} 0xc0000902a0 0xc000090300 {{{} 0} {0 0}} 0xc000090360 {{0 0} <nil>} {{0 0} <nil>}}})    testing.go:1398: race detected during execution of test
--- FAIL: TestIoPipeConcurrency (0.00s)

FAIL

Process finished with the exit code 1

What did you expect to see?

The test finishes successfully without the races.

The text was updated successfully, but these errors were encountered:

cuonglm · 2024-05-24T15:03:15Z

Looks like https://go-review.googlesource.com/c/go/+/473535 is the culprit.

cc @ianlancetaylor @dsnet

mateusz834 · 2024-05-24T15:24:50Z

That seems to only happen because of the fmt.Printf. There is no race here:

func TestIoPipeConcurrency(t *testing.T) {
	r, w := io.Pipe()
	go func() {
		w.Write([]byte("hello"))
		w.Close()
	}()
-	fmt.Printf("(%[1]T=%[1]v)", r)
	buf := make([]byte, 5)
	n, err := r.Read(buf)
	if err != nil {
		t.Fatalf("unexpected error: %v", err)
	}
	if n != 5 {
		t.Fatalf("unexpected number of bytes read: %d", n)
	}
	if string(buf) != "hello" {
		t.Fatalf("unexpected read content: %s", buf)
	}
}

Before CL 473535, the print statement would print:

(*io.PipeReader=&{0xc000241680})

Now it prints:

(*io.PipeReader=&{{{1 0} 0xc0004220e0 0xc000422150 {{{} 0} {0 0}} 0xc0004221c0 {{0 0} <nil>} {{0 0} <nil>}}})

So it has to access all the fields while printing.

aliaksein-orca · 2024-05-24T15:32:01Z

@mateusz834 Yes, exactly. That's why it cannot be passed into the mockery mock as one of the parameters like here: https://github.com/stretchr/testify/blob/v1.9.0/mock/mock.go#L939
This test reproduces our real test races after moving from 1.21.7 to 1.22.0 and 1.22.3.

gopherbot · 2024-05-24T16:43:44Z

Change https://go.dev/cl/588219 mentions this issue: io: add test for Pipe constructor allocations

gopherbot · 2024-05-24T16:43:44Z

Change https://go.dev/cl/588220 mentions this issue: io: fix race condition when formatting PipeWriter/PipeReader

dsnet · 2024-05-24T17:03:07Z

Thanks for the report.

I'm not sure how this race is much different than trying to fmt.Print any other data structure that contains an atomic field or mutex within it. Such cases would also be racy. Reverting the change would be an unfortunate hit to performance for a dubious use case in my opinion. It's been 3 months since 1.20 has been released and I believe this is the first report of this race?

ianlancetaylor · 2024-05-24T19:56:55Z

Seems like we could fix the problem by giving io.PipeReader a String method.

I really don't know how seriously to take this.

ianlancetaylor · 2024-05-24T19:57:45Z

Or perhaps we could give sync.Mutex and sync.Once String methods.

dsnet · 2024-05-24T20:40:31Z

Alternatively, we could teach fmt to avoid printing anything from the sync and atomic package?

cuonglm · 2024-05-25T03:19:57Z

Seems like we could fix the problem by giving io.PipeReader a String method.

I really don't know how seriously to take this.

That would need a proposal 😃

cuonglm · 2024-05-29T08:05:05Z

Seems like we could fix the problem by giving io.PipeReader a String method.

I really don't know how seriously to take this.

Yay, giving String method to pipe seems to be enough.

cuonglm · 2024-05-29T08:51:01Z

Seems like we could fix the problem by giving io.PipeReader a String method.
I really don't know how seriously to take this.

Yay, giving String method to pipe seems to be enough.

Not really, the method is still promoted because pipe is an embeded field.

Updates #67633 Change-Id: If3da9317ba36cb8a7868db94b45c402e1793e018 Reviewed-on: https://go-review.googlesource.com/c/go/+/588219 Auto-Submit: Cuong Manh Le <cuong.manhle.vn@gmail.com> Auto-Submit: Ian Lance Taylor <iant@google.com> Reviewed-by: Mateusz Poliwczak <mpoliwczak34@gmail.com> Reviewed-by: Ian Lance Taylor <iant@google.com> LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com> Reviewed-by: Than McIntosh <thanm@google.com>

cagedmantis changed the title ~~io.Pipe() race condition~~ io: race condition with use of Pipe May 24, 2024

cagedmantis added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 24, 2024

This comment was marked as outdated.

Sign in to view

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

io: race condition with use of Pipe #67633

io: race condition with use of Pipe #67633

aliaksein-orca commented May 24, 2024

cuonglm commented May 24, 2024

mateusz834 commented May 24, 2024

aliaksein-orca commented May 24, 2024

gopherbot commented May 24, 2024

gopherbot commented May 24, 2024

dsnet commented May 24, 2024 •

edited

Loading

ianlancetaylor commented May 24, 2024

ianlancetaylor commented May 24, 2024

dsnet commented May 24, 2024

cuonglm commented May 25, 2024

This comment was marked as outdated.

cuonglm commented May 29, 2024

cuonglm commented May 29, 2024

io: race condition with use of Pipe #67633

io: race condition with use of Pipe #67633

Comments

aliaksein-orca commented May 24, 2024

Go version

Output of go env in your module/workspace:

What did you do?

What did you see happen?

What did you expect to see?

cuonglm commented May 24, 2024

mateusz834 commented May 24, 2024

aliaksein-orca commented May 24, 2024

gopherbot commented May 24, 2024

gopherbot commented May 24, 2024

dsnet commented May 24, 2024 • edited Loading

ianlancetaylor commented May 24, 2024

ianlancetaylor commented May 24, 2024

dsnet commented May 24, 2024

cuonglm commented May 25, 2024

This comment was marked as outdated.

cuonglm commented May 29, 2024

cuonglm commented May 29, 2024

Output of `go env` in your module/workspace:

dsnet commented May 24, 2024 •

edited

Loading