TestCompletenessInit race condition

[zmb3]

Failure

Link(s) to logs

• https://console.cloud.google.com/cloud-build/builds/162eff39-48cf-4b3d-aa0e-25fbdd06fd98;step=0?project=ci-account

Relevant snippet

    testing.go:1319: race detected during execution of test
--- FAIL: TestCompletenessInit (12.87s)

[zmb3]

Took 10-15 minutes to reproduce locally, but I was able to trigger it.

==================
WARNING: DATA RACE
Read at 0x00c000702c60 by goroutine 37749:
  github.com/gravitational/trace.(*TraceErr).UserMessage()
      /Users/zmb/go/pkg/mod/github.com/gravitational/trace@v1.1.19/trace.go:291 +0xe4
  github.com/gravitational/trace.(*TraceErr).Error()
      /Users/zmb/go/pkg/mod/github.com/gravitational/trace@v1.1.19/trace.go:324 +0x28
  github.com/sirupsen/logrus.(*JSONFormatter).Format()
      /Users/zmb/go/pkg/mod/github.com/gravitational/logrus@v1.4.4-0.20210817004754-047e20245621/json_formatter.go:70 +0x184
  github.com/gravitational/teleport/lib/utils.(*JSONFormatter).Format()
      /Users/zmb/teleport/lib/utils/formatter.go:249 +0x1e0
  github.com/sirupsen/logrus.(*Entry).write()
      /Users/zmb/go/pkg/mod/github.com/gravitational/logrus@v1.4.4-0.20210817004754-047e20245621/entry.go:289 +0xe0
  github.com/sirupsen/logrus.(*Entry).log()
      /Users/zmb/go/pkg/mod/github.com/gravitational/logrus@v1.4.4-0.20210817004754-047e20245621/entry.go:252 +0x704
  github.com/sirupsen/logrus.(*Entry).Log()
      /Users/zmb/go/pkg/mod/github.com/gravitational/logrus@v1.4.4-0.20210817004754-047e20245621/entry.go:301 +0x80
  github.com/sirupsen/logrus.(*Entry).Warn()
      /Users/zmb/go/pkg/mod/github.com/gravitational/logrus@v1.4.4-0.20210817004754-047e20245621/entry.go:322 +0x29c
  github.com/gravitational/teleport/lib/cache.(*Cache).update()
      /Users/zmb/teleport/lib/cache/cache.go:823 +0x17c
  github.com/gravitational/teleport/lib/cache.(*Cache).Start.func1()
      /Users/zmb/teleport/lib/cache/cache.go:771 +0x64

Previous write at 0x00c000702c60 by goroutine 37460:
  github.com/gravitational/trace.(*TraceErr).AddUserMessage()
      /Users/zmb/go/pkg/mod/github.com/gravitational/trace@v1.1.19/trace.go:260 +0xe8
  github.com/gravitational/trace.Wrap()
      /Users/zmb/go/pkg/mod/github.com/gravitational/trace@v1.1.19/trace.go:64 +0x1d0
  github.com/gravitational/teleport/lib/cache.(*Cache).fetch.func2()
      /Users/zmb/teleport/lib/cache/cache.go:1262 +0x494
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /Users/zmb/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:75 +0x6c

Goroutine 37749 (running) created at:
  github.com/gravitational/teleport/lib/cache.(*Cache).Start()
      /Users/zmb/teleport/lib/cache/cache.go:771 +0x294
  github.com/gravitational/teleport/lib/cache.New()
      /Users/zmb/teleport/lib/cache/cache.go:749 +0x1524
  github.com/gravitational/teleport/lib/cache.TestCompletenessInit()
      /Users/zmb/teleport/lib/cache/cache_test.go:588 +0x68c
  testing.tRunner()
      /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:1446 +0x188
  testing.(*T).Run.func1()
      /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:1493 +0x40

Goroutine 37460 (finished) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /Users/zmb/go/pkg/mod/golang.org/x/sync@v0.1.0/errgroup/errgroup.go:72 +0x10c
  github.com/gravitational/teleport/lib/cache.(*Cache).fetch()
      /Users/zmb/teleport/lib/cache/cache.go:1244 +0x520
  github.com/gravitational/teleport/lib/cache.(*Cache).fetchAndWatch()
      /Users/zmb/teleport/lib/cache/cache.go:941 +0x328
  github.com/gravitational/teleport/lib/cache.(*Cache).update()
      /Users/zmb/teleport/lib/cache/cache.go:817 +0x14c
  github.com/gravitational/teleport/lib/cache.(*Cache).Start.func1()
      /Users/zmb/teleport/lib/cache/cache.go:771 +0x64
==================
--- FAIL: TestCompletenessInit (2.47s)
    testing.go:1319: race detected during execution of test
FAIL
FAIL	github.com/gravitational/teleport/lib/cache	12.820s
FAIL

[Tener]

Another instance: https://console.cloud.google.com/cloud-build/builds/2d0f840c-ee2e-497f-8e92-e87fdd5e7d71?project=ci-account

[Tener]

The stack traces above were interesting, so I took a look. I believe the core issue is with the trace.Wrap function, since it modifies an existing error in place by calling AddUserMessage on it. This is a problem if another goroutine is in the process of calling Error() on *trace.TraceError, as ultimately this leads to race accessing TraceErr.Messages field.

Here is a small test replicating the issue with only trace as a dependency:

func TestRaceErrorWrap(t *testing.T) {
	baseErr := trace.BadParameter("foo")

	iters := 1000

	wg := sync.WaitGroup{}
	wg.Add(2)

	// trace.Wrap with user message
	go func() {
		for i := 0; i < iters; i++ {
			_ = trace.Wrap(baseErr, "foo bar %q", "baz")
		}
		wg.Done()
	}()

	// plain Error() call
	go func() {
		for i := 0; i < iters; i++ {
			_ = baseErr.Error()
		}
		wg.Done()
	}()

	wg.Wait()
}

Running with -race finds the issue pretty quickly.

I think this should be fixed by making trace.Wrap return a copy of the error in case AddUserMessage is called (which isn't often); what do you think?

[espadolini]

Just hit this in a v10 UT run: https://console.cloud.google.com/cloud-build/builds/94c44426-d06c-4f8b-bd28-3a349a64651f?project=ci-account

[ibeckermayer]

Hit in a v9 run: https://console.cloud.google.com/cloud-build/builds/afd23f62-5d05-4788-939d-a56a045ee5de?project=ci-account

[Tener]

Reopening as v9 and v10 are still affected.

[Tener]

Closing as gravitational/trace has now been updated on all active branches.

#19719
#19718