cuelang / cue

CUE has moved to https://github.com/cue-lang/cue
https://cuelang.org
Apache License 2.0
3.09k stars 171 forks source link

panic: freeNode: nodeContext out of sync [recovered] #673

Closed verdverm closed 3 years ago

verdverm commented 3 years ago

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

occurs with: beta.2 & beta.3

ok in beta.1

bisected to a086f74

Stack trace

cue eval (with https://github.com/hofstadter-io/_saas) (seeing the same stack via the Go API in hof)

panic: nil value
        panic: freeNode: nodeContext out of sync
        panic: freeNode: nodeContext out of sync [recovered]
        panic: freeNode: nodeContext out of sync

goroutine 1 [running]:
cuelang.org/go/cmd/cue/cmd.recoverError(0xc0005c5ec0)
        /home/tony/cue/gerrit/cmd/cue/cmd/root.go:221 +0x95
panic(0xba0ba0, 0xd7c6a0)
        /usr/local/go/src/runtime/panic.go:969 +0x1b9
cuelang.org/go/internal/core/adt.(*Vertex).freeNode(0xc0003c8000, 0xc0003bf180)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:822 +0x132
panic(0xba0ba0, 0xd7c6a0)
        /usr/local/go/src/runtime/panic.go:975 +0x47a
cuelang.org/go/internal/core/adt.(*Vertex).freeNode(0xc0003dc900, 0xc0003cca80)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:822 +0x132
panic(0xba0ba0, 0xd7c660)
        /usr/local/go/src/runtime/panic.go:975 +0x47a
cuelang.org/go/internal/core/adt.(*Unifier).evaluate(0xc000375438, 0xc000375420, 0xc0003dcb40, 0x7bc5bd1c6203, 0xc00040e3d0, 0x1)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:167 +0x371
cuelang.org/go/internal/core/adt.(*OpContext).evalState(0xc000375420, 0xda0a00, 0xc00040e3d0, 0xc000020003, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:594 +0x247
cuelang.org/go/internal/core/adt.(*OpContext).node(0xc000375420, 0xd937e0, 0xc00024a900, 0xda0a00, 0xc00040e3d0, 0xc000020001, 0xbec6c0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:734 +0x5f
cuelang.org/go/internal/core/adt.(*SelectorExpr).resolve(0xc00024a900, 0xc000375420, 0xc000121d70)
        /home/tony/cue/gerrit/internal/core/adt/expr.go:706 +0x65
cuelang.org/go/internal/core/adt.(*OpContext).Resolve(0xc000375420, 0xc0006f5770, 0xd9adc0, 0xc00024a900, 0xc00024a900, 0x1)
        /home/tony/cue/gerrit/internal/core/adt/context.go:401 +0xe8
cuelang.org/go/internal/core/adt.(*nodeContext).evalExpr(0xc000697880, 0xc0006f5770, 0xd933a0, 0xc00024a920, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:1112 +0x51f
cuelang.org/go/internal/core/adt.(*nodeContext).addExprConjunct(0xc000697880, 0xc0006f5770, 0xd933a0, 0xc00024a920, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:1082 +0x211
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0006fcc60, 0xc0005bd003)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:269 +0x319
cuelang.org/go/internal/core/adt.(*Unifier).evaluate(0xc000375438, 0xc000375420, 0xc0006fcc60, 0xd9ad03, 0xc000136700, 0xc00024aa01)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:139 +0x7b
cuelang.org/go/internal/core/adt.(*OpContext).evalState(0xc000375420, 0xda0cc0, 0xc000136700, 0x3, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:594 +0x247
cuelang.org/go/internal/core/adt.(*OpContext).node(0xc000375420, 0xd937e0, 0xc000136720, 0xda0cc0, 0xc000136700, 0xc15101, 0xc0006f5601)
        /home/tony/cue/gerrit/internal/core/adt/context.go:734 +0x5f
cuelang.org/go/internal/core/adt.(*SelectorExpr).resolve(0xc000136720, 0xc000375420, 0xc000136720)
        /home/tony/cue/gerrit/internal/core/adt/expr.go:706 +0x65
cuelang.org/go/internal/core/adt.(*OpContext).evalState(0xc000375420, 0xda0cc0, 0xc000136720, 0x2, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:586 +0x1fd
cuelang.org/go/internal/core/adt.(*OpContext).value(0xc000375420, 0xda0cc0, 0xc000136720, 0xc0006d5cc0, 0x7bc5bc70c648)
        /home/tony/cue/gerrit/internal/core/adt/context.go:546 +0x48
cuelang.org/go/internal/core/adt.(*IfClause).yield(0xc0003422a0, 0xc000375420, 0xc0006d5cc0)
        /home/tony/cue/gerrit/internal/core/adt/expr.go:1440 +0x46
cuelang.org/go/internal/core/adt.(*OpContext).Yield(0xc000375420, 0xc0006f5540, 0xd9ac40, 0xc0003422a0, 0xc0006d5cc0, 0xd933a0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:444 +0xf2
cuelang.org/go/internal/core/adt.(*nodeContext).injectEmbedded(0xc000434700, 0xc000434900, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:1811 +0x165
cuelang.org/go/internal/core/adt.(*nodeContext).expandOne(0xc000434700, 0xc0006fcab0)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:1734 +0xc5
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0006fcab0, 0xc0005bd803)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:280 +0x3de
cuelang.org/go/internal/core/adt.(*Unifier).evaluate(0xc000375438, 0xc000375420, 0xc0006fcab0, 0xd9ad03, 0xc00024b4a0, 0x701)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:139 +0x7b
cuelang.org/go/internal/core/adt.(*OpContext).evalState(0xc000375420, 0xda0cc0, 0xc00024b4a0, 0xc000261c03, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:594 +0x247
cuelang.org/go/internal/core/adt.(*OpContext).node(0xc000375420, 0xd937e0, 0xc00024b580, 0xda0cc0, 0xc00024b4a0, 0xc000020001, 0xbec6c0)
        /home/tony/cue/gerrit/internal/core/adt/context.go:734 +0x5f
cuelang.org/go/internal/core/adt.(*SelectorExpr).resolve(0xc00024b580, 0xc000375420, 0xc00048d5f0)
        /home/tony/cue/gerrit/internal/core/adt/expr.go:706 +0x65
cuelang.org/go/internal/core/adt.(*OpContext).Resolve(0xc000375420, 0xc0006f4f00, 0xd9adc0, 0xc00024b580, 0xc00024b580, 0x1)
        /home/tony/cue/gerrit/internal/core/adt/context.go:401 +0xe8
cuelang.org/go/internal/core/adt.(*nodeContext).evalExpr(0xc000429880, 0xc0006f4f00, 0xd933a0, 0xc00024b5a0, 0xc0003c0f20, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:1112 +0x51f
cuelang.org/go/internal/core/adt.(*nodeContext).addExprConjunct(0xc000429880, 0xc0006f4f00, 0xd933a0, 0xc00024b5a0, 0xc0003c0f20, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:1082 +0x211
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0006fc480, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:269 +0x319
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc000428a80, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc000428a80, 0xc000428a05)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc000428a80, 0xc000480505, 0xc000428a80, 0x0, 0xc000427500)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc000480510, 0xc15005)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc000429180, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc000429180, 0xd05)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc000429180, 0xc0004fd705, 0xc0003cca80, 0x2, 0xc000427201)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc0003cca80, 0xc0003dc905, 0xc0003cca80, 0x0, 0xc0003c0f00)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:214 +0x445
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0003dc900, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc0003cc000, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc0003cc000, 0xc000375405)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc0003cc000, 0xc0003c9205, 0xc0003cc000, 0x0, 0xc0003c0600)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0003c9290, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc0003bfc00, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc0003bfc00, 0x505)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc0003bfc00, 0xc000181905, 0xc0003bf180, 0x2, 0xc0003c0601)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc0003bf180, 0xc0003c8005, 0xc0003bf180, 0x0, 0xc0003c0700)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:214 +0x445
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0003c8000, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc0003bf500, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc0003bf500, 0xc0003b8a05)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc0003bf500, 0xc0003c7d05, 0xc0003bf500, 0x0, 0xc0003c0500)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0003c7dd0, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc0003bea80, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc0003bea80, 0xc0003bea05)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc0003bea80, 0xc0003c3105, 0xc0003bea80, 0x0, 0xc00024bf00)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc0003c3170, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc000337c00, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc000337c00, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc000337c00, 0xc000373105, 0xc000337c00, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc000373170, 0xc15305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*nodeContext).completeArcs(0xc000337880, 0x5)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:600 +0x136
cuelang.org/go/internal/core/adt.(*nodeContext).postDisjunct(0xc000337880, 0xc000147305)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:546 +0x47b
cuelang.org/go/internal/core/adt.(*nodeContext).expandDisjuncts(0xc000337880, 0xc000373005, 0xc000337880, 0x0, 0x0)
        /home/tony/cue/gerrit/internal/core/adt/disjunct.go:142 +0x1032
