Elvish: Panic on loading module with errors

[zzamboni]

If a used module contains an error, Elvish crashes upon any attempt at accessing its namespace.

[~]|> elvish -buildinfo
Version: v0.16.0-dev.f3bef66ee2992200ff6bfba0e6b26128631a173b
Go version: go1.16
Reproducible build: true

For example, if ~/.elvish/lib/test.elv contains the following:

put $foobar

Then:

[~]|> elvish
[~]|> use test
Exception: compilation error: variable $foobar not found
/Users/taazadi1/.elvish/lib/test.elv, line 1: put $foobar
[tty 1], line 1: use test

Now I type test: followed by t (any other key works too), Elvish panics the moment I type the key following the colon:

[~]|> test:panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x1255ee6]

goroutine 19424 [running]:
src.elv.sh/pkg/eval.(*Ns).lookup(0x0, 0xc0007d4cf8, 0x2, 0x2)
    src.elv.sh/pkg/eval/ns.go:101 +0x26
src.elv.sh/pkg/eval.(*Ns).IndexName(...)
    src.elv.sh/pkg/eval/ns.go:93
src.elv.sh/pkg/eval.(*Ns).Index(0x0, 0x12e37a0, 0xc0007d4d18, 0x1359b5d, 0x1, 0xc0007d4cf8)
    src.elv.sh/pkg/eval/ns.go:80 +0x5a
src.elv.sh/pkg/edit.hasFn(0x0, 0xc0006aeac9, 0x1, 0x1)
    src.elv.sh/pkg/edit/highlight.go:97 +0x96
src.elv.sh/pkg/edit.hasQualifiedFn(0xc00014b1e0, 0xc0006aeac4, 0x5, 0xc0006aeac9, 0x1, 0x1)
    src.elv.sh/pkg/edit/highlight.go:93 +0x1ca
src.elv.sh/pkg/edit.hasCommand(0xc00014b1e0, 0xc0006aeac4, 0x6, 0xc0004606d8)
    src.elv.sh/pkg/edit/highlight.go:58 +0x11d
src.elv.sh/pkg/edit.initHighlighter.func2(0xc0006aeac4, 0x6, 0x1)
    src.elv.sh/pkg/edit/highlight.go:17 +0x3e
src.elv.sh/pkg/edit/highlight.highlight.func1(0xc00079e0f0, 0x1, 0x1, 0xc0002d3a40, 0x1, 0x1, 0xc000098200, 0xc000098210, 0xc00008e300)
    src.elv.sh/pkg/edit/highlight/highlight.go:104 +0xe3
created by src.elv.sh/pkg/edit/highlight.highlight
    src.elv.sh/pkg/edit/highlight/highlight.go:100 +0xb65
Exception: elvish exited with 2
[tty 4], line 1: elvish

Trying again, now I type test: followed by Tab, which produces a longer backtrace:

[~]|> elvish
[~]|> use test
Exception: compilation error: variable $foobar not found
/Users/taazadi1/.elvish/lib/test.elv, line 1: put $foobar
[tty 1], line 1: use test
[~]|> test:
goroutine 1 [running]:
src.elv.sh/pkg/sys.DumpStack(0xc0001bc280, 0x12fc080)
    src.elv.sh/pkg/sys/dumpstack.go:10 +0x9f
src.elv.sh/pkg/shell.handlePanic()
    src.elv.sh/pkg/shell/interact.go:39 +0x8a
panic(0x12fc080, 0x154f8a0)
    runtime/panic.go:965 +0x1b9
src.elv.sh/pkg/eval.(*Ns).IterateNames(0x0, 0xc0003cec00)
    src.elv.sh/pkg/eval/ns.go:125 +0x26
src.elv.sh/pkg/edit.eachVariableInTop(0xc0002c6050, 0xc0004335e0, 0xc000a90560, 0x5, 0xc0003cec00)
    src.elv.sh/pkg/edit/ns_helper.go:43 +0x245
src.elv.sh/pkg/edit.pureEvaler.EachVariableInNs(0xc0001531e0, 0xc000a90560, 0x5, 0xc0003cec00)
    src.elv.sh/pkg/edit/completion.go:527 +0x71
src.elv.sh/pkg/edit/complete.generateCommands(0xc000a90560, 0x5, 0x13bfb78, 0xc0001531e0, 0xc000a90560, 0x5, 0xc0005e6f60, 0x0, 0xc0005e6f48)
    src.elv.sh/pkg/edit/complete/generators.go:76 +0x1f4
