Debugger support

Hello everyone!

I am working on a Crystal debugger ( for macOS for now as I am macOS user and I use MacDBG as a source of inspiration and lldb/gdb is quite heavy in my opinion) and I have some question:
Is it me or line numbers information are generated incorrectly by LLVM, or may be DWARF decoder is not decoding that info incorrectly?

I modified a DWARF reader code from callstack.cr a little to create a DWARF reader so it generates log like this:

0x10fe897c0-0x10fe8986e (0xae): main
Lines:
        0x10fe897c0: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:84:0
        0x10fe897c8: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:85:5
        0x10fe897d3: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:0:5
        0x10fe897d7: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:35:5
        0x10fe897e3: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:86:7
        0x10fe897ec: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:39:9
        0x10fe897fd: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:0:9
        0x10fe89802: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:86:7
        0x10fe89804: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:0:7
        0x10fe89807: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:37:5
        0x10fe8980a: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:45:5
        0x10fe89813: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:0:5
        0x10fe89817: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:39:9
        0x10fe89825: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:45:5
        0x10fe89839: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:47:14
        0x10fe8983e: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:47:5
        0x10fe89849: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:48:5
        0x10fe8985a: /usr/local/Cellar/crystal/0.31.1/src/crystal/main.cr:49:5

which is somewhat correct aside of strange line number order, but what strange is this part:

0x10fd46160-0x10fd468bf (0x75f): __crystal_main
Lines:
        0x10fd46160: none:0:0
        0x10fd46186: /Users/sergey/Projects/crystal/crweb/src/crweb.cr:1:1
        0x10fd46192: /usr/local/Cellar/crystal/0.31.1/src/callstack.cr:30:3
        0x10fd461ac: /usr/local/Cellar/crystal/0.31.1/src/callstack.cr:36:12
        0x10fd461c6: /usr/local/Cellar/crystal/0.31.1/src/callstack.cr:42:3
        0x10fd461d2: /usr/local/Cellar/crystal/0.31.1/src/exception.cr:3:1
        0x10fd461e3: /usr/local/Cellar/crystal/0.31.1/src/iterator.cr:79:5
        0x10fd46202: /usr/local/Cellar/crystal/0.31.1/src/lib_c/x86_64-darwin/c/signal.cr:42:3
        0x10fd4621c: /usr/local/Cellar/crystal/0.31.1/src/lib_c/x86_64-darwin/c/signal.cr:43:3
        0x10fd46236: /usr/local/Cellar/crystal/0.31.1/src/string.cr:470:3
        0x10fd46250: /usr/local/Cellar/crystal/0.31.1/src/string.cr:483:3
        0x10fd4626a: /usr/local/Cellar/crystal/0.31.1/src/lib_c/x86_64-darwin/c/sys/mman.cr:12:3
        0x10fd46284: /usr/local/Cellar/crystal/0.31.1/src/fiber.cr:18:29
        0x10fd4629e: /usr/local/Cellar/crystal/0.31.1/src/file.cr:54:3
        0x10fd462b8: /usr/local/Cellar/crystal/0.31.1/src/float/printer/cached_powers.cr:51:3
        0x10fd462d2: /usr/local/Cellar/crystal/0.31.1/src/float/printer/cached_powers.cr:141:3
        0x10fd46317: /usr/local/Cellar/crystal/0.31.1/src/gc/boehm.cr:267:3
        0x10fd4631c: /usr/local/Cellar/crystal/0.31.1/src/crystal/hasher.cr:83:40
        0x10fd46355: /usr/local/Cellar/crystal/0.31.1/src/crystal/hasher.cr:83:3
        0x10fd46362: /usr/local/Cellar/crystal/0.31.1/src/kernel.cr:1:1
        0x10fd463c1: /usr/local/Cellar/crystal/0.31.1/src/kernel.cr:542:1
        0x10fd463dc: /usr/local/Cellar/crystal/0.31.1/src/humanize.cr:64:3
        0x10fd463f6: /usr/local/Cellar/crystal/0.31.1/src/process/executable_path.cr:12:3
. . . (cut for brevity)

it is all over the place and if I use hexdump to disassemble it it does not look that it is correct.

Can you give me some clues if I am doing it wrong?

Here is my class that is reading DWARF info (still ugly as I am experimenting with it):
require “./dwarf/op”
require “./dwarf/info”