cuelang.org/go/internal/core/adt.(*Unifier).Unify(0xc000375438, 0xc000375420, 0xc000373050, 0xc000375405)
        /home/tony/cue/gerrit/internal/core/adt/eval.go:329 +0x49a
cuelang.org/go/internal/core/adt.(*Vertex).Finalize(...)
        /home/tony/cue/gerrit/internal/core/adt/composite.go:405
cuelang.org/go/cue.(*Instance).Value(0xc000569f80, 0x6, 0xc0002a7d80)
        /home/tony/cue/gerrit/cue/instance.go:271 +0x6c
cuelang.org/go/cmd/cue/cmd.buildInstances(0xc0002a7d80, 0xc0005a4600, 0x1, 0x1, 0xc0003f7140, 0xc00059a500, 0xc00059a4f0)
        /home/tony/cue/gerrit/cmd/cue/cmd/common.go:552 +0x131
cuelang.org/go/cmd/cue/cmd.(*buildPlan).instances(0xc0000fc240, 0x0, 0x0)
        /home/tony/cue/gerrit/cmd/cue/cmd/common.go:156 +0x58
cuelang.org/go/cmd/cue/cmd.runEval(0xc0002a7d80, 0x1208248, 0x0, 0x0, 0x0, 0x0)
        /home/tony/cue/gerrit/cmd/cue/cmd/eval.go:113 +0x318
