1861359 - code_id/debug_id and version information mismatch is not detected and can lead to incorrect signatures

Status: NEW

(Socorro :: General, defect)

Description

[Yannis Juglaret [:yannis]]

Attachment: recover-stack.txt

As initially discovered by [:rkraesig], we seem to receive crash reports such as this one, where the module version information is not coherent with the Timestamp and ImageSize.

In this example, the version information stored in the crash dump matches with Firefox 115.0.3esr, but for some modules such as xul.dll the Timestamp and ImageSize are from 115.1.0esr. The mismatch is likely related to the way the updater updates our exe and dll files: xul.dll was most likely already in 115.1.0esr version on disk at the moment we crashed, however the version loaded in the process was 115.0.3esr, as we can confirm by looking for the correct stack for the main thread in a debugger (see attachment).

On Windows, debuggers rely on Timestamp and ImageSize to collect a DLL from a debug server before using it to walk the stacks of threads, using what Breakpad calls the code_id, which is derived from those. Presumably because of this mismatch, Socorro (and debuggers) currently incorrectly uses the 115.1.0esr version of the mismatched DLLs to parse the crash dump from above. As a consequence, these kind of crashes can end up in the wrong signature, and with the wrong proto signature (see attachment).

There are multiple questions here that would require their own investigation, and possibly their own bug:

1. How common is this situation?
2. Is it possible to rewrite the updater and/or the crash reporter to avoid this kind of mismatch? Can we preserve the information that the file on disk changed its version because it could be relevant for the investigation?
3. Can we add heuristics in the Socorro backend to detect this situation and try with the two versions of the DLL then guess which source of information seems more correct?
4. How can we adapt the Socorro webapp to warn about such mismatch?

Note that my own testing suggests that there could be situations where there is a mismatch and it is the code_id that is correct and not the version information. I obtained this example crash dump by forcing a crash after manually renaming xul.dll on disk while the 115.0.3esr process is running and putting version 115.1.0esr of the DLL in its place. In this dump, the situation is somehow reversed: the version information says 115.1.0esr but the TimeStamp and Signature shown by my debugger are correctly from 115.0.3esr. I'm not sure that my test matches how the updater works though, so maybe this situation does not happen with legit crashes.

Comment 1

[Yannis Juglaret [:yannis]]