module DWARF
    class Reader

        struct ProcEntry
            property low_pc       : UInt64
            property high_pc      : UInt64
            property func_name    : String
            property line_numbers : Array(Debug::DWARF::LineNumbers::Row)

            def initialize
                @low_pc = 0
                @high_pc = 0
                @func_name = ""
                @line_numbers = [] of Debug::DWARF::LineNumbers::Row
            end

            def initialize(@low_pc, @high_pc, @func_name)
                @line_numbers = [] of Debug::DWARF::LineNumbers::Row
            end

            def contains (addr)
                @low_pc <= addr && addr <= @high_pc
            end

            def addLine (line : Debug::DWARF::LineNumbers::Row)
                return if line.end_sequence
                line_numbers << line
            end

            def inspect (io : IO) : Void
                io << "0x#{@low_pc.to_s(16)}-0x#{@high_pc.to_s(16)} (0x#{(@high_pc - @low_pc).to_s(16)}): #{@func_name}\n"
                io << "\tLines:\n"
                @line_numbers.each do |line|
                    io << "\t\t0x#{(line.address).to_s(16)}: #{!line.directory.empty? ? line.directory + "/" +line.file : "none"}:#{line.line}:#{line.column}\n"
                end
            end
        end

        property dwarf_line_numbers : Array(Debug::DWARF::LineNumbers::Row)
        property strings : Debug::DWARF::Strings?
        property function_names : Array(ProcEntry)

        def self.open(filename)
            self.new(filename)
        end

        def initialize(filename)
            dwarf = File.open(filename, "r")
            @dwarf_macho = Debug::MachO.new(dwarf)
            @function_names = [] of ProcEntry
            @dwarf_line_numbers = [] of Debug::DWARF::LineNumbers::Row
        end

        def read(baseAddress)
            @dwarf_macho.read_section?("__debug_line") do |sh, io|
                line_numbers = Debug::DWARF::LineNumbers.new(io, sh.size)
                line_numbers.matrix.each do |row|
                    row.each do |subRow|
                        line = Debug::DWARF::LineNumbers::Row.new subRow.address - 0x100000000 + baseAddress,
                            subRow.op_index,
                            subRow.directory,
                            subRow.file,
                            subRow.line,
                            subRow.column,
                            subRow.end_sequence
                        dwarf_line_numbers << line
                    end
                end
            end
          
            @strings = @dwarf_macho.read_section?("__debug_str") do |sh, io|
              Debug::DWARF::Strings.new(io, sh.offset, sh.size)
            end
            
            @dwarf_macho.read_section?("__debug_info") do |sh, io|
              nameList = [] of String
          
              while (offset = io.pos - sh.offset) < sh.size
                info = DWARF::Info.new(io, offset)
          
                @dwarf_macho.read_section?("__debug_abbrev") do |sh, io|
                  info.read_abbreviations(io)
                end
          
                # pp! "===> Info: ", info
          
                parse_function_names_from_dwarf(info, baseAddress) do |low_pc, high_pc, name|
                    procEntry = ProcEntry.new low_pc, high_pc, name
                    dwarf_line_numbers.each do |line|
                        if procEntry.contains line.address
                            procEntry.addLine line
                        end
                    end
                    @function_names << procEntry
                end
              end
          
              puts "===> Function Names: #{function_names}"
            end
        end

        def parse_function_names_from_dwarf(info, baseAddress)
            info.each do |code, abbrev, attributes|
              next unless abbrev && abbrev.tag.subprogram?
              name = low_pc = high_pc = nil
        
        
              attributes.each do |(at, form, value)|
                puts "Attr: AT=#{at}, form=#{form}, value=#{form.strp? ? @strings.try(&.decode(value.as(UInt32 | UInt64))) : value}"
                case at
                when Debug::DWARF::AT::DW_AT_name
                  value = @strings.try(&.decode(value.as(UInt32 | UInt64))) if form.strp?
                  name = value.as(String)
                when Debug::DWARF::AT::DW_AT_low_pc
                  low_pc = value.as(LibC::SizeT) - 0x100000000 + baseAddress
                when Debug::DWARF::AT::DW_AT_high_pc
                  if form.addr?
                    high_pc = value.as(LibC::SizeT) - 0x100000000 + baseAddress
                  elsif value.responds_to?(:to_i)
                    high_pc = low_pc.as(LibC::SizeT) + value.to_i
                  end
                end
              end
        
              if low_pc && high_pc && name
                yield low_pc, high_pc, name
              end
            end
        end
    end
end
6 Likes

Welcome!

Yes, that’s most likely the issue: DWARF sections cannot be parsed properly · Issue #8352 · crystal-lang/crystal · GitHub

There might be other existing issues when parsing or generating the debug informatino.

Hey Ari!

I was quiet watcher and Crystal user for couple of years now so now is the time when I am become more active. I am planning to solve this debugger issue anyway as issue with debugging is slowing down the Crystal adoption and it drives me mad to use a lot of puts to debug around issue.

Do you mind if I will handle this debugging and DWARF issue?