cuelang.org/go/cmd/cue/cmd.mkRunE.func1(0xc0002058c0, 0x1208248, 0x0, 0x0, 0x0, 0x0)
        /home/tony/cue/gerrit/cmd/cue/cmd/root.go:46 +0x6c
github.com/spf13/cobra.(*Command).execute(0xc0002058c0, 0x1208248, 0x0, 0x0, 0xc0002058c0, 0x1208248)
        /home/tony/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:842 +0x47c
github.com/spf13/cobra.(*Command).ExecuteC(0xc000205080, 0x0, 0x0, 0x0)
        /home/tony/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:950 +0x375
github.com/spf13/cobra.(*Command).Execute(...)
        /home/tony/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:887
cuelang.org/go/cmd/cue/cmd.(*Command).Run(0xc0002a7d80, 0xd9e680, 0xc0000340b8, 0x0, 0x0)
        /home/tony/cue/gerrit/cmd/cue/cmd/root.go:206 +0x65
cuelang.org/go/cmd/cue/cmd.mainErr(0xd9e680, 0xc0000340b8, 0xc00000e070, 0x1, 0x1, 0xce1520, 0xc00024df48)
        /home/tony/cue/gerrit/cmd/cue/cmd/root.go:145 +0x8a
cuelang.org/go/cmd/cue/cmd.Main(0xc00008a058)
        /home/tony/cue/gerrit/cmd/cue/cmd/root.go:127 +0x9c
main.main()
        /home/tony/cue/gerrit/cmd/cue/main.go:24 +0x25

Repro

Linux64 repro steps

# get repro
git clone https://github.com/hofstadter-io/_saas
cd _saas

# get hof
curl https://github.com/hofstadter-io/hof/releases/download/v0.5.15/hof_0.5.15_Linux_x86_64 -o hof
chmod +x ./hof

# fetch deps
./hof mod vendor cue

# run repro
cue eval
myitcv commented 3 years ago

@verdverm - thanks for bisecting.

Per https://github.com/cuelang/cue/wiki/Creating-test-or-performance-reproducers, please can you provide a more detailed reproducer, with a specific commit of the hof project (so that we don't accidentally pick up a workaround/any other artefacts)? Thanks

