add COFF (Windows) support to std/debug (stack traces)

[andrewrk]

Right now if you try to print a stack trace on windows, it prints "Stack trace not available for COFF"

These are super useful, especially now that we have error return tracing.

[andrewrk]

Depends on #516 (which will be resolved with llvm 6)

[andrewrk]

Working in the Sahnvour-windows-coff-issue721 branch, here's where I'm at right now @Sahnvour:

test.zig

test "crash" {
    @panic("boom");
}

output

c:\msys64\home\andy\zig\build-llvm6-msvc-release>bin\zig.exe test test.zig
Test 1/1 crash...boom
reading pe optional
skipping 106
loaded data directories
loaded 8 sections
file offset 6f430
cv_signature RSDS
pdb raw path c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\test.pdb
pdb resolved path C:\msys64\home\andy\zig\build-llvm6-msvc-release\zig-cache\test.pdb
magic: 'Microsoft C/C++ MSF 7.00
�DS   '
stream with blocks 102
stream count 18
stream 0B 0 blocks
stream 93B 1 blocks
stream 35940B 9 blocks
stream 9857B 3 blocks
stream 15420B 4 blocks
stream 0B 0 blocks
stream 320B 1 blocks
stream 5071B 2 blocks
stream 0B 0 blocks
stream 189896B 47 blocks
stream 18264B 5 blocks
stream 43108B 11 blocks
stream 720B 1 blocks
stream 4172B 2 blocks
stream 1740B 1 blocks
stream 2296B 1 blocks
stream 4296B 2 blocks
stream 31368B 8 blocks
stream with blocks
stream with blocks 7
stream with blocks 75 76 77 78 79 80 81 82 83
stream with blocks 72 73 74
stream with blocks 86 87 88 89
stream with blocks
stream with blocks 4
stream with blocks 5 6
stream with blocks
stream with blocks 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54
stream with blocks 55 56 57 58 59
stream with blocks 60 61 62 63 64 65 66 67 68 69 70
stream with blocks 71
stream with blocks 84 85
stream with blocks 90
stream with blocks 91
stream with blocks 92 93
stream with blocks 94 95 96 97 98 99 100 101
pdb real filepos 28672
v 20000404 s 1535582771 a 412
7ff6d5a43501 - 7ff6d59d0000 => 73501
DbiStreamHeader{ .VersionSignature = -1, .VersionHeader = 19990903, .Age = 412, .GlobalStreamIndex = 16, .BuildNumber = 0, .PublicStreamIndex = 15, .PdbDllVersion = 0, .SymRecordStream = 17, .PdbDllRbld = 0, .ModInfoSize = 712, .SectionContributionSize = 3756, .SectionMapSize = 184, .SourceInfoSize = 5020, .TypeServerSize = 0, .MFCTypeServerIndex = 65535, .OptionalDbgHeaderSize = 22, .ECSubstreamSize = 99, .Flags = 0, .Machine = 332, .Padding = 0 }
after header dbi stream at 294976 (file offset)
ModInfo{ .Unused1 = 0, .SectionContr = SectionContribEntry{ .Section = 0, .Padding1 =   , .Offset = 0, .Size = 0, .Characteristics = 0, .ModuleIndex = 0, .Padding2 =   , .DataCrc = 0, .RelocCrc = 0 }, .Flags = 0, .ModuleSymStream = 9, .SymByteSize = 91876, .C11ByteSize = 0, .C13ByteSize = 98016, .SourceFileCount = 23, .Padding =   , .Unused2 = 0, .SourceFileNameIndex = 0, .PdbFilePathNameIndex = 0 }
module_name c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\test.obj
obj_file_name c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\test.obj
ModInfo{ .Unused1 = 1, .SectionContr = SectionContribEntry{ .Section = 0, .Padding1 =   , .Offset = 0, .Size = 0, .Characteristics = 0, .ModuleIndex = 1, .Padding2 =   , .DataCrc = 0, .RelocCrc = 0 }, .Flags = 0, .ModuleSymStream = 10, .SymByteSize = 4776, .C11ByteSize = 0, .C13ByteSize = 13484, .SourceFileCount = 5, .Padding =   , .Unused2 = 0, .SourceFileNameIndex = 0, .PdbFilePathNameIndex = 0 }
module_name c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\builtin.obj
obj_file_name c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\builtin.obj
ModInfo{ .Unused1 = 131072, .SectionContr = SectionContribEntry{ .Section = 0, .Padding1 =   , .Offset = 0, .Size = 0, .Characteristics = 0, .ModuleIndex = 0, .Padding2 = � , .DataCrc = 0, .RelocCrc = 0 }, .Flags = 0, .ModuleSymStream = 0, .SymByteSize = 1189609483, .C11ByteSize = 0, .C13ByteSize = 1635254272, .SourceFileCount = 0, .Padding = � , .Unused2 = 0, .SourceFileNameIndex = 0, .PdbFilePathNameIndex = 0 }
module_name
obj_file_name
ModInfo{ .Unused1 = 1834760803, .SectionContr = SectionContribEntry{ .Section = 31091, .Padding1 = s6, .Offset = 1869110324, .Size = 1633445229, .Characteristics = 1551459438, .ModuleIndex = 27002, .Padding2 = g\, .DataCrc = 1818850658, .RelocCrc = 1819028836 }, .Flags = 28022, .ModuleSymStream = 11574, .SymByteSize = 1668707181, .C11ByteSize = 1818587693, .C13ByteSize = 1702060389, .SourceFileCount = 11868, .Padding = \z, .Unused2 = 1663919977, .SourceFileNameIndex = 1701340001, .PdbFilePathNameIndex = 1836016476 }
module_name piler_rt.obj
obj_file_name c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\compiler_rt.obj
ModInfo{ .Unused1 = 196608, .SectionContr = SectionContribEntry{ .Section = 0, .Padding1 =   , .Offset = 0, .Size = 0, .Characteristics = 0, .ModuleIndex = 0, .Padding2 = � , .DataCrc = 0, .RelocCrc = 0 }, .Flags = 0, .ModuleSymStream = 0, .SymByteSize = 46923788, .C11ByteSize = 0, .C13ByteSize = 0, .SourceFileCount = 0, .Padding =   , .Unused2 = 0, .SourceFileNameIndex = 0, .PdbFilePathNameIndex = 65536 }
module_name
obj_file_name
ModInfo{ .Unused1 = 1766596650, .SectionContr = SectionContribEntry{ .Section = 27502, .Padding1 = er, .Offset = 10784, .Size = -248595923, .Characteristics = 1, .ModuleIndex = 0, .Padding2 =   , .DataCrc = 25, .RelocCrc = 3225419904 }, .Flags = 0, .ModuleSymStream = 0, .SymByteSize = 0, .C11ByteSize = 0, .C13ByteSize = 1, .SourceFileCount = 28, .Padding =   , .Unused2 = 0, .SourceFileNameIndex = 3224371328, .PdbFilePathNameIndex = 1 }
module_name
obj_file_name
end modules