src.elv.sh/pkg/edit/complete.completeCommand(0x13bccb0, 0xc0005ba0c0, 0x13bfb78, 0xc0001531e0, 0xc0003ce8a0, 0xc000150300, 0x0, 0xc0005e6f00, 0x135caa9, 0xd, ...)
    src.elv.sh/pkg/edit/complete/completers.go:93 +0x309
src.elv.sh/pkg/edit/complete.Complete(0xc000a90560, 0x5, 0x5, 0x13bfb78, 0xc0001531e0, 0xc0003ce8a0, 0xc000150300, 0x0, 0x0, 0xc0001bc9b8)
    src.elv.sh/pkg/edit/complete/complete.go:92 +0x226
src.elv.sh/pkg/edit.completionStart(0x13c06f8, 0xc0001e4000, 0x13b7be8, 0xc0001c6600, 0x13bfb78, 0xc0001531e0, 0xc0003ce8a0, 0xc000150300, 0xc0001bcb01)
    src.elv.sh/pkg/edit/completion.go:164 +0xf5
src.elv.sh/pkg/edit.initCompletion.func4()
    src.elv.sh/pkg/edit/completion.go:248 +0xaa
reflect.Value.call(0x12decc0, 0xc0001c6630, 0x13, 0x1359f38, 0x4, 0x0, 0x0, 0x0, 0xc0001bcdf8, 0x0, ...)
    reflect/value.go:476 +0x8e7
reflect.Value.Call(0x12decc0, 0xc0001c6630, 0x13, 0x0, 0x0, 0x0, 0x300000002, 0xc000000180, 0xc0001bcf10)
    reflect/value.go:337 +0xb9
src.elv.sh/pkg/eval.(*goFn).Call(0xc0001e3260, 0xc00058c540, 0x0, 0x0, 0x0, 0xc00010f3b0, 0xc0006c07e0, 0x3)
    src.elv.sh/pkg/eval/go_fn.go:237 +0x678
src.elv.sh/pkg/eval.(*Evaler).Call(0xc0001531e0, 0x13b7468, 0xc0001e3260, 0x0, 0x0, 0x0, 0xc00010f3b0, 0x135d8c2, 0x10, 0xc0006c07e0, ...)
    src.elv.sh/pkg/eval/eval.go:491 +0x273
src.elv.sh/pkg/edit.callWithNotifyPorts(0x13b95a0, 0xc0001c42c0, 0xc0001531e0, 0x13b7468, 0xc0001e3260, 0x0, 0x0, 0x0)
    src.elv.sh/pkg/edit/key_binding.go:67 +0x1d2
src.elv.sh/pkg/edit.mapBindings.Handle(0x13b95a0, 0xc0001c42c0, 0xc0001531e0, 0xc000128bb8, 0x1, 0x1, 0x13b9500, 0xc0001e6000, 0x13b7aa8, 0xc0006de120, ...)
    src.elv.sh/pkg/edit/key_binding.go:41 +0x1c5
src.elv.sh/pkg/cli/tk.(*codeArea).handleKeyEvent(0xc0001e6000, 0x9, 0x13b9500)
    src.elv.sh/pkg/cli/tk/codearea.go:289 +0x127
src.elv.sh/pkg/cli/tk.(*codeArea).Handle(0xc0001e6000, 0x13b7aa8, 0xc0006de118, 0x13b9500)
    src.elv.sh/pkg/cli/tk/codearea.go:164 +0xc5
src.elv.sh/pkg/cli.(*app).handle(0xc0001e4000, 0x1322c20, 0xc0006de118)
    src.elv.sh/pkg/cli/app.go:196 +0x231
src.elv.sh/pkg/cli.(*loop).Run(0xc0001c45c0, 0xc000100201, 0xc0000964e0, 0xc0001e4000, 0xc00001bfa0)
    src.elv.sh/pkg/cli/loop.go:129 +0x16f
src.elv.sh/pkg/cli.(*app).ReadCode(0xc0001e4000, 0x0, 0x0, 0x0, 0x0)
    src.elv.sh/pkg/cli/app.go:365 +0x3f9
src.elv.sh/pkg/edit.(*Editor).ReadCode(0xc0001c42c0, 0xc00011e010, 0x13b73c8, 0xc0001e8960, 0xc000a90548)
    src.elv.sh/pkg/edit/editor.go:102 +0x33
