Crystal: Error running at_exit handler: Index out of bounds

[kostya]

require "spec"

it "work" do
  raise "bla"
end

in 0.24

Using compiled compiler at `.build/crystal'
E

Failures:

  1) work

       bla
Error running at_exit handler: Index out of bounds

[MakeNowJust]

On macOS high Sierra, crystal HEAD,

$ cat foo.cr
require "spec"

it "work" do
  raise "bla"
end

$ ./bin/crystal build foo.cr
$ rm foo.dwarf
$ ./foo
E

Failures:

  1) work

       bla
       ~procProc(Nil)@foo.cr:3
       it<String, String, Int32, Int32, &Proc(Nil)>:(Array(Spec::Result) | Nil)
       __crystal_main
       _crystal_main<Int32, Pointer(Pointer(UInt8))>:Nil
       Crystal::main_user_code<Int32, Pointer(Pointer(UInt8))>:Nil
       Crystal::main<Int32, Pointer(Pointer(UInt8))>:Int32
       main

Finished in 124 microseconds
1 examples, 0 failures, 1 errors, 0 pending

Failed examples:

crystal spec foo.cr:3 # work

So, I guess this issues comes from the error on decoding backtrace (at least related to DWARF).

[MakeNowJust]

Error happens on this line:

https://github.com/crystal-lang/crystal/blob/2e00b8f7a779cb52d6cd2b1295af52cb96611d93/src/debug/dwarf/line_numbers.cr#L363

[paulcsmith]

In case it is helpful, I also ran into this issue: https://gitter.im/crystal-lang/crystal?at=5a43f8815355812e572330d5

This line caused the problem: https://github.com/luckyframework/lucky/blob/a55bc0096b53fa30ddaa9e20b9fc5ee3b5fa5dfa/spec/lucky/log_handler_spec.cr#L41

It worked fine when I ran crystal spec --no-debug. I'm also on macOS High Sierra

[asterite]

How can we fix this? It's pretty severe. Every spec I run that fails, I get this error. I have to pass --no-debug to fix it. Do we know what's the problem?

[bew]

To know what the problem is we just need to replace this line: https://github.com/crystal-lang/crystal/blob/c168035853fe8ee9b06a22e5890414e5efa61776/src/kernel.cr#L141
by:

STDERR.print "Error running at_exit handler: "
handler_ex.inspect_with_backtrace STDERR

I was thinking PR-ing it after #5413 is merged, but it can definitely be done before if someone wants to!

[asterite]

Oh, it's an index out of bounds. My question is: why does it happen? Something wrong with dwarf decoding? Wrong line numbers being generated? Should we silently ignore this index of out bounds?

[bcardiff]

@asterite , @MakeNowJust share the offending line in https://github.com/crystal-lang/crystal/issues/5224#issuecomment-341078361 I haven't track down / workaround the issue. Maybe been defensive in the dwarf parsing, at least in that line, is a way to not crash.

Other than @ysbaddaden , I don't know someone that has dwarf format fresh enough to depic the bug in the code.

[ysbaddaden]

Not reproducible on Ubuntu Trusty.

The "index out of bounds" is unexpected: the file register must point to a valid index in the filenames table. Using a nilable getter wouldn't fix anything, but ignore the issue and set an unhelpful blank filename in file:line backtraces.

Possible causes:

1. Darwin only supports DWARF v2, but all other systems (except Android) generate DWARF v4, maybe there is a slight incompatibility. Unlikely, but may be a hint.
2. Maybe LLVM on OS X relies on the DW_LNE_define_file extended opcode which is a TODO: https://github.com/crystal-lang/crystal/blob/2e00b8f7a779cb52d6cd2b1295af52cb96611d93/src/debug/dwarf/line_numbers.cr#L274-L275 Somewhat unexpected as it increases complexity over the flat filename tables, but sounds probable. See http://dwarfstd.org/doc/dwarf-2.0.0.pdf section 6.2.5.3 for documentation. damn, doesn't seem to be the issue.

[ysbaddaden]

Can someone provide me with a macOS binary + .dwarf for the failing snippet?

[bcardiff]

@ysbaddaden foo.zip

$ crystal --version
Crystal 0.24.1 (2017-12-26)

LLVM: 5.0.1
Default target: x86_64-apple-macosx

$ crystal build foo.cr 

$ ./foo 
E

Failures:

  1) work

       bla
Error running at_exit handler: Index out of bounds

Yesterday I try to drill down a bit on this. Trying to reduce as well, nothing worth a sharing still.

[ysbaddaden]

Thanks, my Mach-O reader reproduces the issue.