So this is getting a valid list of addresses from RtlCaptureStackBackTrace and then calling into the Pdb.getSourceLine function. What seems weird to me is that the Offset and Size in the SectionContribEntry are both zero. That should be how we figure out which module the address is in. It's weird because module_name and obj_file_name seem correct at first, which would indicate that the offsets are correct, but then it gets corrupted (and then fixed) for compiler_rt:

module_name piler_rt.obj
obj_file_name c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\compiler_rt.obj

(Indeed if you decode the last field before piler_rt.obj which is .PdbFilePathNameIndex = 1836016476 , it's actually the name string:

>>> hex(1836016476 )
'0x6d6f635c'
>>> [chr(x) for x in [0x6d, 0x6f, 0x63, 0x5c]]
['m', 'o', 'c', '\\']

I'll try auditing the Msf stream code and make sure that it is correctly reading the bytes.

[andrewrk]

Weird, I actually get an error from llvm-pdbutil:

c:\msys64\home\andy\zig\build-llvm6-msvc-release>"c:\Users\andy\llvm+clang-6.0.0-win64-msvc-release\bin\llvm-pdbutil.exe" dump zig-cache\test.exe
llvm-pdbutil: MSF Error: The data is in an unexpected format.  MSF magic header doesn't match

[andrewrk]

Oh, I probably am supposed to run that on the pdb file :-)

[andrewrk]

> pdb-dump.exe zig-cache\test.pdb
============================================================
  Mod 0000 | `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\test.obj`:
  Obj: `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\test.obj`:
  debug stream: 9, # files: 23, has ec info: false
  pdb file ni: 0 ``, src file ni: 0 ``
Mod 0001 | `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\builtin.obj`:
Obj: `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\builtin.obj`:
debug stream: 10, # files: 5, has ec info: false
pdb file ni: 0 ``, src file ni: 0 ``
Mod 0002 | `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\compiler_rt.obj`:
Obj: `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\compiler_rt.obj`:
debug stream: 11, # files: 30, has ec info: false
pdb file ni: 0 ``, src file ni: 0 ``
Mod 0003 | `* Linker *`:
Obj: ``:
debug stream: 12, # files: 0, has ec info: false
pdb file ni: 1 `c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\test.pdb`, src file ni: 0 ``

So the next step is getting zig's code to match this output. Zig is not correctly finding the offset for module 2.

[andrewrk]

I studied the MSF code and it looks fine.

There are 2 problems right now, where I am stuck:

• unable to correctly read all the module info stream
• the offset and size in the correctly read module info streams are 0, so how are we supposed to map address to module index?

I haven't tried to solve the second problem yet, but here's where I'm at with the first problem. This is debug output interspersed with my commentary:

seek 291291 read 1B: block_id=0 block=71 offset=475
seek 291292 read 1B: block_id=0 block=71 offset=476

These are printing the offsets that we read. The first value is the file offset. I pasted the output from the middle of parsing modules. Here we are at the end of finding the module name.

seek 291293 read 1B: block_id=0 block=71 offset=477
obj_file_name 'c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\builtin.obj'

Found the 0 byte. So next we read the ModInfo struct.

seek 291294 read 64B: block_id=0 block=71 offset=478
ModInfo{ .Unused1 = 131072, .SectionContr = SectionContribEntry{ .Section = 0, .Padding1 =   , .Offset = 0, .Size = 0, .Characteristics = 0, .ModuleIndex = 0, .Padding2 = � , .DataCrc = 0, .RelocCrc = 0 }, .Flags = 0, .ModuleSymStream = 0, .SymByteSize = 1189609483, .C11ByteSize = 0, .C13ByteSize = 1635254272, .SourceFileCount = 0, .Padding = � , .Unused2 = 0, .SourceFileNameIndex = 0, .PdbFilePathNameIndex = 0 }
seek 291358 read 1B: block_id=0 block=71 offset=542
module_name ''
seek 291359 read 1B: block_id=0 block=71 offset=543
obj_file_name ''

This ends up being bogus data. We read another ModInfo, but the offset is whack:

seek 291360 read 64B: block_id=0 block=71 offset=544
ModInfo{ .Unused1 = 1834760803, .SectionContr = SectionContribEntry{ .Section = 31091, .Padding1 = s6, .Offset = 1869110324, .Size = 1633445229, .Characteristics = 1551459438, .ModuleIndex = 27002, .Padding2 = g\, .DataCrc = 1818850658, .RelocCrc = 1819028836 }, .Flags = 28022, .ModuleSymStream = 11574, .SymByteSize = 1668707181, .C11ByteSize = 1818587693, .C13ByteSize = 1702060389, .SourceFileCount = 11868, .Padding = \z, .Unused2 = 1663919977, .SourceFileNameIndex = 1701340001, .PdbFilePathNameIndex = 1836016476 }
seek 291424 read 1B: block_id=0 block=71 offset=608
seek 291425 read 1B: block_id=0 block=71 offset=609
seek 291426 read 1B: block_id=0 block=71 offset=610
seek 291427 read 1B: block_id=0 block=71 offset=611
seek 291428 read 1B: block_id=0 block=71 offset=612
seek 291429 read 1B: block_id=0 block=71 offset=613
seek 291430 read 1B: block_id=0 block=71 offset=614
seek 291431 read 1B: block_id=0 block=71 offset=615
seek 291432 read 1B: block_id=0 block=71 offset=616
seek 291433 read 1B: block_id=0 block=71 offset=617
seek 291434 read 1B: block_id=0 block=71 offset=618
seek 291435 read 1B: block_id=0 block=71 offset=619
seek 291436 read 1B: block_id=0 block=71 offset=620
module_name 'piler_rt.obj'

The part where we read a null terminated string found the end of a module name. I added a hack to seek the stream back to the beginning of the ModInfo based on this data, which is why it says detected bad thing.

detected bad thing
seek 291296 read 64B: block_id=0 block=71 offset=480
ModInfo{ .Unused1 = 2, .SectionContr = SectionContribEntry{ .Section = 0, .Padding1 =   , .Offset = 0, .Size = 0, .Characteristics = 0, .ModuleIndex = 2, .Padding2 =   , .DataCrc = 0, .RelocCrc = 0 }, .Flags = 0, .ModuleSymStream = 11, .SymByteSize = 18152, .C11ByteSize = 0, .C13ByteSize = 24952, .SourceFileCount = 30, .Padding =   , .Unused2 = 0, .SourceFileNameIndex = 0, .PdbFilePathNameIndex = 0 }

This ends up being the correct module (see below)

seek 291360 read 1B: block_id=0 block=71 offset=544
seek 291361 read 1B: block_id=0 block=71 offset=545
seek 291362 read 1B: block_id=0 block=71 offset=546
seek 291363 read 1B: block_id=0 block=71 offset=547
seek 291364 read 1B: block_id=0 block=71 offset=548
seek 291365 read 1B: block_id=0 block=71 offset=549
seek 291366 read 1B: block_id=0 block=71 offset=550
seek 291367 read 1B: block_id=0 block=71 offset=551
seek 291368 read 1B: block_id=0 block=71 offset=552
seek 291369 read 1B: block_id=0 block=71 offset=553
seek 291370 read 1B: block_id=0 block=71 offset=554
seek 291371 read 1B: block_id=0 block=71 offset=555
seek 291372 read 1B: block_id=0 block=71 offset=556
seek 291373 read 1B: block_id=0 block=71 offset=557
seek 291374 read 1B: block_id=0 block=71 offset=558
seek 291375 read 1B: block_id=0 block=71 offset=559
seek 291376 read 1B: block_id=0 block=71 offset=560
seek 291377 read 1B: block_id=0 block=71 offset=561
seek 291378 read 1B: block_id=0 block=71 offset=562
seek 291379 read 1B: block_id=0 block=71 offset=563
seek 291380 read 1B: block_id=0 block=71 offset=564
seek 291381 read 1B: block_id=0 block=71 offset=565
seek 291382 read 1B: block_id=0 block=71 offset=566
seek 291383 read 1B: block_id=0 block=71 offset=567
seek 291384 read 1B: block_id=0 block=71 offset=568
seek 291385 read 1B: block_id=0 block=71 offset=569
seek 291386 read 1B: block_id=0 block=71 offset=570
seek 291387 read 1B: block_id=0 block=71 offset=571
seek 291388 read 1B: block_id=0 block=71 offset=572
seek 291389 read 1B: block_id=0 block=71 offset=573
seek 291390 read 1B: block_id=0 block=71 offset=574
seek 291391 read 1B: block_id=0 block=71 offset=575
seek 291392 read 1B: block_id=0 block=71 offset=576
seek 291393 read 1B: block_id=0 block=71 offset=577
seek 291394 read 1B: block_id=0 block=71 offset=578
seek 291395 read 1B: block_id=0 block=71 offset=579
seek 291396 read 1B: block_id=0 block=71 offset=580
seek 291397 read 1B: block_id=0 block=71 offset=581
seek 291398 read 1B: block_id=0 block=71 offset=582
seek 291399 read 1B: block_id=0 block=71 offset=583
seek 291400 read 1B: block_id=0 block=71 offset=584
seek 291401 read 1B: block_id=0 block=71 offset=585
seek 291402 read 1B: block_id=0 block=71 offset=586
seek 291403 read 1B: block_id=0 block=71 offset=587
seek 291404 read 1B: block_id=0 block=71 offset=588
seek 291405 read 1B: block_id=0 block=71 offset=589
seek 291406 read 1B: block_id=0 block=71 offset=590
seek 291407 read 1B: block_id=0 block=71 offset=591
seek 291408 read 1B: block_id=0 block=71 offset=592
seek 291409 read 1B: block_id=0 block=71 offset=593
seek 291410 read 1B: block_id=0 block=71 offset=594
seek 291411 read 1B: block_id=0 block=71 offset=595
seek 291412 read 1B: block_id=0 block=71 offset=596
seek 291413 read 1B: block_id=0 block=71 offset=597
seek 291414 read 1B: block_id=0 block=71 offset=598
seek 291415 read 1B: block_id=0 block=71 offset=599
seek 291416 read 1B: block_id=0 block=71 offset=600
seek 291417 read 1B: block_id=0 block=71 offset=601
seek 291418 read 1B: block_id=0 block=71 offset=602
seek 291419 read 1B: block_id=0 block=71 offset=603
seek 291420 read 1B: block_id=0 block=71 offset=604
seek 291421 read 1B: block_id=0 block=71 offset=605
seek 291422 read 1B: block_id=0 block=71 offset=606
seek 291423 read 1B: block_id=0 block=71 offset=607
seek 291424 read 1B: block_id=0 block=71 offset=608
seek 291425 read 1B: block_id=0 block=71 offset=609
seek 291426 read 1B: block_id=0 block=71 offset=610
seek 291427 read 1B: block_id=0 block=71 offset=611
seek 291428 read 1B: block_id=0 block=71 offset=612
seek 291429 read 1B: block_id=0 block=71 offset=613
seek 291430 read 1B: block_id=0 block=71 offset=614
seek 291431 read 1B: block_id=0 block=71 offset=615
seek 291432 read 1B: block_id=0 block=71 offset=616
seek 291433 read 1B: block_id=0 block=71 offset=617
seek 291434 read 1B: block_id=0 block=71 offset=618
seek 291435 read 1B: block_id=0 block=71 offset=619
seek 291436 read 1B: block_id=0 block=71 offset=620
module_name 'c:\msys64\home\andy\zig\build-llvm6-msvc-release\.\zig-cache\compiler_rt.obj'