src.elv.sh/pkg/shell.Interact(0xc00011e000, 0xc00011e008, 0xc00011e010, 0xc0001bdcb8)
    src.elv.sh/pkg/shell/interact.go:81 +0x4b0
src.elv.sh/pkg/shell.program.Run(0xc00011e000, 0xc00011e008, 0xc00011e010, 0xc0001a7490, 0xc00010a1d0, 0x0, 0x0, 0x1587740, 0xc00014df68)
    src.elv.sh/pkg/shell/shell.go:40 +0x2de
src.elv.sh/pkg/prog.Run(0xc00011e000, 0xc00011e008, 0xc00011e010, 0xc00010a1d0, 0x1, 0x1, 0xc00014df48, 0x3, 0x3, 0x0)
    src.elv.sh/pkg/prog/prog.go:136 +0x258
main.main()
    src.elv.sh/cmd/elvish/main.go:17 +0x11f

goroutine 34 [chan receive]:
src.elv.sh/pkg/eval.getBlackholeChan.func1(0xc000100120)
    src.elv.sh/pkg/eval/port.go:67 +0x47
created by src.elv.sh/pkg/eval.getBlackholeChan
    src.elv.sh/pkg/eval/port.go:66 +0x58

goroutine 36 [syscall]:
os/signal.signal_recv(0x13b9cf8)
    runtime/sigqueue.go:165 +0x9d
os/signal.loop()
    os/signal/signal_unix.go:23 +0x25
created by os/signal.Notify.func1.1
    os/signal/signal.go:151 +0x45

goroutine 38 [chan receive]:
src.elv.sh/pkg/shell.setupShell.func1(0xc0001208a0, 0xc00011e000, 0xc00011e008, 0xc00011e010)
    src.elv.sh/pkg/shell/shell.go:51 +0xa5
created by src.elv.sh/pkg/shell.setupShell
    src.elv.sh/pkg/shell/shell.go:50 +0xf9

goroutine 39 [chan receive]:
src.elv.sh/pkg/cli/prompt.(*Prompt).loop(0xc0001e20e0)
    src.elv.sh/pkg/cli/prompt/prompt.go:77 +0xc8
created by src.elv.sh/pkg/cli/prompt.New
    src.elv.sh/pkg/cli/prompt/prompt.go:70 +0x165

goroutine 40 [chan receive]:
src.elv.sh/pkg/cli/prompt.(*Prompt).loop(0xc0001e21c0)
    src.elv.sh/pkg/cli/prompt/prompt.go:77 +0xc8
created by src.elv.sh/pkg/cli/prompt.New
    src.elv.sh/pkg/cli/prompt/prompt.go:70 +0x165

goroutine 11975 [syscall]:
syscall.syscall6(0x10822c0, 0x4d49, 0xc000a0baf4, 0x0, 0xc0007a8090, 0x0, 0x0, 0x0, 0x0, 0x0)
    runtime/sys_darwin.go:41 +0x2e
syscall.wait4(0x4d49, 0xc000a0baf4, 0x0, 0xc0007a8090, 0x90, 0x1351d60, 0x1)
    syscall/zsyscall_darwin_amd64.go:44 +0x85
syscall.Wait4(0x4d49, 0xc000a0bb44, 0x0, 0xc0007a8090, 0x47, 0xc00050ca20, 0x6)
    syscall/syscall_bsd.go:144 +0x51
os.(*Process).wait(0xc000832000, 0x47, 0xc00050ca20, 0x6)
    os/exec_unix.go:43 +0x85
os.(*Process).Wait(...)
    os/exec.go:129
src.elv.sh/pkg/eval.externalCmd.Call(0xc000016550, 0x47, 0xc00074e0e0, 0xc0002b6000, 0x5, 0x8, 0xc000620360, 0xc000373800, 0xc000016410)
    src.elv.sh/pkg/eval/external_cmd.go:97 +0x365
src.elv.sh/pkg/eval.(*formOp).exec(0xc0005c3550, 0xc00074e0e0, 0x0, 0x0)
    src.elv.sh/pkg/eval/compile_effect.go:376 +0x9a2
src.elv.sh/pkg/eval.(*pipelineOp).exec.func1(0x13b7448, 0xc0005c3550, 0xc00074e0e0, 0xc000500600, 0xc0002340b0, 0xc000426c00)
    src.elv.sh/pkg/eval/compile_effect.go:117 +0x3f
