1767214 - Intermittent SUMMARY: AddressSanitizer: access-violation /builds/worker/workspace/obj-build/ipc/ipdl/PHandlerServiceChild.cpp:383 in mozilla::dom::PHandlerServiceChild::SendGetMIMEInfoFromOS

Status: RESOLVED FIXED

(Firefox :: File Handling, defect)

Description

[Treeherder Bug Filer]

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

---

INFO - TEST-START | toolkit/components/reader/test/browser_readerMode_remoteType.js
[task 2022-05-02T00:38:14.158Z] 00:38:14     INFO - GECKO(3056) | ###!!! [Parent][PBackgroundParent] Error: RunMessage(msgname=PRemoteWorkerService::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-05-02T00:38:14.743Z] 00:38:14     INFO - GECKO(3056) | =================================================================
[task 2022-05-02T00:38:14.748Z] 00:38:14    ERROR - GECKO(3056) | ==8616==ERROR: AddressSanitizer: access-violation on unknown address 0x000000000008 (pc 0x7ffd6c041b25 bp 0x00a6f4ffa380 sp 0x00a6f4ffa160 T0)
[task 2022-05-02T00:38:14.749Z] 00:38:14     INFO - GECKO(3056) | ==8616==The signal is caused by a READ memory access.
[task 2022-05-02T00:38:14.749Z] 00:38:14     INFO - GECKO(3056) | ==8616==Hint: address points to the zero page.
[task 2022-05-02T00:38:15.592Z] 00:38:15     INFO - GECKO(3056) | MEMORY STAT | vsize 19414314MB | vsizeMaxContiguous 66459177MB | residentFast 1005MB
[task 2022-05-02T00:38:15.598Z] 00:38:15     INFO - TEST-OK | toolkit/components/reader/test/browser_readerMode_remoteType.js | took 2320ms
[task 2022-05-02T00:38:15.601Z] 00:38:15     INFO - GECKO(3056) | ==8616==WARNING: Failed to use and restart external symbolizer!
[task 2022-05-02T00:38:15.630Z] 00:38:15     INFO - checking window state
[task 2022-05-02T00:38:15.665Z] 00:38:15     INFO - GECKO(3056) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-05-02T00:38:15.678Z] 00:38:15     INFO - TEST-START | toolkit/components/reader/test/browser_readerMode_with_anchor.js
[task 2022-05-02T00:38:16.115Z] 00:38:16     INFO - GECKO(3056) |     #0 0x7ffd6c041b24 in mozilla::dom::PHandlerServiceChild::SendGetMIMEInfoFromOS /builds/worker/workspace/obj-build/ipc/ipdl/PHandlerServiceChild.cpp:383
[task 2022-05-02T00:38:16.125Z] 00:38:16     INFO - GECKO(3056) |     #1 0x7ffd6c041631 in mozilla::dom::ContentHandlerService::GetMIMEInfoFromOS /builds/worker/checkouts/gecko/uriloader/exthandler/ContentHandlerService.cpp:174
[task 2022-05-02T00:38:16.126Z] 00:38:16     INFO - GECKO(3056) |     #2 0x7ffd6c083734 in nsOSHelperAppServiceChild::GetMIMEInfoFromOS /builds/worker/checkouts/gecko/uriloader/exthandler/nsOSHelperAppServiceChild.cpp:94
[task 2022-05-02T00:38:16.126Z] 00:38:16     INFO - GECKO(3056) |     #3 0x7ffd6c078370 in nsExternalHelperAppService::GetMIMETypeFromOSForExtension /builds/worker/checkouts/gecko/uriloader/exthandler/nsExternalHelperAppService.cpp:3474
[task 2022-05-02T00:38:16.127Z] 00:38:16     INFO - GECKO(3056) |     #4 0x7ffd6c0755ab in nsExternalHelperAppService::GetTypeFromExtension /builds/worker/checkouts/gecko/uriloader/exthandler/nsExternalHelperAppService.cpp:3254
[task 2022-05-02T00:38:16.127Z] 00:38:16     INFO - GECKO(3056) |     #5 0x7ffd6be5fcf2 in nsJARChannel::GetContentTypeGuess /builds/worker/checkouts/gecko/modules/libjar/nsJARChannel.cpp:748
[task 2022-05-02T00:38:16.128Z] 00:38:16     INFO - GECKO(3056) |     #6 0x7ffd6be5bcf7 in nsJARChannel::OpenLocalFile /builds/worker/checkouts/gecko/modules/libjar/nsJARChannel.cpp:394
[task 2022-05-02T00:38:16.128Z] 00:38:16     INFO - GECKO(3056) |     #7 0x7ffd6be60cf5 in nsJARChannel::AsyncOpen /builds/worker/checkouts/gecko/modules/libjar/nsJARChannel.cpp:1098
[task 2022-05-02T00:38:16.129Z] 00:38:16     INFO - GECKO(3056) |     #8 0x7ffd734579f1 in mozilla::dom::XMLHttpRequestMainThread::InitiateFetch /builds/worker/checkouts/gecko/dom/xhr/XMLHttpRequestMainThread.cpp:2725
[task 2022-05-02T00:38:16.130Z] 00:38:16     INFO - GECKO(3056) |     #9 0x7ffd7345d380 in mozilla::dom::XMLHttpRequestMainThread::SendInternal /builds/worker/checkouts/gecko/dom/xhr/XMLHttpRequestMainThread.cpp:3022
[task 2022-05-02T00:38:16.130Z] 00:38:16     INFO - GECKO(3056) |     #10 0x7ffd7345b62c in mozilla::dom::XMLHttpRequestMainThread::Send /builds/worker/checkouts/gecko/dom/xhr/XMLHttpRequestMainThread.cpp:2818
[task 2022-05-02T00:38:16.131Z] 00:38:16     INFO - GECKO(3056) |     #11 0x7ffd7346de90 in mozilla::dom::SendRunnable::RunOnMainThread /builds/worker/checkouts/gecko/dom/xhr/XMLHttpRequestWorker.cpp:1325
[task 2022-05-02T00:38:16.132Z] 00:38:16     INFO - GECKO(3056) |     #12 0x7ffd7346d334 in mozilla::dom::WorkerThreadProxySyncRunnable::MainThreadRun /builds/worker/checkouts/gecko/dom/xhr/XMLHttpRequestWorker.cpp:1190
[task 2022-05-02T00:38:16.132Z] 00:38:16     INFO - GECKO(3056) |     #13 0x7ffd72f7938e in mozilla::dom::WorkerMainThreadRunnable::Run /builds/worker/checkouts/gecko/dom/workers/WorkerRunnable.cpp:588
[task 2022-05-02T00:38:16.133Z] 00:38:16     INFO - GECKO(3056) |     #14 0x7ffd6a5034d2 in mozilla::ThrottledEventQueue::Inner::ExecuteRunnable /builds/worker/checkouts/gecko/xpcom/threads/ThrottledEventQueue.cpp:254
[task 2022-05-02T00:38:16.134Z] 00:38:16     INFO - GECKO(3056) |     #15 0x7ffd6a502ea3 in mozilla::ThrottledEventQueue::Inner::Executor::Run /builds/worker/checkouts/gecko/xpcom/threads/ThrottledEventQueue.cpp:81
[task 2022-05-02T00:38:16.134Z] 00:38:16     INFO - GECKO(3056) |     #16 0x7ffd6a4feaed in mozilla::RunnableTask::Run /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:467
[task 2022-05-02T00:38:16.135Z] 00:38:16     INFO - GECKO(3056) |     #17 0x7ffd6a4b5471 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:780
[task 2022-05-02T00:38:16.136Z] 00:38:16     INFO - GECKO(3056) |     #18 0x7ffd6a4b198c in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:612
[task 2022-05-02T00:38:16.136Z] 00:38:16     INFO - GECKO(3056) |     #19 0x7ffd6a4b236e in mozilla::TaskController::ProcessPendingMTTask /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:390
[task 2022-05-02T00:38:16.137Z] 00:38:16     INFO - GECKO(3056) |     #20 0x7ffd6a509cc1 in mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:127:7'>::Run /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:531
[task 2022-05-02T00:38:16.138Z] 00:38:16     INFO - GECKO(3056) |     #21 0x7ffd6a4e1365 in nsThread::ProcessNextEvent /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1180
[task 2022-05-02T00:38:16.138Z] 00:38:16     INFO - GECKO(3056) |     #22 0x7ffd6a4efc7c in NS_ProcessNextEvent /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:465
[task 2022-05-02T00:38:16.139Z] 00:38:16     INFO - GECKO(3056) |     #23 0x7ffd6a4dec6d in nsThread::Shutdown /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:875
INFO - GECKO(3056) |     #24 0x7ffd71699dcd in mozilla::RemoteDecoderManagerChild::Shutdown /builds/worker/checkouts/gecko/dom/media/ipc/RemoteDecoderManagerChild.cpp:162
[task 2022-05-02T00:38:16.140Z] 00:38:16     INFO - GECKO(3056) |     #25 0x7ffd716999b8 in mozilla::ShutdownObserver::Observe /builds/worker/checkouts/gecko/dom/media/ipc/RemoteDecoderManagerChild.cpp:78
[task 2022-05-02T00:38:16.141Z] 00:38:16     INFO - GECKO(3056) |     #26 0x7ffd6a33b25c in nsObserverList::NotifyObservers /builds/worker/checkouts/gecko/xpcom/ds/nsObserverList.cpp:70
[task 2022-05-02T00:38:16.142Z] 00:38:16     INFO - GECKO(3056) |     #27 0x7ffd6a352f3c in nsObserverService::NotifyObservers /builds/worker/checkouts/gecko/xpcom/ds/nsObserverService.cpp:292
[task 2022-05-02T00:38:16.142Z] 00:38:16     INFO - GECKO(3056) |     #28 0x7ffd6a223670 in mozilla::AdvanceShutdownPhaseInternal /builds/worker/checkouts/gecko/xpcom/base/AppShutdown.cpp:345
[task 2022-05-02T00:38:16.143Z] 00:38:16     INFO - GECKO(3056) |     #29 0x7ffd6a580243 in mozilla::ShutdownXPCOM /builds/worker/checkouts/gecko/xpcom/build/XPCOMInit.cpp:623
[task 2022-05-02T00:38:16.144Z] 00:38:16     INFO - GECKO(3056) |     #30 0x7ffd78311e80 in XRE_TermEmbedding /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:226
[task 2022-05-02T00:38:16.144Z] 00:38:16     INFO - GECKO(3056) |     #31 0x7ffd6bb04218 in mozilla::ipc::ScopedXREEmbed::Stop /builds/worker/checkouts/gecko/ipc/glue/ScopedXREEmbed.cpp:90
[task 2022-05-02T00:38:16.145Z] 00:38:16     INFO - GECKO(3056) |     #32 0x7ffd78312eb3 in XRE_InitChildProcess /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:740
[task 2022-05-02T00:38:16.146Z] 00:38:16     INFO - GECKO(3056) |     #33 0x7ff7ab4120ac in NS_internal_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:327
[task 2022-05-02T00:38:16.146Z] 00:38:16     INFO - GECKO(3056) |     #34 0x7ff7ab4117bf in wmain /builds/worker/checkouts/gecko/toolkit/xre/nsWindowsWMain.cpp:167
[task 2022-05-02T00:38:16.147Z] 00:38:16     INFO - GECKO(3056) |     #35 0x7ff7ab50c297 in __scrt_common_main_seh d:\agent\_work\2\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
[task 2022-05-02T00:38:16.148Z] 00:38:16     INFO - GECKO(3056) |     #36 0x7ffdb1b17033 in BaseThreadInitThunk+0x13 (C:\Windows\System32\KERNEL32.DLL+0x180017033)
[task 2022-05-02T00:38:16.148Z] 00:38:16     INFO - GECKO(3056) |     #37 0x7ffdb3b02650 in RtlUserThreadStart+0x20 (C:\Windows\SYSTEM32\ntdll.dll+0x180052650)
[task 2022-05-02T00:38:16.149Z] 00:38:16     INFO - GECKO(3056) | AddressSanitizer can not provide additional info.
[task 2022-05-02T00:38:16.150Z] 00:38:16     INFO - GECKO(3056) | SUMMARY: AddressSanitizer: access-violation /builds/worker/workspace/obj-build/ipc/ipdl/PHandlerServiceChild.cpp:383 in mozilla::dom::PHandlerServiceChild::SendGetMIMEInfoFromOS
[task 2022-05-02T00:38:16.150Z] 00:38:16     INFO - GECKO(3056) | ==8616==ABORTING
[task 2022-05-02T00:38:16.863Z] 00:38:16     INFO - GECKO(3056) | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-05-02T00:38:17.997Z] 00:38:17     INFO - GECKO(3056) | JavaScript error: resource://gre/actors/ContentMetaChild.jsm, line 179: InvalidStateError: JSWindowActorChild.sendAsyncMessage: JSWindowActorChild cannot send at the moment
[task 2022-05-02T00:38:18.030Z] 00:38:18     INFO - GECKO(3056) | MEMORY STAT | vsize 19414314MB | vsizeMaxContiguous 66459177MB | residentFast 1006MB
[task 2022-05-02T00:38:18.041Z] 00:38:18     INFO - TEST-OK | toolkit/components/reader/test/browser_readerMode_with_anchor.js | took 2363ms