verdverm commented 3 years ago

added to the original writeup

myitcv commented 3 years ago

That repro doesn't work for me:

cd $(mktemp -d)
(
set -ex

# get repro
git clone https://github.com/hofstadter-io/_saas
cd _saas

# get hof
curl https://github.com/hofstadter-io/hof/releases/download/v0.5.15/hof_0.5.15_Linux_x86_64 -o hof
chmod +x ./hof

# fetch deps
./hof mod vendor cue

# run repro
cue eval
)

Gives:

./hof: line 1: syntax error near unexpected token `<'
./hof: line 1: `<html><body>You are being <a href="https://github-production-release-asset-2e65be.s3.amazonaws.com/238593012/ff3dfa00-5346-11eb-80e2-53bed5772806?X-Amz-Algorithm=AWS4-HMAC-SHA256&amp;X-Amz-Credential=AKIAIWNJYAX4CSVEH53A%2F20210125%2Fus-east-1%2Fs3%2Faws4_request&amp;X-Amz-Date=20210125T155716Z&amp;X-Amz-Expires=300&amp;X-Amz-Signature=d30cc815ac8a0f1efed4090076909e05238675c0d4f439158af44d57deb1cd4c&amp;X-Amz-SignedHeaders=host&amp;actor_id=0&amp;key_id=0&amp;repo_id=238593012&amp;response-content-disposition=attachment%3B%20filename%3Dhof_0.5.15_Linux_x86_64&amp;response-content-type=application%2Foctet-stream">redirected</a>.</body></html>'

But the following does (added missing -L flag to curl):

cd $(mktemp -d)
(
set -ex

# get repro
git clone https://github.com/hofstadter-io/_saas
cd _saas

# get hof
curl -sL https://github.com/hofstadter-io/hof/releases/download/v0.5.15/hof_0.5.15_Linux_x86_64 -o hof
chmod +x ./hof

# fetch deps
./hof mod vendor cue

# run repro
cue eval
)

Per my original question, what commit of the _sass repo should we be checking? Your repro is the tip of the default remote branch... which is a moving feast.

verdverm commented 3 years ago

I pushed earlier and made sure everything is current for this repro. Won't be touching any of it for a bit, so tip there should be good.

myitcv commented 3 years ago

Won't be touching any of it for a bit, so tip there should be good.

That might well be, but communicating the exact commit with which you tested is as much about confirming from your side that you were indeed testing a clean commit, as opposed to a dirty working tree. It also means that you can copy-paste the repro steps you are sharing locally to verify as a quick final check that they a) work and b) are using exactly the right code.

Perhaps most importantly it also makes the repro consistent over time, and hence reduces the amount of effort/potential confusion for someone looking to investigate now or later.

mpvl commented 3 years ago

@verdverm could you verify whether this is fixed with master?

verdverm commented 3 years ago

@mpvl Can confirm the panic is gone, but with a decent slowdown (~2.5s -> ~4.5) (previous is beta.1)

mpvl commented 3 years ago

@verdverm Would you be able to bisect at which commit the slowdown occurs?

mpvl commented 3 years ago

Or alternatively, see if the slowdown still occurs when commenting out the body of addNotify

if v != nil {
        n.notify = append(n.notify, v)
    }

at around internal/core/adt/eval.go:732?

verdverm commented 3 years ago

Commenting out that code does not later the runtime. I'll get to bisecting next

verdverm commented 3 years ago

Not sure I can bisect due to the panics.

So I do not know if / where the slowdown occurred between beta.1 and ee78ec3

myitcv commented 3 years ago

On the basis the panic reported in this issue is now solved, I think we need to move performance issues to a separate issue.

It's not clear to me that we have a solid base against which to compare performance here in any case. Reason being, there a correctness fixes along the way. The panic was "introduced" in bef7b263893bf64368d00aeb6d3e8cf7976dbdf2 which is fixing a cycle bug for example.

That's not to say performance issues aren't important. Far from it. Rather it's hard to definitively say there has been a real performance regression here, and instead that we should, all else being equal, come to look in more detail at a later time.

cueckoo commented 3 years ago

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

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