created by src.elv.sh/pkg/eval.(*pipelineOp).exec
    src.elv.sh/pkg/eval/compile_effect.go:116 +0x225

goroutine 11976 [semacquire]:
sync.runtime_Semacquire(0xc0002340b8)
    runtime/sema.go:56 +0x45
sync.(*WaitGroup).Wait(0xc0002340b0)
    sync/waitgroup.go:130 +0x65
src.elv.sh/pkg/eval.(*pipelineOp).exec.func2(0xc0002340b0, 0xc00074e070, 0xc0005b2f40, 0xc000500600, 0x1, 0x1)
    src.elv.sh/pkg/eval/compile_effect.go:137 +0x45
created by src.elv.sh/pkg/eval.(*pipelineOp).exec
    src.elv.sh/pkg/eval/compile_effect.go:136 +0x29c

runtime error: invalid memory address or nil pointer dereference

Execing recovery shell /bin/sh
sh-3.2$

[krader1961]

@zzamboni, You should be a test engineer. Note that your reproduction only affects interactive shells. The non-interactive equivalent behaves as expected; i.e., no panic.

> ./elvish -c 'try { use bad } except x { put WTF $x }
                                                   bad:x'
▶ WTF
▶ [&reason=<unknown parse error: 25-25 in /Users/krader/.elvish/lib/bad.elv: should be ']'>]
Exception: exec: "bad:x": executable file not found in $PATH
code from -c, line 2:     bad:x
Exception: ./elvish exited with 2
[tty 224], line 1-2: ./elvish -c 'try { use bad } except x { put WTF $x }
                         bad:x'

TBD is why the interactive context mutates the global list of namespaces to include an invalid module while the non-interactive context does not.

[zzamboni]

@krader1961 interesting. With an example like yours, it indeed does not crash:

> elvish -c 'try { use test } except e { put $e }; test:x'
▶ [&reason=<unknown compilation error: 4-11 in /Users/taazadi1/.elvish/lib/test.elv: variable $foobar not found>]
Exception: exec: "test:x": executable file not found in $PATH
code from -c, line 1: try { use test } except e { put $e }; test:x
Exception: elvish exited with 2
[tty 2], line 1: elvish -c 'try { use test } except e { put $e }; test:x'

However, if I don't use try/except, I still get the crash even noninteractively:

> elvish -c 'e = ?(use test); put $e
                         test:x'
▶ [&reason=<unknown compilation error: 4-11 in /Users/taazadi1/.elvish/lib/test.elv: variable $foobar not found>]
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x20 pc=0x1255ee6]

goroutine 28 [running]:
src.elv.sh/pkg/eval.(*Ns).lookup(0x0, 0xc0000a90d5, 0x2, 0xc0000a49d8)
    src.elv.sh/pkg/eval/ns.go:101 +0x26
src.elv.sh/pkg/eval.(*Ns).IndexName(...)
    src.elv.sh/pkg/eval/ns.go:93
src.elv.sh/pkg/eval.deref(0xc0001be700, 0xc00008dbf0, 0xc000072ac0, 0x10cfb19)
    src.elv.sh/pkg/eval/var_ref.go:135 +0xd5
src.elv.sh/pkg/eval.variableOp.exec(0x18, 0x1e, 0x0, 0xc0000a90d7, 0x7, 0xc00008dbf0, 0xc0001be700, 0xc0000fdf70, 0x8, 0x1, ...)
    src.elv.sh/pkg/eval/compile_value.go:317 +0x4d
src.elv.sh/pkg/eval.evalForValue(0xc0001be700, 0x13b9bb8, 0xc00008dc20, 0x135abe2, 0x7, 0x7ffeefbff8c2, 0x4, 0xc0001c44d0, 0x1262ee5)
    src.elv.sh/pkg/eval/compile_value.go:577 +0x48
src.elv.sh/pkg/eval.evalForCommand(0xc0001be700, 0x13b9bb8, 0xc00008dc20, 0x135abe2, 0x7, 0x0, 0x0, 0x0, 0x0)
    src.elv.sh/pkg/eval/compile_effect.go:384 +0x74
src.elv.sh/pkg/eval.(*formOp).exec(0xc0000ae9a0, 0xc0001be700, 0x0, 0x0)
    src.elv.sh/pkg/eval/compile_effect.go:346 +0x609