I will need to modify some DWARF code to make it to work correctly. Also I will need to modify some of Mach-O / DWARF crystal libraries to work not only with File IO but also with Memory IO as I am reading Mach-O/DWARF info directly from the other process (that I am debugging) memory. For now I had just to copy/paste the MachO class and some of the Debug::DWARF classes.

7 Likes

Do you mind if I will handle this debugging and DWARF issue?

We would love it if you contributed this to Crystal! :heart_decoration:

4 Likes

Of course I will contribute! :slight_smile:

It can be done as builtin debugger. For now it will be macOS, and then I will implement Linux one.

3 Likes

The lack of debugging has really bitten me. I would love to have full debugging support.

5 Likes

Same here!
And I think that this is an adoption slowdown for the language itself which is a pity as I really enjoy the language as Ruby on Rails user since 2005. (I still miss custom operators that Swift has but hey! who knows may be it will be implemented as well ;) )

1 Like

At this moment my simple debugger is able to attach/detach to other process, read DWARF information out of that process, read and write into that process memory.
Next step is parse the variables from DWARF data and display them and then setting breakpoints.

3 Likes

I just Went through the llvm-ir code generated for that test program and !dbg statement looks correct.
That means bfd ld is either encode them incorrectly or it also uses the line ranges at the same time. I saw some of them in use:

@abbreviations=
[Debug::DWARF::Abbrev(
@attributes=
[Debug::DWARF::Abbrev::Attribute(@at=DW_AT_producer, @form=Strp),
Debug::DWARF::Abbrev::Attribute(@at=DW_AT_language, @form=Data2),
Debug::DWARF::Abbrev::Attribute(@at=DW_AT_name, @form=Strp),
Debug::DWARF::Abbrev::Attribute(@at=DW_AT_stmt_list, @form=SecOffset),
Debug::DWARF::Abbrev::Attribute(@at=DW_AT_comp_dir, @form=Strp),
Debug::DWARF::Abbrev::Attribute(@at=16353, @form=FlagPresent),
Debug::DWARF::Abbrev::Attribute(@at=DW_AT_low_pc, @form=Addr),
Debug::DWARF::Abbrev::Attribute(@at=DW_AT_ranges, @form=SecOffset)],
@children=true,
@code=1,
@tag=CompileUnit),
which is not used by Debug::DWARF::LineNumbers class

Actually I just rechecked more carefully generated LLVM-IR code and I found that bug is on IR level.
I was able to trace !dbg items with DIEs in DWARF and my log and they are identical. and in the same order. So I will trace it back to LLVM and codegen

So I am not lost. I figured out some stuff and rechecking some other.
I built llvm 9 with debug support and I am debugging lldb with one of my test crystal programs. I am checking line by line what may be wrong with crystal variables not being shown.

JetBrains CLion IDE rocks in this case!

It’s either being generated or parsed wrong, good luck on your hunt! :)

1 Like

Ok, here is some update:
After few days of deep debugging of lldb I found that variables will be shown only for languages that have type system implemented inside of LLDB. Here is the method that is defined in llvm/tools/lldb/source/Symbol/ClangASTContext.cpp:

ClangASTContextSupportsLanguage(lldb::LanguageType language) {
  return language == eLanguageTypeUnknown || // Clang is the default type system
         Language::LanguageIsC(language) ||
         Language::LanguageIsCPlusPlus(language) ||
         Language::LanguageIsObjC(language) ||
         Language::LanguageIsPascal(language) ||
         // Use Clang for Rust until there is a proper language plugin for it
         language == eLanguageTypeRust ||
         language == eLanguageTypeExtRenderScript ||
         // Use Clang for D until there is a proper language plugin for it
         language == eLanguageTypeD ||
         // Open Dylan compiler debug info is designed to be Clang-compatible
         language == eLanguageTypeDylan;
}