(In reply to Yannis Juglaret [:yannis] from comment #0)

On Windows, debuggers rely on Timestamp and ImageSize to collect a DLL from a debug server before using it to walk the stacks of threads, using what Breakpad calls the code_id, which is derived from those.

Since we're talking about xul.dll I guess from looking at other bugs that we may be relying on the PDB GUID (aka debug_id) directly since it should be available, so this information is probably mismatched as well.

Comment 2

[Will Kahn-Greene [:willkg] ET needinfo? me]

If I understand this correctly, we can't do anything about this currently in Socorro, but I have some thoughts.

We could adjust dump_syms to capture module version (and maybe other information?) and add it as INFO lines in the symbols files.

We could then adjust the Symbols Server to capture that additional INFO information and put it in the db. We could expose that information in a Symbols Server API.

If I understand the problem correctly, once we have these two things done, it's possible to write a tool to investigate this issue more and get a feel for how often this happens and whether additional work is impactful. It would look at the version, code_file, and code_id fields in the module information for crash reports and determine whether there's a mismatch for the module.

If it is impactful, then we could then adjust the stackwalker to compare the version in the sym file to the version in the minidump modules list stream (I think that's where we're pulling the information from) and add something to the output when there's a mismatch.

Crash Stats could expose this information in the modules list on the report view and maybe other places, too. This would allow us to know "how often does this happen?" and "can we adapt the webapp to warn of the mismatch?" Further, we could then adjust Crash Stats so it would be able to know which symbol file goes with the version version and which symbol file goes with the module information goes with the code file/code id. That helps with debugging.

Then we could adjust the stackwalker allowing it to recognize the situation, acquire the two symbols files involved for the module in question, and do something better when unwinding and symbolicating the stack.

Does that sound roughly right? If so, this starts with a change to dump_syms and someone should write up an issue there.

Comment 9

[Gabriele Svelto [:gsvelto]]

(In reply to Will Kahn-Greene [:willkg] ET needinfo? me from comment #2)

We could adjust dump_syms to capture module version (and maybe other information?) and add it as INFO lines in the symbols files.

That's definitely possible

Comment 10

[Will Kahn-Greene [:willkg] ET needinfo? me]

I wrote up an issue in dump_syms: https://github.com/mozilla/dump_syms/issues/658

Once someone has implemented that and it lands in mozilla-central, I can write up an issue in Tecken to parse and store that information and then create an API around it.

Comment 11

[Will Kahn-Greene [:willkg] ET needinfo? me]

I think I can approximate looking at the prevalence of the problem by looking at processed crash data for crash reports with xul.dll/ED793C067BA95EFF4C4C44205044422E1 in the stack.

> supersearch --product=Firefox --num=all --modules_in_stack='xul.dll/ED793C067BA95EFF4C4C44205044422E1' \
    --date='>=2023-10-20' --date='<2023-10-27' > 1861359_crashids.txt

That yields 756 crash reports from the last 7 days.

I then downloaded the processed crash data and wrote a script to print out the module information:

import json
import os
import sys


def check_file(fn):
    with open(fn, "r") as fp:
        processed_crash = json.load(fp)

    uuid = processed_crash["uuid"]
    modules = processed_crash.get("json_dump", {}).get("modules", [])
    for module in modules:
        if not module["debug_file"] == "xul.pdb":
            continue

        print(
            f"{uuid}  {module['debug_file']}  {module['debug_id']} {module['version']}"
        )


def main():
    arg = sys.argv[1]

    for fn in os.listdir(arg):
        check_file(os.path.join(arg, fn))


if __name__ == "__main__":
    main()

Everything in that week has xul.pdb ED793C067BA95EFF4C4C44205044422E1 64be83267055000 115.1.0.8605.

The crash report yannis was looking at is from 2023-08-04. There are a lot more crash reports around that time with this module in the stack. I'll look at a sampling of those next.

Comment 12

[Yannis Juglaret [:yannis]]

The plan from comment 2 looks good to me as an outsider who has little idea how our crash infrastructure is implemented.

(In reply to Will Kahn-Greene [:willkg] ET needinfo? me from comment #11)

The crash report yannis was looking at is from 2023-08-04. There are a lot more crash reports around that time with this module in the stack. I'll look at a sampling of those next.

I think your script should do the job. The update from 115.0.3esr to 115.1.0esr coincides with the release of Firefox 116, so I would expect to find the highest amount of crashes with mismatches due to the updater to be somewhere between, say, 2023-07-31 and 2023-08-10 for this specific update.

Comment 13

[Will Kahn-Greene [:willkg] ET needinfo? me]

There's a lot of crash reports in that range, so I looked at just the ones on 2023-08-04. This is the list of crash reports that have mismatched module data:

e1247831-a7fb-4f6e-9aee-8aa670230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8607
c16c17e2-0e48-4fc9-bc13-c1b0d0230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8607
5413ae79-c59b-4416-9141-3aab50230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8607
092b307f-ca70-4e6c-9873-effff0230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8607
0446f240-491b-43fd-bd94-643640230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8607
3ff40580-9f29-4850-9325-b7d8e0230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8607
92d1bb82-33fe-4e9c-8e2f-c96ac0230804  xul.pdb  ED793C067BA95EFF4C4C44205044422E1  64be83267055000  115.0.3.8599
Total files checked: 13667

That's 7 out of 13,667.

I didn't check other days. I also didn't check other modules. I think that one is for Windows x86. Maybe the issue is more likely for other platform/architecture/whatever combinations?

Is this good enough? Are there other things we want to look at?

Comment 14

[Yannis Juglaret [:yannis]]

I thought this would be a Windows-only issue, but it seems that macOS is potentially a bit more affected, while Linux seems mostly immune.

Here is an experiment: choose a build id, and get the debug_id for xul for this build. Then list all crashes that have xul with this debug_id in modules in stack, and aggregate over build id. Sometimes, you will find that there are crash reports where the build id is not the expected one.

This gives less precise results than the methodology from comment 13 but it can be used on crash-stats directly, and can thus give an estimate of the dates where we should find the most mismatched crashes for a given build id (so we can later apply the methodology from comment 13).

Some examples:

• xul/d591692ab6c83b95a0d75fc1d1e0594e0 from 119.0 macOS x64 release appears in the stack of 49 crashes that have older build ids than 20231019122658, the majority (17) of those mismatched crashes were reported on 2023-10-27;
• xul/ac616d5c25ca382d9ce25b04105a22d40 from 119.0 macOS arm64 release appears in the stack of 49 crashes that have older build ids than 20231019122658, the majority (9) of those mismatched crashes were reported on 2023-10-25;
• xul.dll/1bc43681d14caaa74c4c44205044422e1 from 118.0.2 Windows x64 release appears in the stack of 19 crashes that have older build ids than 20231019122658, the majority (4) of those mismatched crashes were reported on 2023-10-17;
• xul.dll/569e0a6c6b88c1564c4c44205044422e1 from 115.4.0esr Windows x86 release appears in the stack of 25 crashes that have older build ids than 20231016232700, the majority (5) of those mismatched crashes were reported on 2023-10-25.

In summary, these mismatched crashes seem to coincide with update release dates, then they tend to disappear after that. They do not seem to represent a very significant part of our crash volume. It would be good to confirm that, by applying the methodology of comment 13 to the examples given above.

Also, here we are focusing on xul. This makes sense because that would be the biggest source of poorly bucketed crashes. However there could be crashes where there are mismatches in other modules but not in xul.

Comment 15

[Gabriele Svelto [:gsvelto]]

macOS is affected because of a known issue in how we read module information. Sometimes we find it in memory (then it's 100% coherent) but sometimes we have to fall back to whatever's on disk, and in that case it might be mismatched.