1665730 - Intermittent runner.py | application crashed [@ MessageLoop::DoWork()]

Status: RESOLVED DUPLICATE of bug 1665798

(Core :: Storage: IndexedDB, defect)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=315981550&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YLBAkKovSdupBThapn0LXg/runs/0/artifacts/public/logs/live_backing.log

---

>[task 2020-09-17T18:38:20.815Z] 18:38:20    ERROR -  PROCESS-CRASH | runner.py | application crashed [@ MessageLoop::DoWork()]
[task 2020-09-17T18:38:20.815Z] 18:38:20     INFO -  Crash dump filename: c:\users\task_1600366484\appdata\local\temp\tmp1pkgni\profile\minidumps\c55f5740-6135-4722-a57a-74c63cfba02d.dmp
[task 2020-09-17T18:38:20.816Z] 18:38:20     INFO -  Operating system: Windows NT
[task 2020-09-17T18:38:20.816Z] 18:38:20     INFO -                    10.0.17134
[task 2020-09-17T18:38:20.816Z] 18:38:20     INFO -  CPU: amd64
[task 2020-09-17T18:38:20.817Z] 18:38:20     INFO -       family 6 model 94 stepping 3
[task 2020-09-17T18:38:20.817Z] 18:38:20     INFO -       8 CPUs
[task 2020-09-17T18:38:20.817Z] 18:38:20     INFO -  GPU: UNKNOWN
[task 2020-09-17T18:38:20.817Z] 18:38:20     INFO -  Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
[task 2020-09-17T18:38:20.818Z] 18:38:20     INFO -  Crash address: 0xffffffff
[task 2020-09-17T18:38:20.818Z] 18:38:20     INFO -  Process uptime: 4 seconds
[task 2020-09-17T18:38:20.818Z] 18:38:20     INFO -  Thread 3 (crashed)
[task 2020-09-17T18:38:20.818Z] 18:38:20     INFO -   0  xul.dll!MessageLoop::DoWork() [message_loop.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 548 + 0x33]
[task 2020-09-17T18:38:20.819Z] 18:38:20     INFO -      rax = 0xe5e5e5e5e5e5e5e5   rdx = 0x00000225946c9040
[task 2020-09-17T18:38:20.819Z] 18:38:20     INFO -      rcx = 0x3e708a16fe460000   rbx = 0x0000009c9cdff850
[task 2020-09-17T18:38:20.819Z] 18:38:20     INFO -      rsi = 0x0000009c9cdff7f8   rdi = 0x00000225946c9040
[task 2020-09-17T18:38:20.819Z] 18:38:20     INFO -      rbp = 0x0000000000000000   rsp = 0x0000009c9cdff580
[task 2020-09-17T18:38:20.820Z] 18:38:20     INFO -       r8 = 0x0000000000000000    r9 = 0x0000022588914250
[task 2020-09-17T18:38:20.820Z] 18:38:20     INFO -      r10 = 0x00000fffb9983c38   r11 = 0x0100010000000000
[task 2020-09-17T18:38:20.820Z] 18:38:20     INFO -      r12 = 0x0000009c9cdff680   r13 = 0x00007ffdd2c4e374
[task 2020-09-17T18:38:20.820Z] 18:38:20     INFO -      r14 = 0x0000009c9cdff5b0   r15 = 0x0000009c9cdff5a8
[task 2020-09-17T18:38:20.820Z] 18:38:20     INFO -      rip = 0x00007ffdccc1e34a
[task 2020-09-17T18:38:20.821Z] 18:38:20     INFO -      Found by: given as instruction pointer in context
[task 2020-09-17T18:38:20.821Z] 18:38:20     INFO -   1  xul.dll!base::MessagePumpForIO::DoRunLoop() [message_pump_win.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 419 + 0x14]
[task 2020-09-17T18:38:20.821Z] 18:38:20     INFO -      rbx = 0x0000009c9cdff850   rbp = 0x0000000000000000
[task 2020-09-17T18:38:20.821Z] 18:38:20     INFO -      rsp = 0x0000009c9cdff620   r12 = 0x0000009c9cdff680
[task 2020-09-17T18:38:20.821Z] 18:38:20     INFO -      r13 = 0x00007ffdd2c4e374   r14 = 0x0000009c9cdff5b0
[task 2020-09-17T18:38:20.822Z] 18:38:20     INFO -      r15 = 0x0000009c9cdff5a8   rip = 0x00007ffdcdb618e1
[task 2020-09-17T18:38:20.822Z] 18:38:20     INFO -      Found by: call frame info
[task 2020-09-17T18:38:20.822Z] 18:38:20     INFO -   2  xul.dll!base::MessagePumpWin::Run(base::MessagePump::Delegate*) [message_pump_win.h:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 79 + 0x55]
[task 2020-09-17T18:38:20.822Z] 18:38:20     INFO -      rbx = 0x0000009c9cdff850   rbp = 0x0000000000000000
[task 2020-09-17T18:38:20.822Z] 18:38:20     INFO -      rsp = 0x0000009c9cdff6f0   r12 = 0x0000009c9cdff680
[task 2020-09-17T18:38:20.823Z] 18:38:20     INFO -      r13 = 0x00007ffdd2c4e374   r14 = 0x0000009c9cdff5b0
[task 2020-09-17T18:38:20.823Z] 18:38:20     INFO -      r15 = 0x0000009c9cdff5a8   rip = 0x00007ffdccc1e195
[task 2020-09-17T18:38:20.823Z] 18:38:20     INFO -      Found by: call frame info
[task 2020-09-17T18:38:20.823Z] 18:38:20     INFO -   3  xul.dll!MessageLoop::RunHandler() [message_loop.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 327 + 0x16]
[task 2020-09-17T18:38:20.823Z] 18:38:20     INFO -      rbx = 0x0000009c9cdff850   rbp = 0x0000000000000000
[task 2020-09-17T18:38:20.823Z] 18:38:20     INFO -      rsp = 0x0000009c9cdff750   r12 = 0x0000009c9cdff680
[task 2020-09-17T18:38:20.824Z] 18:38:20     INFO -      r13 = 0x00007ffdd2c4e374   r14 = 0x0000009c9cdff5b0
[task 2020-09-17T18:38:20.824Z] 18:38:20     INFO -      r15 = 0x0000009c9cdff5a8   rip = 0x00007ffdcdb6b1af
[task 2020-09-17T18:38:20.824Z] 18:38:20     INFO -      Found by: call frame info
[task 2020-09-17T18:38:20.824Z] 18:38:20     INFO -   4  xul.dll!base::Thread::ThreadMain() [thread.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 192 + 0x46]
[task 2020-09-17T18:38:20.824Z] 18:38:20     INFO -      rbx = 0x0000009c9cdff850   rbp = 0x0000000000000000
[task 2020-09-17T18:38:20.825Z] 18:38:20     INFO -      rsp = 0x0000009c9cdff7a0   r12 = 0x0000009c9cdff680
[task 2020-09-17T18:38:20.825Z] 18:38:20     INFO -      r13 = 0x00007ffdd2c4e374   r14 = 0x0000009c9cdff5b0
[task 2020-09-17T18:38:20.825Z] 18:38:20     INFO -      r15 = 0x0000009c9cdff5a8   rip = 0x00007ffdccc1c2a4
[task 2020-09-17T18:38:20.825Z] 18:38:20     INFO -      Found by: call frame info
[task 2020-09-17T18:38:20.826Z] 18:38:20     INFO -   5  xul.dll!`anonymous namespace'::ThreadFunc(void*) [platform_thread_win.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 19 + 0xd]
[task 2020-09-17T18:38:20.826Z] 18:38:20     INFO -      rbx = 0x0000009c9cdff850   rbp = 0x0000000000000000
[task 2020-09-17T18:38:20.826Z] 18:38:20     INFO -      rsp = 0x0000009c9cdff980   r12 = 0x0000009c9cdff680
[task 2020-09-17T18:38:20.826Z] 18:38:20     INFO -      r13 = 0x00007ffdd2c4e374   r14 = 0x0000009c9cdff5b0
[task 2020-09-17T18:38:20.826Z] 18:38:20     INFO -      r15 = 0x0000009c9cdff5a8   rip = 0x00007ffdcdb625f1
[task 2020-09-17T18:38:20.827Z] 18:38:20     INFO -      Found by: call frame info
[task 2020-09-17T18:38:20.827Z] 18:38:20     INFO -   6  kernel32.dll!RtlpLowFragHeapAllocFromContext + 0x204
[task 2020-09-17T18:38:20.827Z] 18:38:20     INFO -      rbx = 0x0000009c9cdff850   rbp = 0x0000000000000000
[task 2020-09-17T18:38:20.827Z] 18:38:20     INFO -      rsp = 0x0000009c9cdff9b0   r12 = 0x0000009c9cdff680
[task 2020-09-17T18:38:20.827Z] 18:38:20     INFO -      r13 = 0x00007ffdd2c4e374   r14 = 0x0000009c9cdff5b0
[task 2020-09-17T18:38:20.828Z] 18:38:20     INFO -      r15 = 0x0000009c9cdff5a8   rip = 0x00007ffe0b233034
[task 2020-09-17T18:38:20.828Z] 18:38:20     INFO -      Found by: call frame info```

Comment 1

[Andrew McCreight [:mccr8]]

This is a UAF based on rax = 0xe5e5e5e5e5e5e5e5.

Comment 2

[Andrew McCreight [:mccr8]]

Bug 1665798 got re-filed for this, but probably it is better to have a public bug to catch the occurrences and a private bug to discuss the crash.

Comment 3

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

So here's the crash site:

    7ffdccc1e337:	48 8d 4c 24 40       	lea    0x40(%rsp),%rcx
    7ffdccc1e33c:	48 89 fa             	mov    %rdi,%rdx
    7ffdccc1e33f:	45 31 c0             	xor    %r8d,%r8d
    7ffdccc1e342:	e8 49 66 a6 00       	callq  7ffdcd684990
    7ffdccc1e347:	48 8b 07             	mov    (%rdi),%rax
    7ffdccc1e34a:	48 8b 40 18          	mov    0x18(%rax),%rax

What is 7ffdcd684990? The xul.dll base is 0x7ffdccc10000, so that would be 0xa74990 in the breakpad symbols:

FUNC a74990 1dd 0 mozilla::LogTaskBase<nsIRunnable>::Run::Run(nsIRunnable*, bool)

So that places us at this virtual function call, trying to call through the vtable of task, which has been freed. (Or, not quite call — the address is compared to a known PC-relative address in what looks like PGO speculative inlining, but the fallback case also isn't the indirect call I expected; maybe that's also a side effect of PGO? But, given the context, this really looks like a vtable load.)

