Closed Bug 1765226 Opened 4 years ago Closed 4 years ago

Intermittent test_feature_fileioall.js | application crashed [@ `anonymous namespace'::InterposedNtWriteFile(void*, void*, void (*)(void*, _IO_STATUS_BLOCK*, unsigned long), void*, _IO_STATUS_BLOCK*, void*, unsigned long, _LARGE_INTEGER*, unsigned long*)]

Categories

(Core :: Gecko Profiler, defect, P1)

Product:
Core
Component:
Gecko Profiler
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
101 Branch
Project Flags:
Root Cause Coding: Concurrency Issue
Tracking Flags:
Tracking Status
firefox-esr91 --- wontfix
firefox99 --- wontfix
firefox100 --- wontfix
firefox101 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: mozbugz)

Details

(4 keywords, Whiteboard: [post-critsmash-triage][adv-main101+r])

Crash Data

Attachments

(1 file)

Bug 1765226 - Make ProfilerIOInterposeObserver a static object - r?florian
48 bytes, text/x-phabricator-request
Details | Review

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=374909535&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/MjF4VuCmQxaWR_RMLgEbsg/runs/0/artifacts/public/logs/live_backing.log

[task 2022-04-18T23:22:33.866Z] 23:22:33     INFO -  TEST-START | tools/profiler/tests/xpcshell/test_feature_java.js
[task 2022-04-18T23:22:33.866Z] 23:22:33     INFO -  TEST-SKIP | tools/profiler/tests/xpcshell/test_feature_java.js | took 0ms
[task 2022-04-18T23:22:39.163Z] 23:22:39  WARNING -  PROCESS-CRASH | tools/profiler/tests/xpcshell/test_feature_fileioall.js | application crashed [@ `anonymous namespace'::InterposedNtWriteFile(void*, void*, void (*)(void*, _IO_STATUS_BLOCK*, unsigned long), void*, _IO_STATUS_BLOCK*, void*, unsigned long, _LARGE_INTEGER*, unsigned long*)]
[task 2022-04-18T23:22:39.175Z] 23:22:39     INFO -  Crash dump filename: C:\Users\task_165032240308470\AppData\Local\Temp\xpc-other-r5pwq61_\f9cd28f9-60af-455d-87c3-a808c4783fb9.dmp
[task 2022-04-18T23:22:39.175Z] 23:22:39     INFO -  Operating system: Windows NT
[task 2022-04-18T23:22:39.175Z] 23:22:39     INFO -                    10.0.19041
[task 2022-04-18T23:22:39.175Z] 23:22:39     INFO -  CPU: amd64
[task 2022-04-18T23:22:39.176Z] 23:22:39     INFO -       family 6 model 85 stepping 7
[task 2022-04-18T23:22:39.176Z] 23:22:39     INFO -       8 CPUs
[task 2022-04-18T23:22:39.176Z] 23:22:39     INFO -  Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
[task 2022-04-18T23:22:39.176Z] 23:22:39     INFO -  Crash address: 0xffffffffffffffff
[task 2022-04-18T23:22:39.176Z] 23:22:39     INFO -  Process uptime: 0 seconds
[task 2022-04-18T23:22:39.176Z] 23:22:39     INFO -  Thread 1 IPC I/O Child (crashed)
[task 2022-04-18T23:22:39.177Z] 23:22:39     INFO -   0  xul.dll!`anonymous namespace'::InterposedNtWriteFile(void*, void*, void (*)(void*, _IO_STATUS_BLOCK*, unsigned long), void*, _IO_STATUS_BLOCK*, void*, unsigned long, _LARGE_INTEGER*, unsigned long*) [PoisonIOInterposerWin.cpp:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 359 + 0x5f]
[task 2022-04-18T23:22:39.177Z] 23:22:39     INFO -       rax = 0xe5e5e5e5e5e5e5e5    rdx = 0x0000007865dff278
[task 2022-04-18T23:22:39.177Z] 23:22:39     INFO -       rcx = 0x00007ffd3f07cc8c    rbx = 0x0000025ed4e03ce0
[task 2022-04-18T23:22:39.177Z] 23:22:39     INFO -       rsi = 0x00007ffd3f28c340    rdi = 0x0000025ed4e03ce8
[task 2022-04-18T23:22:39.178Z] 23:22:39     INFO -       rbp = 0x0000000000000000    rsp = 0x0000007865dff210
[task 2022-04-18T23:22:39.178Z] 23:22:39     INFO -        r8 = 0x0000007865dff288     r9 = 0x00007ffd520d6a10
[task 2022-04-18T23:22:39.178Z] 23:22:39     INFO -       r10 = 0x0000000000000001    r11 = 0x0000007865dff308
[task 2022-04-18T23:22:39.178Z] 23:22:39     INFO -       r12 = 0x0000000000000000    r13 = 0x0000025ed4e030e0
[task 2022-04-18T23:22:39.178Z] 23:22:39     INFO -       r14 = 0x0000025ed4e03dc0    r15 = 0x0000007865dff2a0
[task 2022-04-18T23:22:39.179Z] 23:22:39     INFO -       rip = 0x00007ffd3f07c5e1
[task 2022-04-18T23:22:39.179Z] 23:22:39     INFO -      Found by: given as instruction pointer in context
[task 2022-04-18T23:22:39.179Z] 23:22:39     INFO -   1  KERNELBASE.dll!WriteFile + 0xf9
[task 2022-04-18T23:22:39.179Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.180Z] 23:22:39     INFO -       rsp = 0x0000007865dff4c0    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.180Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.180Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd7448aada
[task 2022-04-18T23:22:39.180Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.181Z] 23:22:39     INFO -   2  xul.dll!IPC::Channel::ChannelImpl::OnIOCompleted(base::MessagePumpForIO::IOContext*, unsigned long, unsigned long) [ipc_channel_win.cc:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 590 + 0x153]
[task 2022-04-18T23:22:39.181Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.181Z] 23:22:39     INFO -       rsp = 0x0000007865dff530    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.181Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.181Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd3f098d7f
[task 2022-04-18T23:22:39.181Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.182Z] 23:22:39     INFO -   3  xul.dll!base::MessagePumpForIO::DoRunLoop() [message_pump_win.cc:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 423 + 0x238]
[task 2022-04-18T23:22:39.182Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.182Z] 23:22:39     INFO -       rsp = 0x0000007865dff730    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.182Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.183Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd3f097be4
[task 2022-04-18T23:22:39.183Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.183Z] 23:22:39     INFO -   4  xul.dll!base::MessagePumpWin::Run(base::MessagePump::Delegate*) [message_pump_win.h:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 79 + 0x54]
[task 2022-04-18T23:22:39.183Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.183Z] 23:22:39     INFO -       rsp = 0x0000007865dff8e0    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.184Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.184Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd3d6633a5
[task 2022-04-18T23:22:39.184Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.184Z] 23:22:39     INFO -   5  xul.dll!MessageLoop::RunHandler() [message_loop.cc:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 373 + 0x15]
[task 2022-04-18T23:22:39.184Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.185Z] 23:22:39     INFO -       rsp = 0x0000007865dff940    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.185Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.185Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd3e0339cf
[task 2022-04-18T23:22:39.185Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.185Z] 23:22:39     INFO -   6  xul.dll!base::Thread::ThreadMain() [thread.cc:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 187 + 0x45]
[task 2022-04-18T23:22:39.185Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.186Z] 23:22:39     INFO -       rsp = 0x0000007865dff990    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.186Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.186Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd3d662f37
[task 2022-04-18T23:22:39.186Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.186Z] 23:22:39     INFO -   7  xul.dll!`anonymous namespace'::ThreadFunc(void*) [platform_thread_win.cc:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 19 + 0xc]
[task 2022-04-18T23:22:39.187Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.187Z] 23:22:39     INFO -       rsp = 0x0000007865dffb70    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.187Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.187Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd3e0307d1
[task 2022-04-18T23:22:39.187Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.187Z] 23:22:39     INFO -   8  kernel32.dll!BaseThreadInitThunk + 0x13
[task 2022-04-18T23:22:39.188Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.188Z] 23:22:39     INFO -       rsp = 0x0000007865dffba0    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.188Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.188Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd75f17034
[task 2022-04-18T23:22:39.188Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.189Z] 23:22:39     INFO -   9  mozglue.dll!patched_BaseThreadInitThunk(int, void*, void*) [WindowsDllBlocklist.cpp:a1be0e0a7515604ac0a9bf5d08ac8cdb798867bc : 576 + 0x14]
[task 2022-04-18T23:22:39.189Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.189Z] 23:22:39     INFO -       rsp = 0x0000007865dffbd0    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.189Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.189Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd52140b38
[task 2022-04-18T23:22:39.189Z] 23:22:39     INFO -      Found by: call frame info
[task 2022-04-18T23:22:39.190Z] 23:22:39     INFO -  10  ntdll.dll!RtlUserThreadStart + 0x20
[task 2022-04-18T23:22:39.190Z] 23:22:39     INFO -       rbx = 0x0000025ed4e03ce0    rbp = 0x0000000000000000
[task 2022-04-18T23:22:39.190Z] 23:22:39     INFO -       rsp = 0x0000007865dffc40    r12 = 0x0000000000000000
[task 2022-04-18T23:22:39.190Z] 23:22:39     INFO -       r13 = 0x0000025ed4e030e0    r14 = 0x0000025ed4e03dc0
[task 2022-04-18T23:22:39.190Z] 23:22:39     INFO -       r15 = 0x0000007865dff2a0    rip = 0x00007ffd76aa2651
[task 2022-04-18T23:22:39.190Z] 23:22:39     INFO -      Found by: call frame info

The problem is that when stopping, the profiler unregisters its IOInterposeObserver and then deletes it (as part of ~ActivePS()); but another thread could be intercepting an IO, it may have just copied the list of observers before the unregistration, and afterwards calls a virtual method on the now-deleted observer.

I believe it would be difficult to exploit: Bad code would have to allocate an object with a dangerous pointer at just the right size & location & time, after running and stopping the Profiler with the optional FileIO feature, in the short time (if any) between the ActivePS destruction in one thread and the virtual call in another thread.
This code has been there since 2017 or even before. The test code that is now showing this issue was added in 2020. Assuming it hasn't triggered until now, it tells me that this sequence of events should be very rare.
Based on all this, I'm tentatively marking this as sec-low.

Daniel: In your opinion, is that an accurate rating? (Or please redirect NI to someone else.)

Fix:
Other observers are static, they always live long enough to avoid this issue, so I think the solution here would be to store one ProfilerIOInterposeObserver in a mozilla::StaticAutoPtr (like sLateWriteObserver).

Assignee: nobody → gsquelart
Severity: S4 → S3
Root Cause: --- → Coding: Concurrency Issue
Flags: needinfo?(dveditz)
Keywords: sec-low
Priority: -- → P1

I forgot to mention that my analysis in comment 1 was based on the dump file from that test failure, which helpfully gives a few more inline frames than visible in comment 0:

[Inline Frame] xul.dll!`anonymous namespace'::PerThreadData::CallObservers(mozilla::IOInterposeObserver::Observation & aObservation) Line 128
	at /builds/worker/checkouts/gecko/xpcom/build/IOInterposer.cpp(128)
[Inline Frame] xul.dll!mozilla::IOInterposer::Report(mozilla::IOInterposeObserver::Observation & aObservation) Line 477
	at /builds/worker/checkouts/gecko/xpcom/build/IOInterposer.cpp(477)
[Inline Frame] xul.dll!mozilla::IOInterposeObserver::Observation::Report() Line 384
	at /builds/worker/checkouts/gecko/xpcom/build/IOInterposer.cpp(384)
[Inline Frame] xul.dll!`anonymous namespace'::WinIOAutoObservation::~WinIOAutoObservation() Line 178
	at /builds/worker/checkouts/gecko/xpcom/build/PoisonIOInterposerWin.cpp(178)
xul.dll!`anonymous namespace'::InterposedNtWriteFile(void * aFileHandle, void * aEvent, void(*)(void *, _IO_STATUS_BLOCK *, unsigned long) aApc, void * aApcCtx, _IO_STATUS_BLOCK * aIoStatus, void * aBuffer, unsigned long aLength, _LARGE_INTEGER * aOffset, unsigned long * aKey) Line 359
	at /builds/worker/checkouts/gecko/xpcom/build/PoisonIOInterposerWin.cpp(359)
...

The leaf frame is where PerThreadData::CallObservers calls the virtual function on object pointers that were just copied a moment before.

Note that I could write the fix (make ProfilerIOInterposeObserver static) in a separate innocent-looking bug, saying that it's a performance improvement: No need to heap-allocate it every time.
Please let me know if that's worth pursuing.

I probably would have gone with sec-moderate, but in practice the risk of someone pulling it off would be extremely small because the victim would have to be profiling a malicious site doing just the right things. "low" works for me, too. This doesn't need a cover bug

Group: core-security → dom-core-security
Flags: needinfo?(dveditz)
Keywords: csectype-uaf

This removes some memory operations, and extends the observer's life.

Make ProfilerIOInterposeObserver a static object - r=florian
https://hg.mozilla.org/integration/autoland/rev/1d5bd0a6dedcada6d0ba6ce96cd7d174ba5c7ab3
https://hg.mozilla.org/mozilla-central/rev/1d5bd0a6dedc

Group: dom-core-security → core-security-release
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox101: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 101 Branch
Flags: qe-verify-
Whiteboard: [post-critsmash-triage]
Whiteboard: [post-critsmash-triage] → [post-critsmash-triage][adv-main101+r]

This fix landed in 101, and Firefox is now at release 102, so I've filed a small follow-up bug 1777391 to reduce the likelihood of this occurring again.

Group: core-security-release
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: