Data race in app.Run with shared cli.Commands

[JohnStarich]

my urfave/cli version is

v2.3.0

Checklist

• Are you running the latest v2 release? The list of releases is here.
• Did you check the manual for your release? The v2 manual is here
• Did you perform a search about this problem? Here's the Github guide about searching.

(I didn't see any previous mentions of a race condition in code, issues, or PRs.)

Dependency Management

• My project is using go modules.
• My project is using vendoring.
• My project is automatically downloading the latest version.
• I am unsure of what my dependency management setup is.

Describe the bug

There's a data race when executing concurrent calls to app.Run().

Specifically, the race occurs while handling help flags in app.Commands. If the slice is shared, i.e. multiple concurrent tests are constructed from the same slice of commands, then inserting the help flag triggers the race detector.

To reproduce

I'm using the latest version of urfave v2, and go version go1.15.6 darwin/amd64.

Run go test -race main_test.go on the below file:

main_test.go:

package main

import (
	"testing"

	"github.com/urfave/cli/v2"
)

var Commands = cli.Commands{
	{
		Name:   "hello",
		Action: func(c *cli.Context) error { return nil },
	},
}

func TestRun1(t *testing.T) {
	t.Parallel()
	app := &cli.App{Commands: Commands}
	err := app.Run([]string{"", "hello"})
	if err != nil {
		t.Error("Error must be nil:", err)
	}
}

func TestRun2(t *testing.T) {
	t.Parallel()
	app := &cli.App{Commands: Commands}
	err := app.Run([]string{"", "hello"})
	if err != nil {
		t.Error("Error must be nil:", err)
	}
}

Observed behavior

I'm getting the following data race output from the above command:

(In my real test suite, I observed several data races involving help flags. The below might be one of several race condition sites.)

(click to expand)

Read at 0x00000150d6d8 by goroutine 8:
  github.com/urfave/cli/v2.(*App).Setup()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:181 +0x317

Previous write at 0x00000150d6d8 by goroutine 7:
  github.com/urfave/cli/v2.(*App).Setup()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:182 +0x510

Here's that spot:

if c.HelpName == "" {
	c.HelpName = fmt.Sprintf("%s %s", a.HelpName, c.Name)
}

==================
WARNING: DATA RACE
Read at 0x00000150d6d8 by goroutine 8:
  github.com/urfave/cli/v2.(*App).Setup()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:181 +0x317
  github.com/urfave/cli/v2.(*App).RunContext()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:231 +0x64
  github.com/urfave/cli/v2.(*App).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:224 +0x208
  urfave-data-race.TestRun2()
      ~/tmp/urfave-v2-data-race/main_test.go:28 +0x13c
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202

Previous write at 0x00000150d6d8 by goroutine 7:
  github.com/urfave/cli/v2.(*App).Setup()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:182 +0x510
  github.com/urfave/cli/v2.(*App).RunContext()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:231 +0x64
  github.com/urfave/cli/v2.(*App).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:224 +0x208
  urfave-data-race.TestRun1()
      ~/tmp/urfave-v2-data-race/main_test.go:19 +0x13c
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:45 +0x236

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:45 +0x236
==================
--- FAIL: TestRun1 (0.00s)
    testing.go:1038: race detected during execution of test
==================
WARNING: DATA RACE
Read at 0x00000150d6b8 by goroutine 8:
  github.com/urfave/cli/v2.(*Command).appendFlag()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:287 +0x108f
  github.com/urfave/cli/v2.(*Command).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:99 +0x1045
  github.com/urfave/cli/v2.(*App).RunContext()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:313 +0xc31
  github.com/urfave/cli/v2.(*App).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:224 +0x208
  urfave-data-race.TestRun2()
      ~/tmp/urfave-v2-data-race/main_test.go:28 +0x13c
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202

Previous write at 0x00000150d6b8 by goroutine 7:
  github.com/urfave/cli/v2.(*Command).appendFlag()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:288 +0x1199
  github.com/urfave/cli/v2.(*Command).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:99 +0x1045
  github.com/urfave/cli/v2.(*App).RunContext()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:313 +0xc31
  github.com/urfave/cli/v2.(*App).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:224 +0x208
  urfave-data-race.TestRun1()
      ~/tmp/urfave-v2-data-race/main_test.go:19 +0x13c
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:45 +0x236

Goroutine 7 (finished) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:45 +0x236
==================
==================
WARNING: DATA RACE
Read at 0x00c0000a2fe0 by goroutine 8:
  github.com/urfave/cli/v2.hasFlag()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/flag.go:366 +0x5e
  github.com/urfave/cli/v2.(*Command).appendFlag()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:287 +0x10d6
  github.com/urfave/cli/v2.(*Command).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:99 +0x1045
  github.com/urfave/cli/v2.(*App).RunContext()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:313 +0xc31
  github.com/urfave/cli/v2.(*App).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:224 +0x208
  urfave-data-race.TestRun2()
      ~/tmp/urfave-v2-data-race/main_test.go:28 +0x13c
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202

Previous write at 0x00c0000a2fe0 by goroutine 7:
  github.com/urfave/cli/v2.(*Command).appendFlag()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:288 +0x1154
  github.com/urfave/cli/v2.(*Command).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/command.go:99 +0x1045
  github.com/urfave/cli/v2.(*App).RunContext()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:313 +0xc31
  github.com/urfave/cli/v2.(*App).Run()
      ~/Documents/Projects/go/pkg/mod/github.com/urfave/cli/v2@v2.3.0/app.go:224 +0x208
  urfave-data-race.TestRun1()
      ~/tmp/urfave-v2-data-race/main_test.go:19 +0x13c
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202

Goroutine 8 (running) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:45 +0x236

Goroutine 7 (finished) created at:
  testing.(*T).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1168 +0x5bb
  testing.runTests.func1()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1439 +0xa6
  testing.tRunner()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1123 +0x202
  testing.runTests()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1437 +0x612
  testing.(*M).Run()
      /usr/local/Cellar/go/1.15.6/libexec/src/testing/testing.go:1345 +0x3b3
  main.main()
      _testmain.go:45 +0x236
==================
--- FAIL: TestRun2 (0.00s)
    testing.go:1038: race detected during execution of test
FAIL
FAIL	urfave-data-race	0.143s
FAIL

Expected behavior

I found it surprising that a shared slice of commands causes data races when starting a new app.

I realize this scenario is essentially non-existent in the real world, but this does crop up when running a suite of tests in parallel.

In my case, I'm using a pattern (borrowed from Cobra) where each command is set up inside a single file and init() registers the command with a package-global var Commands cli.Commands. It's easier to structure my app with this, and tests become even simpler to write.

I'm curious if this is an expected result? I'm unfamiliar with the code base, but if you like I might have some time to hammer out a fix.

Run go version and paste its output here

go version go1.15.6 darwin/amd64

Run go env and paste its output here

I could paste a pared down version of go env if you need it. I'm going to hold off for now though, since it has some company proxy info embedded in there.

[coilysiren]

I'm curious if this is an expected result?

Race conditions should never be an expected result 😄 I'm hoping the fix for this is straightforward and possible to cover with unit tests 🤞🏼🤞🏼🤞🏼

[coilysiren]

PRs welcome ✨

[JohnStarich]

PR opened 😄 Let me know what you think!
#1248

[igungor]

I realize this scenario is essentially non-existent in the real world, but this does crop up when running a suite of tests in parallel.

Actually it is :) peak/s5cmd#301