src.elv.sh/pkg/eval.(*pipelineOp).exec.func1(0x13b7448, 0xc0000ae9a0, 0xc0001be700, 0xc0001ca030, 0xc0000a9150, 0x203000)
    src.elv.sh/pkg/eval/compile_effect.go:117 +0x3f
created by src.elv.sh/pkg/eval.(*pipelineOp).exec
    src.elv.sh/pkg/eval/compile_effect.go:116 +0x225
Exception: elvish exited with 2
[tty 1], line 1-2: elvish -c 'e = ?(use test); put $e
                   test:x'

[xiaq]

Hmm, the behavior is specific to interactive shells because a failed import would cause an exception and abort the surrounding block. In non-interactive cases this would normally cause the surrounding namespace to become inaccessible, so the broken variable doesn't matter (unless the exception is swallowed by ?(); you can construct a similar repro with it in a non-interactive script). The interactive case is different as the REPL will still pick up the broken variable.

I'll need to think a bit about how to best handle this.

[krader1961]

I'll need to think a bit about how to best handle this.

I spent a couple of hours using my (unmerged) trace package to understand the dynamics of this unexpected behavior in the hope I could identify an obvious fix. I failed to find a simple fix. ☹️

It's not clear this should be a blocking bug for the next point release. All bugs should be fixed ASAP but this is primarily a UI bug that few people (close to zero in my estimation) will ever notice.

[Xjs]

Not entirely sure if relevant, but I can trigger a crash in the same function (src.elv.sh/pkg/eval.(*Ns).lookup) by doing the following:

• Start an interactive shell
• Type the following commands:

str:split "abc" "b"
fail; use str # it appears necessary that the line fails in which an import is performed

Use the up arrow key twice to cycle back to the "str:split" command.

I can reliably reproduce a SIGSEGV panic with the following backtrace on df3e7a9268435d96b4432b517784e1358575ae3b:

panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x2 addr=0x20 pc=0x100f619c0]

goroutine 4591 [running]:
src.elv.sh/pkg/eval.(*Ns).lookup(0x0, 0x14000339cf8, 0x6, 0x6)
    /Users/jannis/src/github.com/elves/elvish/pkg/eval/ns.go:100 +0x20
src.elv.sh/pkg/eval.(*Ns).IndexName(...)
    /Users/jannis/src/github.com/elves/elvish/pkg/eval/ns.go:92
src.elv.sh/pkg/eval.(*Ns).Index(0x0, 0x1010458a0, 0x14000339d18, 0x100fb7ffd, 0x1, 0x14000339cf8)
    /Users/jannis/src/github.com/elves/elvish/pkg/eval/ns.go:80 +0x50
src.elv.sh/pkg/edit.hasFn(0x0, 0x1400015dc24, 0x5, 0x1)
    /Users/jannis/src/github.com/elves/elvish/pkg/edit/highlight.go:93 +0x7c
src.elv.sh/pkg/edit.hasQualifiedFn(0x1400015f450, 0x1400015dc20, 0x4, 0x1400015dc24, 0x5, 0x5)
    /Users/jannis/src/github.com/elves/elvish/pkg/edit/highlight.go:89 +0x16c
src.elv.sh/pkg/edit.hasCommand(0x1400015f450, 0x1400015dc20, 0x9, 0x14000235ec0)
    /Users/jannis/src/github.com/elves/elvish/pkg/edit/highlight.go:54 +0xe0
src.elv.sh/pkg/edit.initHighlighter.func2(0x1400015dc20, 0x9, 0x8)
    /Users/jannis/src/github.com/elves/elvish/pkg/edit/highlight.go:17 +0x38
src.elv.sh/pkg/edit/highlight.highlight.func1(0x14000235d80, 0x5, 0x8, 0x1400028c318, 0x1, 0x1, 0x14000189e80, 0x14000189e90, 0x14
    /Users/jannis/src/github.com/elves/elvish/pkg/edit/highlight/highlight.go:104 +0xac
created by src.elv.sh/pkg/edit/highlight.highlight
    /Users/jannis/src/github.com/elves/elvish/pkg/edit/highlight/highlight.go:100 +0x858

[zzamboni]

I can reproduce the panic described by @Xjs.

[~]|> elvish -buildinfo
Version: v0.16.0-dev.df3e7a9268435d96b4432b517784e1358575ae3b
Go version: go1.16.3
Reproducible build: true