cue: data race when calling cue.Fill concurrently

myitcv commented 3 years ago

What version of CUE are you using (`cue version`)?

$ cue version
v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb

Does this issue reproduce with the latest release?

Yes

What did you do?

cat <<'EOD' | testscript -e GOPATH="$(go env GOPATH)" -e GOBUILD="$(go env GOBUILD)"

exec go mod tidy
exec go run -race main.go

-- go.mod --
module mod.com

go 1.16

require cuelang.org/go v0.3.0-beta.2.0.20210120153448-c58e0ffc4c74
-- main.cue --
package main

#A: {
 type: "a"
 val:  #C
}

#C: string

tasks: {
 a: {
  $id: "a"
 }
 b: {
  $id: "b"
 }
}
-- main.go --
package main

import (
 "cuelang.org/go/cue"
 "cuelang.org/go/cue/load"
)

func main() {
 bis := load.Instances([]string{"."}, nil)
 is := cue.Build(bis)
 inst := is[0]

 schema := inst.LookupDef("#A")
 go fill(schema)
 go fill(schema)
}

func fill(schema cue.Value) {
 for i := 0; i < 100000; i++ {
  schema.Fill(5)
 }
}
EOD

Note, you might need to re-run this a few times (or increase the counter limit in the for loop)

What did you expect to see?

Success

What did you see instead?

[stderr]
==================
WARNING: DATA RACE
Write at 0x00c00034b6a0 by goroutine 19:
  cuelang.org/go/internal/core/adt.(*nodeContext).evalExpr()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1063 +0x136
  cuelang.org/go/internal/core/adt.(*nodeContext).addExprConjunct()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1049 +0x2f4
  cuelang.org/go/internal/core/adt.(*Unifier).Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:250 +0x1644
  cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:567 +0x21c
  cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:538 +0x5d3
  cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/disjunct.go:142 +0x1d07
  cuelang.org/go/internal/core/adt.(*Unifier).Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:305 +0x3b0
  cuelang.org/go/internal/core/adt.(*Vertex).Finalize()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/composite.go:405 +0x148
  cuelang.org/go/cue.Value.Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1778 +0x127
  cuelang.org/go/cue.Value.Fill()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1648 +0x288
  main.fill()
      $WORK/main.go:20 +0x78

Previous read at 0x00c00034b6a0 by goroutine 20:
  cuelang.org/go/internal/core/adt.(*Vertex).Status()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/composite.go:269 +0x265
  cuelang.org/go/internal/core/adt.(*nodeContext).addVertexConjuncts()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1168 +0x871
  cuelang.org/go/internal/core/adt.(*nodeContext).addExprConjunct()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1024 +0x1dd
  cuelang.org/go/internal/core/adt.(*Unifier).Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:250 +0x1644
  cuelang.org/go/internal/core/adt.(*Vertex).Finalize()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/composite.go:405 +0x148
  cuelang.org/go/cue.Value.Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1778 +0x127
  cuelang.org/go/cue.Value.Fill()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1648 +0x288
  main.fill()
      $WORK/main.go:20 +0x78

Goroutine 19 (running) created at:
  main.main()
      $WORK/main.go:14 +0x113

Goroutine 20 (running) created at:
  main.main()
      $WORK/main.go:15 +0x144
==================
==================
WARNING: DATA RACE
Read at 0x00c00034b6a8 by goroutine 19:
  cuelang.org/go/internal/core/adt.(*nodeContext).addVertexConjuncts()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1204 +0x728
  cuelang.org/go/internal/core/adt.(*nodeContext).addExprConjunct()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1024 +0x1dd
  cuelang.org/go/internal/core/adt.(*Unifier).Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:250 +0x1644
  cuelang.org/go/internal/core/adt.(*Vertex).Finalize()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/composite.go:405 +0x148
  cuelang.org/go/cue.Value.Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1778 +0x127
  cuelang.org/go/cue.Value.Fill()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1648 +0x288
  main.fill()
      $WORK/main.go:20 +0x78

Previous write at 0x00c00034b6a8 by goroutine 20:
  cuelang.org/go/internal/core/adt.(*nodeContext).addVertexConjuncts()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1210 +0x771
  cuelang.org/go/internal/core/adt.(*nodeContext).addExprConjunct()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:1024 +0x1dd
  cuelang.org/go/internal/core/adt.(*Unifier).Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/eval.go:250 +0x1644
  cuelang.org/go/internal/core/adt.(*Vertex).Finalize()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/internal/core/adt/composite.go:405 +0x148
  cuelang.org/go/cue.Value.Unify()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1778 +0x127
  cuelang.org/go/cue.Value.Fill()
      /home/myitcv/gostuff/pkg/mod/cuelang.org/go@v0.3.0-beta.2.0.20210118191218-f0c025c1a4cb/cue/types.go:1648 +0x288
  main.fill()
      $WORK/main.go:20 +0x78

Goroutine 19 (running) created at:
  main.main()
      $WORK/main.go:14 +0x113

Goroutine 20 (running) created at:
  main.main()
      $WORK/main.go:15 +0x144
==================
Found 2 data race(s)
exit status 66
[exit status 1]
FAIL: /tmp/testscript736373366/-/script.txt:3: unexpected command failure
error running <stdin> in /tmp/testscript736373366/-

cc @shykes

Note the above repro is using c58e0ffc4c74. However, the underlying problem also exists with v0.3.0-alpha6, albeit a different kind of problem (hence stack traces vary). Critically, this reproducer does not trigger the issue for v0.3.0-alpha6

myitcv commented 3 years ago

Further analysis: LookupPath also races with a Fill call. Which may or may not point to a problem in the code path LookupPath is following if it's reading that same state?

mpvl commented 3 years ago

Analysis: the race is caused by the reference cycle detection, which modifies fields in Vertex even when it is already Finalized.

So to fix this, the reference cycle detection algorithm needs to be changed. One idea is the following: the fields are only necessary to detect the cycle for fields that are already finalized; the first time the cycle is found, it uses a different mechanism. There is a possible optimization where identical arcs (i.e. those that evaluate without an error after the cycle detection) are evaluated once and share the same data structure. This is a great optimization. But it seemingly also would obviate the need for the additional cycle check, the one that causes things to be not thread-safe.

The following would be needed to implement structure sharing:

In the general case, use referenced fields as arcs, and only copy on demand.
The need to copy on demand can be recognized if the parent of an arc differs from the actual parent.
The API will need to track parent separately (like v0.2, but this is easier, as there is a "fallback" parent).
Ensure that all nodes in a cycle dereference immediately to the final node.

cueckoo commented 3 years ago

This issue has been migrated to https://github.com/cue-lang/cue/issues/652.

For more details about CUE's migration to a new home, please see https://github.com/cue-lang/cue/issues/1078.

cuelang / cue