Comment 1

[Andrew McCreight [:mccr8]]

Null deref. Maybe mHandlerServiceChild is null?

Comment 2

[:Gijs (he/him)]

(In reply to Andrew McCreight [:mccr8] from comment #1)

Null deref. Maybe mHandlerServiceChild is null?

Can you elaborate on what's happening here? AFAICT the only way this could be null is if we've somehow run the destructor but are still calling into this object (so the issue would presumably be a UAF of PHandlerServiceChild) or if the construction failed ( https://searchfox.org/mozilla-central/rev/ea1234192518e01694a88eac8ff090e4cadf5ca4/uriloader/exthandler/ContentHandlerService.cpp#34 ) which according to coverage data never happens.

We can sprinkle nullchecks all over the thing but that seems bad. :-(

Comment 3

[Andrew McCreight [:mccr8]]

From the stack, it looks like we're spinning the event loop during thread shutdown. It is possible that something is trying to initialize the handler service very late in shutdown beyond the point where we can send IPC messages, which would cause that. We have a lot of weird shutdown races right now due to things like that. Maybe Init() should fail if it doesn't create the handle service child? Jens might have some suggestions.

Comment 4

[Jens Stutte [:jstutte]]

I assume when nsOSHelperAppServiceChild::GetMIMEInfoFromOS wants to get the handler service, it is late and
cpc->SendPHandlerServiceConstructor(mHandlerServiceChild) fails, leaving mHandlerServiceChild nullptr without reporting an error. This seems odd and should be changed.

However, to avoid this error situation, we should probably understand why we want to run XHR such late in shutdown. The runnable that causes this seems to be SendRunnable which causes the JAR access and then the MIME lookup.

I think, we could check the shutdown state inside dom::WorkerMainThreadRunnable::Run because we should not dispatch any more messages to threads in or after XPCOMShutdownThreads.

Comment 5

[Jens Stutte [:jstutte]]

(In reply to Jens Stutte [:jstutte] from comment #4)

I think, we could check the shutdown state inside dom::WorkerMainThreadRunnable::Run because we should not dispatch any more messages to threads in or after XPCOMShutdownThreads.

:asuth, WDYT ?

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

(In reply to Jens Stutte [:jstutte] from comment #5)

:asuth, WDYT ?

Based on our investigation just now, it does look like our logic at xpcom-shutdown should establish a barrier where we cancel all already-extant top-level workers and set a flag so no new ones can be launched, so the low hanging fruit here for stopping whatever this worker earlier is already dealt with. So, yeah, this seems like a reasonable additional backstop to help make shutdown more aggressive. Maybe add a comment like "this shouldn't be necessary once we're better about making sure no workers are created during shutdown in earlier phases".

Comment 7

[Jens Stutte [:jstutte]]

Attachment: Bug 1767214: Make ContentHandlerService::Init return an error on failed initialization. r?smaug

Comment 8

[Jens Stutte [:jstutte]]

Attachment: Bug 1767214: Avoid executing WorkerMainThreadRunnable::Run late in shutdown. r?#dom-worker-reviewers

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8fc571b48c67
Make ContentHandlerService::Init return an error on failed initialization. r=smaug

Comment 10

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/8fc571b48c67

Comment 11

[Jens Stutte [:jstutte]]

The just landed patch is supposed to help already with this specific intermittent, so I think we can keep this closed even if there's another patch to land.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4a6f7ba7402f
Avoid executing WorkerMainThreadRunnable::Run late in shutdown. r=dom-worker-reviewers,jesup

Comment 13

[bszekely]

https://hg.mozilla.org/mozilla-central/rev/4a6f7ba7402f