At this point everything parses fine until the end of the module info stream. So here's the interesting part: the correct offset was 291296 but earlier we read 291294, just 2 bytes too early. But 291294 was directly after ObjFileName which is supposed to be a null terminated string. The null byte was at 291293. So how did we get to be 2 bytes too early?

I read the source code for llvm-pdbutil and it looks like it has the same logic as I have here in this branch - read the struct, read 2 null terminated strings. I don't see any code in there for alignment or padding.

[andrewrk]

I added this logic and it does work, but I'm confused since I don't see the equivalent in llvm-pdbutil or in the documentation:

            const march_forward_bytes = dbi.getFilePos() % 4;
            if (march_forward_bytes != 0) {
                try dbi.seekForward(march_forward_bytes);
                mod_info_offset += march_forward_bytes;
            }

Anyway if we run with this for now, we're down to this question:

• the offset and size in the correctly read module info streams are 0, so how are we supposed to map address to module index?

[andrewrk]

Mystery solved:

uint32_t DbiModuleDescriptor::getRecordLength() const {
  uint32_t M = ModuleName.str().size() + 1;
  uint32_t O = ObjFileName.str().size() + 1;
  uint32_t Size = sizeof(ModuleInfoHeader) + M + O;
  Size = alignTo(Size, 4);
  return Size;
}

So the length is 4 bytes aligned.

As for the other mystery, I think I solved that one too. The SectionContribEntry that is embedded in ModInfo is deprecated as far as I can tell. But after the Module Information Substream is the Section Contribution Substream which has all the offset info.

[andrewrk]

<zturner_> andrewrk: Try llvm-pdbutil dump -section-headers. The full COFF header of each section in the output file is embedded in the PDB. (Note that you could get this from the binary itself too by just parsing the COFF file). So if you have a runtime address, you first figure out which dll/exe that variable is in by enumerating process modules. subtract the base address of the module you find. that gives you the file address. then
<zturner_> you can either use the section headers in the corresponding PDB, or parsing that COFF file. Then you can figure out which section it's in. From there, you enumerate the section contribs in the PDB. The secnod field in the dump is something like 0005:9866. The first number is the section number. So you can build the section contrib table for each section this way, and finally map the address to the section contrib entry. And
<zturner_> then you have the module number
<zturner_> there might be a better way, that's what i'm coming up with at a cursory glance

[Sahnvour]

Glad you have zturner helping. I unfortunately do not have time to spend on this at the moment, and can only follow your progress. :(

[andrewrk]

No worries, thanks for getting me started!

[andrewrk]

Now, based on address, zig can find object name and function name. Next up, figure out how the CodeView line information in C13 format works. At this point the documentation does not exist and I'm left reading llvm source code.

[andrewrk]

This is starting to come together:

• based on an address zig can find out object name, function name, source file index, line number, and column number
• figure out what the 8 unknown bytes are before LineFragmentHeader
• the source file index maps to the checksum subsection, but I can't figure out where the checksum subsection stream is
• figure out where the /names stream is. It might be some complicated hash table thing, but maybe there's a simpler way. the checksum record will map into this string table which has the actual source file name
• colored formatted printing of the data
• clean up the code, rework it to make it perform better and more robustly

[Sahnvour]

Regarding the /names stream, its index should be in the PDB Stream which contains the map of named streams. But then as you noted documentation is lacking.
For the content of /names, you want to look at llvm::pdb::PDBStringTableBuilder.

[andrewrk]

It's all figured out now! Just need to re-arrange the code and pretty print it

[andrewrk]

It works!