The freed object was refcounted and had a strong reference, so it shouldn't have been freed.

Are there any nsIRunnables with non-thread-safe refcounting, and could one of those have been sent to the IPC I/O thread?

Comment 4

[Andrew McCreight [:mccr8]]

As I said in the public bug, I'm going to try to do some retriggers to narrow down the regression range.

Comment 5

[Andrew McCreight [:mccr8]]

This seems to have gone away as quickly as it came, so I'm going to dupe it to the public bug.

FYI, Simon, some of your patches in bug 1663924 seem to have caused high frequency UAFs on TreeHerder.

Comment 6

[Simon Giesecke [:sg] [he/him]]

I am sorry for the trouble caused! (I wasn't aware a thing like this was going to happen, since at least I thought this was backed out before it reached central)

I think I identified the cause being somewhere around the thread_local use and have filed Bug 1666216 to enable this again once fixed.

It's worth noting that this seems to happen only under Windows, not under Linux or OS X.

Comment 7

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

I'm wondering if there's a pre-existing issue that was exposed by sg's patches changing the timing of a race condition, because I don't see how the MOZ_THREAD_LOCAL use in D90112 could cause this UAF.

Comment 8

[Simon Giesecke [:sg] [he/him]]

(In reply to Jed Davis [:jld] ⟨⏰|UTC-6⟩ ⟦he/him⟧ from comment #7)

I'm wondering if there's a pre-existing issue that was exposed by sg's patches changing the timing of a race condition, because I don't see how the MOZ_THREAD_LOCAL use in D90112 could cause this UAF.

That's a good question. Admittedly, I don't quite understand these strange/disastrous effects (UAF, massive raptor test regressions, test timeouts, etc. of these changes under Windows.

FWIW, I wasn't using MOZ_THREAD_LOCAL but rather native thread_local because the value type (std::map<const char*, nsCString>) is not trivial. Eventually we need to fix this (it's disabled during compilation as of D90112), but maybe we won't use a map but simply a fixed set of MOZ_THREAD_LOCAL(const char*) variables.