[rliebz]

I'm actually going to push back here and say this is a data race in the application, not a data race in the library. This package does not advertise concurrency, immutability, or thread-safety. To that point, it also does not perform any concurrent operations.

I think the Commands type in the example here hides what's really going on under the hood—absolutely to the fault of the library. But here is an example that is entirely equivalent, but makes the issue a lot more clear:

package main

import (
	"testing"

	"github.com/urfave/cli/v2"
)

var Commands = []*cli.Command{
	&cli.Command{
		Name:   "hello",
		Action: func(c *cli.Context) error { return nil },
	},
}

func TestRun1(t *testing.T) {
	t.Parallel()
	app := &cli.App{Commands: Commands}
	err := app.Run([]string{"", "hello"})
	if err != nil {
		t.Error("Error must be nil:", err)
	}
}

func TestRun2(t *testing.T) {
	t.Parallel()
	app := &cli.App{Commands: Commands}
	err := app.Run([]string{"", "hello"})
	if err != nil {
		t.Error("Error must be nil:", err)
	}
}

Playground link: https://play.golang.org/p/OP8SjDqkqT1

Passing references to a data structure, which contains stateful information, to multiple concurrent goroutines that may write to that data structure is a bug in the application, not a bug in the library.

The good news is there's a fairly straightforward way to get around this in the example, which hopefully can translate to the original program in which the data race was found. What I would do is instead of defining a Commands slice as a variable in the package scope, define a function in the package scope which returns the slice. For example:

package main

import (
	"testing"

	"github.com/urfave/cli/v2"
)

func NewCommands() cli.Commands {
	return cli.Commands{
		{
			Name:   "hello",
			Action: func(c *cli.Context) error { return nil },
		},
	}
}

func TestRun1(t *testing.T) {
	t.Parallel()
	app := &cli.App{Commands: NewCommands()}
	err := app.Run([]string{"", "hello"})
	if err != nil {
		t.Error("Error must be nil:", err)
	}
}

func TestRun2(t *testing.T) {
	t.Parallel()
	app := &cli.App{Commands: NewCommands()}
	err := app.Run([]string{"", "hello"})
	if err != nil {
		t.Error("Error must be nil:", err)
	}
}

Playground link: https://play.golang.org/p/MNht5HHH53I

In this case, each cli.App gets a unique set of commands, without needing to copy chunks of code with the same definition in each place.

[JohnStarich]

A fair stance for any library 👍

The reason I find this confusing is the documentation encourages a declarative style of defining commands and flags, just like v1. However, in v2, a declarative set of commands doesn't work when input commands are mutated unbeknownst to the user.

In my mind, it is surprising to encounter a race condition when sharing what amounts to a CLI's "schema".