Wrong debug info

[Sija]

Sometimes I'm seeing stacktraces with frames having wrong line (and possible column) numbers.
It seems to me there's some overflow going on (0 / 255 values).

Example stacktrace - notice column numbers with 0 and 255:

Can only invoke 'to_s' once on String::Builder (Exception)
  from /usr/local/Cellar/crystal/0.27.2/src/string/builder.cr:0:5 in 'to_s'
  from src/raven/processors/sanitize_data.cr:28:5 in 'sanitize_query_string'
  from src/raven/processors/sanitize_data.cr:68:11 in 'process'
  from src/raven/processors/sanitize_data.cr:45:21 in 'process'
  from src/raven/processors/sanitize_data.cr:56:9 in 'process'
  from src/raven/processors/sanitize_data.cr:45:21 in 'process'
  from src/raven/processors/sanitize_data.cr:56:9 in 'process'
  from src/raven/processors/sanitize_data.cr:45:21 in 'process'
  from spec/raven/processors/sanitize_data_spec.cr:259:7 in '->'
  from /usr/local/Cellar/crystal/0.27.2/src/spec/methods.cr:255:3 in 'it'
  from spec/raven/processors/sanitize_data_spec.cr:249:5 in '->'
  from /usr/local/Cellar/crystal/0.27.2/src/spec/context.cr:158:7 in 'describe'
  from /usr/local/Cellar/crystal/0.27.2/src/spec/methods.cr:16:5 in 'describe'
  from /usr/local/Cellar/crystal/0.27.2/src/spec/methods.cr:25:5 in 'context'
  from spec/raven/processors/sanitize_data_spec.cr:200:3 in '->'
  from /usr/local/Cellar/crystal/0.27.2/src/spec/context.cr:255:3 in 'describe'
  from /usr/local/Cellar/crystal/0.27.2/src/spec/methods.cr:16:5 in 'describe'
  from spec/raven/processors/remove_stacktrace_spec.cr:1:1 in '__crystal_main'
  from /usr/local/Cellar/crystal/0.27.2/src/crystal/main.cr:97:5 in 'main_user_code'
  from /usr/local/Cellar/crystal/0.27.2/src/crystal/main.cr:86:7 in 'main'
  from /usr/local/Cellar/crystal/0.27.2/src/crystal/main.cr:106:3 in 'main'

Tested with Crystal 0.27.2 and macOS 10.13.6.

[rdp]

still present? how to reproduce?

[ysbaddaden]

Can you check in gdb/lldb (add a breakpoint before the raise and then print the backtrack when execution stops) and report whether the line number is correct or zero?

First case means there is a bug in the dwarf decoder, zero means there is a bug in the debug information passed to llvm ir.

[RX14]

Is there a reproducible example?

[Sija]

I've reproduced it with kemal, perhaps there are other prerequisites.

[ysbaddaden]

It's quite easy to reproduce. I spot it from time to time but never gathered the courage to analyze it.

[Sija]

It might have sth to do with @[AlwaysInline] annotation 🤔

[rdp]

I just ran into this (linux, OS X is OK) see top line of this backtrace:

#7383 (comment)

[rdp]

OK I was asked to add some other "classes" of wrong debug info to this issue, so I guess it'll be a grab bag of sorts...

Here's one:

Here's how to repro. Linux ubuntu. From a crystal git repo:

diff --git a/src/socket.cr b/src/socket.cr
index fb25d63ae..3da6719cf 100644
--- a/src/socket.cr
+++ b/src/socket.cr
@@ -544,6 +544,7 @@ class Socket < IO
   end
 
   private def unbuffered_write(slice : Bytes)
+    raise "hello"
     evented_write(slice, "Error writing to socket") do |slice|
       LibC.send(@fd, slice, slice.size, 0)
     end

Use it somehow:

crystal$ ./bin/crystal  spec/std/openssl/ssl/socket_spec.cr
Unhandled exception in spawn: hello (Exception)
  from src/socket.cr:547:5 in 'unbuffered_write'
  from src/io/buffered.cr:135:14 in 'write'
  from src/openssl/bio.cr:31:7 in '->'
  from src/slice/sort.cr:147:5 in 'heapify!'
  from src/slice/sort.cr:153:10 in 'center_median!'
  from src/slice/sort.cr:204:0 in 'cmp'
  from src/slice/sort.cr:156:9 in 'center_median!'
  from ???
  from ???
  from ???
  from SSL_do_handshake
  from src/openssl/ssl/socket.cr:32:15 in 'initialize'
  from src/openssl/ssl/socket.cr:3:5 in 'new'
  from spec/std/openssl/ssl/socket_spec.cr:43:7 in '->'
  from src/fiber.cr:255:3 in 'run'
  from src/fiber.cr:47:34 in '->'
  from ???

Same trace, in gdb

$ gdb socket_spec
(gdb) b src/socket.cr:547
(gdb) r
(gdb) bt
#0  unbuffered_write () at /home/joshua/dev/crystal/src/socket.cr:547
#1  0x0000555555682c63 in write () at /home/joshua/dev/crystal/src/io/buffered.cr:135
#2  0x00005555555d5bb5 in -> () at /home/joshua/dev/crystal/src/openssl/bio.cr:31
#3  0x00007ffff7cfea33 in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
#4  0x00007ffff7cfeed3 in BIO_write () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
#5  0x00007ffff7cfd02a in ?? () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
#6  0x00007ffff7cff3a7 in BIO_ctrl () from /lib/x86_64-linux-gnu/libcrypto.so.1.1
#7  0x00007ffff7f6d3bd in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.1
#8  0x00007ffff7f71e0f in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.1
#9  0x00007ffff7f6c89a in ?? () from /lib/x86_64-linux-gnu/libssl.so.1.1
#10 0x00007ffff7f589c4 in SSL_do_handshake () from /lib/x86_64-linux-gnu/libssl.so.1.1
#11 0x00005555556b0890 in initialize () at /home/joshua/dev/crystal/src/openssl/ssl/socket.cr:32
#12 0x00005555556b06c9 in new () at /home/joshua/dev/crystal/src/openssl/ssl/socket.cr:3
#13 0x00005555555d78ad in -> () at /home/joshua/dev/crystal/spec/std/openssl/ssl/socket_spec.cr:43
#14 0x0000555555614123 in run () at /home/joshua/dev/crystal/src/fiber.cr:255
#15 0x00005555555d2c96 in -> () at /home/joshua/dev/crystal/src/fiber.cr:47
#16 0x0000000000000000 in ?? ()

Appears crystal is identifying some lines as part of the crystal std lib crystal files (heapify et al lines) that are actually part of a 3rd party library.

Or maybe this example is unrelated since it doesn't have the 255's? hmm

[rdp]

Also somewhat related: #8352

[rdp]

Possibly related? the question marks in the backtrace here: #8584

[rdp]

#9209 may have some clues. Does anybody have a way to repro this easily these days?

[rdp]

I'm hoping this was fixed in 2d02e52