If we can have official LLDB language identifier then automatically we can have some rudimentary support ( I just changed language id from Crystal (0x8002) to C++ (0x4) and I was able to see the value of simple variables without any other changes. For member values we will have to implement proper TypeSystem subclass (language plugin).
I also considering if I can use Python scripting for custom commands to be able to extract this information in real time.
Source code for language plugins (C++,ClangCommon, Objective C, Objective C++) can be found in /llvm/tools/lldb/source/Plugins/Language (in case if you installed lldb into llvm project)

I am still considering to build my own debugger as it will give me much flexibility with the same amount of effort.

6 Likes

Ok. Here is some interesting tidbit.
If we set Debug Language ID to 0 (unknown language) it uses Clang( LLVM) type system and it gives us some good debug support for what we have for Crystal (for now though).

Here is my experiment with web server example (debug output):

Listening on http://127.0.0.1:3000
Process 26013 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 3.1
    frame #0: 0x00000001000ddde6 crweb`startHTTPServer(serverPort=<unavailable>) at crweb.cr:9:14
   6
   7
   8   	  def self.startHTTPServer (serverPort)
-> 9   	    server = HTTP::Server.new do |context|
   10  	      context.response.content_type = "text/plain"
   11  	      context.response.print "!"
   12  	    end
(lldb) var
(int) serverPort = <read memory from 0xdde1000000bb8 failed (0 of 4 bytes read)>

(HTTP::Server *) server = 0x0000000101083eb0
(lldb) p serverPort
error: Couldn't materialize: couldn't get the value of variable serverPort: read memory from 0xdde1000000bb8 failed (0 of 4 bytes read)
error: errored out in DoExecute, couldn't PrepareToExecuteJITExpression
(lldb) n
Process 26013 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = step over
    frame #0: 0x00000001000dddf6 crweb`startHTTPServer(serverPort=<unavailable>) at crweb.cr:14:5
   11  	      context.response.print "!"
   12  	    end
   13
-> 14  	    server.listen(serverPort)
   15  	  end
   16
   17  	  puts "PID=#{Process.pid}"
(lldb) p server
(HTTP::Server *) $2 = 0x0000000101080a20
(lldb) p *server
(HTTP::Server) $3 = {
  closed = false
  listening = false
  sockets = 0x0000000101080a00
  processor = 0x0000000101085380
}
(lldb) p *server.sockets
(Array(Socket::Server)) $4 = (size = 0, capacity = 0)
  Fix-it applied, fixed expression was:
    *server->sockets
(lldb) p *server->sockets
(Array(Socket::Server)) $5 = (size = 0, capacity = 0)
(lldb)

So with this level of debugger support it is already possible to do some useful stuff.

It is just two-liner fix. In src/compiler/crystal/codegen/debug.cr file add line:
UNKNOWN_LANG_DEBUG_IDENTIFIER = 0_u32

and in line 13 replace:
di_builder.create_compile_unit(CRYSTAL_LANG_DEBUG_IDENTIFIER, file, dir, "Crystal", false, "", 0_u32)
with:
di_builder.create_compile_unit(UNKNOWN_LANG_DEBUG_IDENTIFIER, file, dir, "Crystal", false, "", 0_u32)

There is still some issues that needs to be solved (will try to look at it) like in this example (pay attention to value of context variable):

  • thread #1, queue = ‘com.apple.main-thread’, stop reason = breakpoint 3.1
    frame #0: 0x00000001000dde2b crweb`->(context=0x00000000000000da) at crweb.cr:10:7
    7
    8 def self.startHTTPServer (serverPort)
    9 server = HTTP::Server.new do |context|
    → 10 context.response.content_type = “text/plain”
    11 context.response.print “!”
    12 end
    13

(lldb) po context
0x00000000000000da

(lldb) p context
(HTTP::Server::Context *) $3 = 0x00000000000000da
(lldb) p *context
error: Couldn’t apply expression side effects : Couldn’t dematerialize a result variable: couldn’t read its memory
(lldb)

5 Likes

Another interesting fact that I found: gdb 8.3 (installed on my MacBook with Homebrew and codesigned) is hangs up when I run it built with Crystal or C++ DWARF Debug Language IDs.
If the type is Unknown then it runs but it makes mistakes with identifying line numbers to run.
So if gdb works for you guys then I suspect it is better to use C++ language type for now so it will allow to use both debuggers.

This is awesome. I would love to see some of this work. Do you think this should move into a github issue?

Probably this is good idea.
I still trying to figure out how to solve issue with closure/block variables.
@asterite Ary may be you can help me with this. I am still not a big expert in the codegen. I did localized it (I hope) but if you can give me a clue where exactly closure/block variable generation is located, that will be great!
I hope I found it in codegen.cr:554 but I may be wrong.

@ComputerMage I think you might be looking for setup_closure_vars in fun.cr.

Do you know if it’s possible to start lldb with some plugin that could provide better Crystal support until we can build something worth submitting to become a well known language for it? (In case there is something more than registering the language id…)

2 Likes

This is what exactly I am trying to do. LLDB is pluginable. I am investigating if I can build LLDB type system plugin for Crystal on Crystal itself. IT will give me much more flexibility than to write it on C++ itself. I am long time C++ user (since 1990) and I am trying to avoid to use it if possible.
As long as we can expose types to LLDB expression engine and it will be able to eval it properly to specific address or register then we should be good.

If you want to build a C library from crystal you will need to deal with some initialization things of the runtime. Or avoid using part of the runtime. Relevant reference: https://github.com/crystal-lang/crystal/issues/921

1 Like