Closed Bug 1752308 Opened 3 years ago Closed 3 years ago

Intermittent Assertion failure: false (!AppShutdown::IsInOrBeyond(ShutdownPhase::XPCOMShutdownThreads)), at /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:1591

Categories

(Core :: Preferences: Backend, defect, P5)

Product:
Core
Component:
Preferences: Backend
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
98 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox96 --- unaffected
firefox97 --- unaffected
firefox98 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: assertion, intermittent-failure, regression)

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

[task 2022-01-27T11:25:36.085Z] 11:25:36     INFO - GECKO(4840) | [Parent 8688, IPDL Background] WARNING: ls: '0.313000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3789
[task 2022-01-27T11:25:36.421Z] 11:25:36     INFO - GECKO(4840) | ###!!! [Parent][PGPUParent] Error: RunMessage(msgname=PGPU::Msg_ShutdownVR) Channel closing: too late to send/recv, messages will be lost
[task 2022-01-27T11:25:36.421Z] 11:25:36     INFO - GECKO(4840) | [GPU 6328, Main Thread] WARNING: IPC message 'PGPU::Msg_FOGData' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-01-27T11:25:36.421Z] 11:25:36     INFO - GECKO(4840) | [RDD 8072, Main Thread] WARNING: IPC message 'PRDD::Msg_FOGData' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-01-27T11:25:36.437Z] 11:25:36     INFO - GECKO(4840) | [Socket 2124, Main Thread] WARNING: IPC message 'PSocketProcess::Msg_FOGData' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-01-27T11:25:36.441Z] 11:25:36     INFO - GECKO(4840) | [RDD 8072, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4451
[task 2022-01-27T11:25:36.442Z] 11:25:36     INFO - GECKO(4840) | [Socket 2124, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4451
[task 2022-01-27T11:25:36.452Z] 11:25:36     INFO - GECKO(4840) | Destroying context 000001894AA8B000 surface 0000018949063430 on display 00000189490B3E00
[task 2022-01-27T11:25:36.464Z] 11:25:36     INFO - GECKO(4840) | [GPU 6328, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4451
[task 2022-01-27T11:25:36.483Z] 11:25:36     INFO - GECKO(4840) | Assertion failure: false (!AppShutdown::IsInOrBeyond(ShutdownPhase::XPCOMShutdownThreads)), at /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:1591
[task 2022-01-27T11:25:36.624Z] 11:25:36     INFO - GECKO(4840) | #01: pref_SetPref(nsTString<char> const&, mozilla::PrefType, mozilla::PrefValueKind, PrefValue, bool, bool, bool) [modules/libpref/Preferences.cpp:1589]
[task 2022-01-27T11:25:36.630Z] 11:25:36     INFO - GECKO(4840) | #02: static mozilla::Preferences::SetCString(char const*, nsTSubstring<char> const&, mozilla::PrefValueKind) [modules/libpref/Preferences.cpp:4871]
[task 2022-01-27T11:25:36.631Z] 11:25:36     INFO - GECKO(4840) | #03: nsPrefBranch::SetCharPrefNoLengthCheck(char const*, nsTSubstring<char> const&) [modules/libpref/Preferences.cpp:2156]
[task 2022-01-27T11:25:36.631Z] 11:25:36     INFO - GECKO(4840) | #04: XRE_GetBootstrap [Z:\task_164328026206205\build\application\firefox\xul.dll + 0x8fc7052]
[task 2022-01-27T11:25:36.632Z] 11:25:36     INFO - GECKO(4840) | #05: CallMethodHelper::Call() [js/xpconnect/src/XPCWrappedNative.cpp:1184]
[task 2022-01-27T11:25:36.632Z] 11:25:36     INFO - GECKO(4840) | #06: static XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [js/xpconnect/src/XPCWrappedNative.cpp:1130]
[task 2022-01-27T11:25:36.633Z] 11:25:36     INFO - GECKO(4840) | #07: XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [js/xpconnect/src/XPCWrappedNativeJSOps.cpp:923]
[task 2022-01-27T11:25:36.633Z] 11:25:36     INFO - GECKO(4840) | #08: CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [js/src/vm/Interpreter.cpp:425]
[task 2022-01-27T11:25:36.634Z] 11:25:36     INFO - GECKO(4840) | #09: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:512]
[task 2022-01-27T11:25:36.634Z] 11:25:36     INFO - GECKO(4840) | #10: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:572]
[task 2022-01-27T11:25:36.635Z] 11:25:36     INFO - GECKO(4840) | #11: Interpret(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:3309]
[task 2022-01-27T11:25:36.635Z] 11:25:36     INFO - GECKO(4840) | #12: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:394]
[task 2022-01-27T11:25:36.636Z] 11:25:36     INFO - GECKO(4840) | #13: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:544]
[task 2022-01-27T11:25:36.636Z] 11:25:36     INFO - GECKO(4840) | #14: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:572]
[task 2022-01-27T11:25:36.637Z] 11:25:36     INFO - GECKO(4840) | #15: js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [js/src/vm/Interpreter.cpp:589]
[task 2022-01-27T11:25:36.637Z] 11:25:36     INFO - GECKO(4840) | #16: js::fun_apply(JSContext*, unsigned int, JS::Value*) [js/src/vm/JSFunction.cpp:1014]
[task 2022-01-27T11:25:36.638Z] 11:25:36     INFO - GECKO(4840) | #17: CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [js/src/vm/Interpreter.cpp:425]
[task 2022-01-27T11:25:36.638Z] 11:25:36     INFO - GECKO(4840) | #18: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:512]
[task 2022-01-27T11:25:36.639Z] 11:25:36     INFO - GECKO(4840) | #19: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:572]
[task 2022-01-27T11:25:36.639Z] 11:25:36     INFO - GECKO(4840) | #20: Interpret(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:3309]
[task 2022-01-27T11:25:36.640Z] 11:25:36     INFO - GECKO(4840) | #21: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:394]
[task 2022-01-27T11:25:36.640Z] 11:25:36     INFO - GECKO(4840) | #22: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:544]
[task 2022-01-27T11:25:36.641Z] 11:25:36     INFO - GECKO(4840) | #23: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:572]
[task 2022-01-27T11:25:36.641Z] 11:25:36     INFO - GECKO(4840) | #24: js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [js/src/vm/Interpreter.cpp:589]
[task 2022-01-27T11:25:36.642Z] 11:25:36     INFO - GECKO(4840) | #25: JS_CallFunctionValue(JSContext*, JS::Handle<JSObject *>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [js/src/vm/CallAndConstruct.cpp:53]
[task 2022-01-27T11:25:36.642Z] 11:25:36     INFO - GECKO(4840) | #26: nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) [js/xpconnect/src/XPCWrappedJSClass.cpp:995]
[task 2022-01-27T11:25:36.643Z] 11:25:36     INFO - GECKO(4840) | #27: PrepareAndDispatch(nsXPTCStubBase*, unsigned int, unsigned long long*, unsigned long long*, double*) [xpcom/reflect/xptcall/md/win32/xptcstubs_x86_64.cpp:168]
[task 2022-01-27T11:25:36.643Z] 11:25:36     INFO - GECKO(4840) | #28: XRE_GetBootstrap [Z:\task_164328026206205\build\application\firefox\xul.dll + 0x8fc70a9]
[task 2022-01-27T11:25:36.644Z] 11:25:36     INFO - GECKO(4840) | #29: nsTimerImpl::Fire(int) [xpcom/threads/nsTimerImpl.cpp:652]
[task 2022-01-27T11:25:36.644Z] 11:25:36     INFO - GECKO(4840) | #30: nsTimerEvent::Run() [xpcom/threads/TimerThread.cpp:265]
[task 2022-01-27T11:25:36.645Z] 11:25:36     INFO - GECKO(4840) | #31: mozilla::RunnableTask::Run() [xpcom/threads/TaskController.cpp:468]
[task 2022-01-27T11:25:36.645Z] 11:25:36     INFO - GECKO(4840) | #32: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:770]
[task 2022-01-27T11:25:36.646Z] 11:25:36     INFO - GECKO(4840) | #33: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:606]
[task 2022-01-27T11:25:36.646Z] 11:25:36     INFO - GECKO(4840) | #34: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:390]
[task 2022-01-27T11:25:36.647Z] 11:25:36     INFO - GECKO(4840) | #35: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:127:7'>::Run() [xpcom/threads/nsThreadUtils.h:532]
[task 2022-01-27T11:25:36.647Z] 11:25:36     INFO - GECKO(4840) | #36: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1199]
[task 2022-01-27T11:25:36.648Z] 11:25:36     INFO - GECKO(4840) | #37: nsThread::Shutdown() [xpcom/threads/nsThread.cpp:885]
[task 2022-01-27T11:25:36.648Z] 11:25:36     INFO - GECKO(4840) | #38: nsThreadPool::Shutdown() [xpcom/threads/nsThreadPool.cpp:407]
[task 2022-01-27T11:25:36.649Z] 11:25:36     INFO - GECKO(4840) | #39: mozilla::net::nsStreamTransportService::Observe(nsISupports*, char const*, char16_t const*) [netwerk/base/nsStreamTransportService.cpp:374]
[task 2022-01-27T11:25:36.649Z] 11:25:36     INFO - GECKO(4840) | #40: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/ds/nsObserverList.cpp:69]
[task 2022-01-27T11:25:36.650Z] 11:25:36     INFO - GECKO(4840) | #41: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/ds/nsObserverService.cpp:295]
[task 2022-01-27T11:25:36.650Z] 11:25:36     INFO - GECKO(4840) | #42: mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) [xpcom/base/AppShutdown.cpp:362]
[task 2022-01-27T11:25:36.651Z] 11:25:36     INFO - GECKO(4840) | #43: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:638]
[task 2022-01-27T11:25:36.651Z] 11:25:36     INFO - GECKO(4840) | #44: ScopedXPCOMStartup::~ScopedXPCOMStartup() [toolkit/xre/nsAppRunner.cpp:1682]
[task 2022-01-27T11:25:36.651Z] 11:25:36     INFO - GECKO(4840) | #45: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5573]
[task 2022-01-27T11:25:36.652Z] 11:25:36     INFO - GECKO(4840) | #46: XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5615]
[task 2022-01-27T11:25:36.652Z] 11:25:36     INFO - GECKO(4840) | #47: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:395]
[task 2022-01-27T11:25:36.653Z] 11:25:36     INFO - GECKO(4840) | #48: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:147]
[task 2022-01-27T11:25:36.653Z] 11:25:36     INFO - GECKO(4840) | #49: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/browser/app/d:/agent/_work/1/s/src/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2022-01-27T11:25:36.654Z] 11:25:36     INFO - GECKO(4840) | #50: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x17034]
[task 2022-01-27T11:25:36.654Z] 11:25:36     INFO - GECKO(4840) | #51: RtlUserThreadStart [C:\Windows\SYSTEM32\ntdll.dll + 0x52651]
[task 2022-01-27T11:25:36.858Z] 11:25:36     INFO - TEST-INFO | Main app process: exit 1
[task 2022-01-27T11:25:36.860Z] 11:25:36     INFO - TEST-INFO | Confirming we saw 36 DOCSHELL created and 36 destroyed log strings.
[task 2022-01-27T11:25:36.860Z] 11:25:36     INFO - TEST-INFO | Confirming we saw 98 DOMWINDOW created and 88 destroyed log strings.
[task 2022-01-27T11:25:36.861Z] 11:25:36     INFO - TEST-INFO | browser/base/content/test/plugins/browser_bug797677.js | This test created 1 hidden docshell(s)
[task 2022-01-27T11:25:36.862Z] 11:25:36     INFO - TEST-INFO | browser/base/content/test/plugins/browser_enable_DRM_prompt.js | This test created 1 hidden docshell(s)
[task 2022-01-27T11:25:36.862Z] 11:25:36     INFO - TEST-INFO | browser/base/content/test/plugins/browser_globalplugin_crashinfobar.js | This test created 1 hidden docshell(s)
[task 2022-01-27T11:25:36.863Z] 11:25:36     INFO - TEST-INFO | browser/base/content/test/plugins/browser_private_browsing_eme_persistent_state.js | This test created 1 hidden docshell(s)
[task 2022-01-27T11:25:36.863Z] 11:25:36     INFO - Buffered messages finished
[task 2022-01-27T11:25:36.864Z] 11:25:36    ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code 1
[task 2022-01-27T11:25:36.864Z] 11:25:36     INFO - runtests.py | Application ran for: 0:00:16.858607
[task 2022-01-27T11:25:36.864Z] 11:25:36     INFO - zombiecheck | Reading PID log: C:\Users\task_164328026206205\AppData\Local\Temp\tmptgla_zxcpidlog
[task 2022-01-27T11:25:36.865Z] 11:25:36     INFO - ==> process 8688 launched child process 2124 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.0.2111694233\1315038194" -parentBuildID 20220127094620 -prefsHandle 1572 -prefMapHandle 1760 -prefsLen 1 -prefMapSize 258430 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 1840 1debfc3ab80 socket)
[task 2022-01-27T11:25:36.866Z] 11:25:36     INFO - ==> process 8688 launched child process 6328 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.1.431900015\1813720171" -parentBuildID 20220127094620 -prefsHandle 2372 -prefMapHandle 2368 -prefsLen 789 -prefMapSize 258430 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 2404 1debfc3db80 gpu)
[task 2022-01-27T11:25:36.867Z] 11:25:36     INFO - ==> process 8688 launched child process 8324 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.2.38736173\888850019" -childID 1 -isForBrowser -prefsHandle 3000 -prefMapHandle 2992 -prefsLen 2133 -prefMapSize 258430 -jsInitHandle 1336 -jsInitLen 338496 -parentBuildID 20220127094620 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 3020 1dec0e5e580 tab)
[task 2022-01-27T11:25:36.868Z] 11:25:36     INFO - ==> process 8688 launched child process 8216 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.4.84861693\1468181417" -childID 2 -isForBrowser -prefsHandle 3472 -prefMapHandle 3468 -prefsLen 2313 -prefMapSize 258430 -jsInitHandle 1336 -jsInitLen 338496 -parentBuildID 20220127094620 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 3480 1dec6d86d80 tab)
[task 2022-01-27T11:25:36.869Z] 11:25:36     INFO - ==> process 8688 launched child process 1816 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.6.1456481515\643075626" -childID 3 -isForBrowser -prefsHandle 3664 -prefMapHandle 3660 -prefsLen 2353 -prefMapSize 258430 -jsInitHandle 1336 -jsInitLen 338496 -parentBuildID 20220127094620 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 3500 1dec6c6ef80 tab)
[task 2022-01-27T11:25:36.870Z] 11:25:36     INFO - ==> process 8688 launched child process 2652 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.8.1443062658\232598529" -childID 4 -isForBrowser -prefsHandle 3992 -prefMapHandle 3960 -prefsLen 2486 -prefMapSize 258430 -jsInitHandle 1336 -jsInitLen 338496 -parentBuildID 20220127094620 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 4028 1dec0e5f180 tab)
[task 2022-01-27T11:25:36.870Z] 11:25:36     INFO - ==> process 8688 launched child process 3196 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.10.232368907\1209673948" -childID 5 -isForBrowser -prefsHandle 4908 -prefMapHandle 4904 -prefsLen 10884 -prefMapSize 258430 -jsInitHandle 1336 -jsInitLen 338496 -parentBuildID 20220127094620 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 4928 1decb6a0d80 tab)
[task 2022-01-27T11:25:36.871Z] 11:25:36     INFO - ==> process 8688 launched child process 6768 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.13.1610289555\923826009" -childID 6 -isForBrowser -prefsHandle 5084 -prefMapHandle 4208 -prefsLen 10884 -prefMapSize 258430 -jsInitHandle 1336 -jsInitLen 338496 -parentBuildID 20220127094620 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 4904 1decc2f6180 tab)
[task 2022-01-27T11:25:36.872Z] 11:25:36     INFO - ==> process 8688 launched child process 8072 ("Z:\task_164328026206205\build\application\firefox\firefox.exe" -contentproc --channel="8688.16.347575805\538939735" -parentBuildID 20220127094620 -prefsHandle 5504 -prefMapHandle 5552 -prefsLen 11177 -prefMapSize 258430 -appDir "Z:\task_164328026206205\build\application\firefox\browser" - 8688 "\\.\pipe\gecko-crash-server-pipe.8688" 5600 1deb4179180 rdd)
[task 2022-01-27T11:25:36.873Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 8324
[task 2022-01-27T11:25:36.873Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 8072
[task 2022-01-27T11:25:36.873Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 2124
[task 2022-01-27T11:25:36.874Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 3196
[task 2022-01-27T11:25:36.874Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 1816
[task 2022-01-27T11:25:36.874Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 6768
[task 2022-01-27T11:25:36.875Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 6328
[task 2022-01-27T11:25:36.875Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 8216
[task 2022-01-27T11:25:36.876Z] 11:25:36     INFO - zombiecheck | Checking for orphan process with PID: 2652
[task 2022-01-27T11:25:36.887Z] 11:25:36     INFO - mozcrash Copy/paste: Z:/task_164328026206205/fetches\minidump_stackwalk\minidump_stackwalk.exe --symbols-url=https://symbols.mozilla.org/ --human C:\Users\task_164328026206205\AppData\Local\Temp\tmp50ki4nzi.mozrunner\minidumps\f7b4e87a-8b47-4e35-8b2d-9ccabef56d88.dmp Z:\task_164328026206205\build\symbols
[task 2022-01-27T11:25:42.074Z] 11:25:42     INFO - mozcrash Saved minidump as Z:\task_164328026206205\build\blobber_upload_dir\f7b4e87a-8b47-4e35-8b2d-9ccabef56d88.dmp
[task 2022-01-27T11:25:42.085Z] 11:25:42     INFO - mozcrash Saved app info as Z:\task_164328026206205\build\blobber_upload_dir\f7b4e87a-8b47-4e35-8b2d-9ccabef56d88.extra
[task 2022-01-27T11:25:42.301Z] 11:25:42     INFO - PROCESS-CRASH | Last test finished | application crashed [@ pref_SetPref(nsTString<char> const&, mozilla::PrefType, mozilla::PrefValueKind, PrefValue, bool, bool, bool)]
[task 2022-01-27T11:25:42.301Z] 11:25:42     INFO - Mozilla crash reason: MOZ_ASSERT(false) (!AppShutdown::IsInOrBeyond(ShutdownPhase::XPCOMShutdownThreads))
[task 2022-01-27T11:25:42.301Z] 11:25:42     INFO - Crash dump filename: C:\Users\task_164328026206205\AppData\Local\Temp\tmp50ki4nzi.mozrunner\minidumps\f7b4e87a-8b47-4e35-8b2d-9ccabef56d88.dmp
[task 2022-01-27T11:25:42.301Z] 11:25:42     INFO - Operating system: Windows NT
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -                   10.0.19041 
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - CPU: amd64
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -      family 6 model 85 stepping 7
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -      8 CPUs
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - 
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - Crash reason:  EXCEPTION_BREAKPOINT
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - Crash address: 0x7ff9495d80a5
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - Process uptime: 16 seconds
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - 
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO - Thread 0 MainThread (crashed)
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -  0  xul.dll!pref_SetPref(nsTString<char> const&, mozilla::PrefType, mozilla::PrefValueKind, PrefValue, bool, bool, bool) [Preferences.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 1589 + 0x0]
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     rax = 0x00007ff9522ea6a0   rdx = 0x0000000000000000
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     rcx = 0x00007ff96d40faa0   rbx = 0x0000d2a3996a07a0
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     rsi = 0x0000004502dfbdf0   rdi = 0x000001deb413d428
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     rbp = 0x0000000080070057   rsp = 0x0000004502dfbce0
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -      r8 = 0x0000004502dffe00    r9 = 0x00007ff987e50000
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     r10 = 0x00007ff987ea2651   r11 = 0x0000004502dfb6a0
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     r12 = 0x0000000000000002   r13 = 0x0000000000000001
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     r14 = 0x0000004502dfbe00   r15 = 0x000001deb4113408
[task 2022-01-27T11:25:42.312Z] 11:25:42     INFO -     rip = 0x00007ff9495d80a5
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     Found by: given as instruction pointer in context
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -  1  xul.dll!static mozilla::Preferences::SetCString(char const*, nsTSubstring<char> const&, mozilla::PrefValueKind) [Preferences.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 4871 + 0x29]
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     rbx = 0x0000d2a3996a07a0   rbp = 0x0000000080070057
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     rsp = 0x0000004502dfbdb0   r12 = 0x0000000000000002
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     r13 = 0x0000000000000001   r14 = 0x0000004502dfbe00
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     r15 = 0x000001deb4113408   rip = 0x00007ff949564e09
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -  2  xul.dll!nsPrefBranch::SetCharPrefNoLengthCheck(char const*, nsTSubstring<char> const&) [Preferences.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 2156 + 0x7]
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     rbx = 0x0000d2a3996a07a0   rbp = 0x0000000080070057
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     rsp = 0x0000004502dfbe70   r12 = 0x0000000000000002
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     r13 = 0x0000000000000001   r14 = 0x0000004502dfbe00
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     r15 = 0x000001deb4113408   rip = 0x00007ff949564cfc
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -  3  xul.dll!XPTC__InvokebyIndex + 0x71
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     rbx = 0x0000d2a3996a07a0   rbp = 0x0000000080070057
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     rsp = 0x0000004502dfbef0   r12 = 0x0000000000000002
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     r13 = 0x0000000000000001   r14 = 0x0000004502dfbe00
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     r15 = 0x000001deb4113408   rip = 0x00007ff9520f7052
[task 2022-01-27T11:25:42.313Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -  4  0x1deb413d25f
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO - 
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     rbx = 0x0000d2a3996a07a0   rbp = 0x0000000080070057
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     rsp = 0x0000004502dfbf00   r12 = 0x0000000000000002
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     r13 = 0x0000000000000001   r14 = 0x0000004502dfbe00
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     r15 = 0x000001deb4113408   rip = 0x000001deb413d260
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -  5  xul.dll!_tailMerge_d3dcompiler_47.dll + 0xa0c82
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     rsp = 0x0000004502dfbf30   rip = 0x00007ff95229b600
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     Found by: stack scanning
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -  6  xul.dll!CallMethodHelper::Call() [XPCWrappedNative.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 1184 + 0x18]
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     rsp = 0x0000004502dfbf40   rip = 0x00007ff94a5a0dc8
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -     Found by: stack scanning
[task 2022-01-27T11:25:42.314Z] 11:25:42     INFO -  7  xul.dll!static XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 1130 + 0x7]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfbfc0   rip = 0x00007ff94a5a09d7
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -  8  xul.dll!XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [XPCWrappedNativeJSOps.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 923 + 0x7]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfc150   rip = 0x00007ff94a5a265f
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -  9  xul.dll!CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 425 + 0xb]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfc2f0   rip = 0x00007ff94fbd9c2e
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO - 10  xul.dll!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 512 + 0x10]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfc390   rip = 0x00007ff94fbd92d7
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO - 11  xul.dll!InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 572 + 0x10]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfc490   rip = 0x00007ff94fbdad87
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO - 12  xul.dll!Interpret(JSContext*, js::RunState&) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 3309 + 0x17]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfc510   rip = 0x00007ff94fbcf5c1
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO - 13  xul.dll!js::RunScript(JSContext*, js::RunState&) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 394 + 0xa]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfca50   rip = 0x00007ff94fbc6d83
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO - 14  xul.dll!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 544 + 0xc]
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     rsp = 0x0000004502dfcb10   rip = 0x00007ff94fbd92f2
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.315Z] 11:25:42     INFO - 15  xul.dll!InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 572 + 0x10]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfcc10   rip = 0x00007ff94fbdad87
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO - 16  xul.dll!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 589 + 0xa]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfcc90   rip = 0x00007ff94fbdaf0a
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO - 17  xul.dll!js::fun_apply(JSContext*, unsigned int, JS::Value*) [JSFunction.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 1014 + 0x29]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfcce0   rip = 0x00007ff94fe2afdf
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO - 18  xul.dll!CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 425 + 0xb]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfceb0   rip = 0x00007ff94fbd9c2e
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO - 19  xul.dll!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 512 + 0x10]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfcf50   rip = 0x00007ff94fbd92d7
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO - 20  xul.dll!InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 572 + 0x10]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfd050   rip = 0x00007ff94fbdad87
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO - 21  xul.dll!Interpret(JSContext*, js::RunState&) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 3309 + 0x17]
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     rsp = 0x0000004502dfd0d0   rip = 0x00007ff94fbcf5c1
[task 2022-01-27T11:25:42.316Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO - 22  xul.dll!js::RunScript(JSContext*, js::RunState&) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 394 + 0xa]
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     rsp = 0x0000004502dfd610   rip = 0x00007ff94fbc6d83
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO - 23  xul.dll!js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 544 + 0xc]
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     rsp = 0x0000004502dfd6d0   rip = 0x00007ff94fbd92f2
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO - 24  xul.dll!InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 572 + 0x10]
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     rsp = 0x0000004502dfd7d0   rip = 0x00007ff94fbdad87
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO - 25  xul.dll!js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [Interpreter.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 589 + 0xa]
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     rsp = 0x0000004502dfd850   rip = 0x00007ff94fbdaf0a
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO - 26  xul.dll!JS_CallFunctionValue(JSContext*, JS::Handle<JSObject *>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [CallAndConstruct.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 53 + 0x21]
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     rsp = 0x0000004502dfd8a0   rip = 0x00007ff94fd6a06b
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.317Z] 11:25:42     INFO - 27  xul.dll!nsXPCWrappedJS::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) [XPCWrappedJSClass.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 973 + 0x2f]
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     rsp = 0x0000004502dfda60   rip = 0x00007ff94a5992bc
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO - 28  xul.dll!PrepareAndDispatch(nsXPTCStubBase*, unsigned int, unsigned long long*, unsigned long long*, double*) [xptcstubs_x86_64.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 168 + 0x17]
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     rsp = 0x0000004502dfdee0   rip = 0x00007ff94953f627
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO - 29  xul.dll!SharedStub + 0x48
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     rsp = 0x0000004502dfdfe0   rip = 0x00007ff9520f70a9
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO - 30  xul.dll!nsTimerImpl::Fire(int) [nsTimerImpl.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 652 + 0x47]
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     rsp = 0x0000004502dfe050   rip = 0x00007ff94952f40e
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO - 31  xul.dll!nsTimerEvent::Run() [TimerThread.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 265 + 0x7]
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     rsp = 0x0000004502dfe1e0   rip = 0x00007ff949500cce
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.318Z] 11:25:42     INFO - 32  xul.dll!mozilla::RunnableTask::Run() [TaskController.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 467 + 0xc]
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     rsp = 0x0000004502dfe360   rip = 0x00007ff94951cedb
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO - 33  xul.dll!mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [TaskController.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 770 + 0xf]
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     rsp = 0x0000004502dfe800   rip = 0x00007ff9494f7c8e
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO - 34  xul.dll!mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [TaskController.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 606 + 0x4]
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     rsp = 0x0000004502dfead0   rip = 0x00007ff9494f63d8
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO - 35  xul.dll!mozilla::TaskController::ProcessPendingMTTask(bool) [TaskController.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 390 + 0x7]
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     rsp = 0x0000004502dfeb60   rip = 0x00007ff9494f669e
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO - 36  xul.dll!mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:127:7'>::Run() [nsThreadUtils.h:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 531 + 0x12]
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     rsp = 0x0000004502dfebe0   rip = 0x00007ff949520e07
[task 2022-01-27T11:25:42.319Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO - 37  xul.dll!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 1195 + 0xc]
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     rsp = 0x0000004502dfec10   rip = 0x00007ff94950d25c
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO - 38  xul.dll!nsThread::Shutdown() [nsThread.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 885 + 0x34d]
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     rsp = 0x0000004502dfedf0   rip = 0x00007ff94950be76
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO - 39  xul.dll!nsThreadPool::Shutdown() [nsThreadPool.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 408 + 0xc]
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     rsp = 0x0000004502dff0b0   rip = 0x00007ff94951881d
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO - 40  xul.dll!mozilla::net::nsStreamTransportService::Observe(nsISupports*, char const*, char16_t const*) [nsStreamTransportService.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 373 + 0x10]
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     rsp = 0x0000004502dff110   rip = 0x00007ff9497618cc
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO - 41  xul.dll!nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [nsObserverList.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 70 + 0x15]
[task 2022-01-27T11:25:42.320Z] 11:25:42     INFO -     rsp = 0x0000004502dff190   rip = 0x00007ff949440a7a
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO - 42  xul.dll!nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [nsObserverService.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 292 + 0x10]
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     rsp = 0x0000004502dff1f0   rip = 0x00007ff94944c194
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO - 43  xul.dll!mozilla::AdvanceShutdownPhaseInternal(mozilla::ShutdownPhase, bool, char16_t const*, nsCOMPtr<nsISupports> const&) [AppShutdown.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 360 + 0x12]
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     rsp = 0x0000004502dff3a0   rip = 0x00007ff9493b457c
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO - 44  xul.dll!mozilla::ShutdownXPCOM(nsIServiceManager*) [XPCOMInit.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 638 + 0xb]
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     rsp = 0x0000004502dff400   rip = 0x00007ff94955f1a0
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO - 45  xul.dll!ScopedXPCOMStartup::~ScopedXPCOMStartup() [nsAppRunner.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 1681 + 0x7]
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     rsp = 0x0000004502dff4f0   rip = 0x00007ff94fa4f0a6
[task 2022-01-27T11:25:42.321Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO - 46  xul.dll!XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 5573 + 0x18]
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO -     rsp = 0x0000004502dff5c0   rip = 0x00007ff94fa5ebad
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO - 47  xul.dll!XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 5615 + 0xf]
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO -     rsp = 0x0000004502dff6d0   rip = 0x00007ff94fa5f482
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO - 48  firefox.exe!NS_internal_main(int, char**, char**) [nsBrowserApp.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 395 + 0x18f]
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO -     rsp = 0x0000004502dff830   rip = 0x00007ff684b61916
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.322Z] 11:25:42     INFO - 49  firefox.exe!wmain(int, wchar_t**) [nsWindowsWMain.cpp:7dff1a12e1a4fd90cd5bf56e334120b08b64066b : 147 + 0x14]
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     rsp = 0x0000004502dffa10   rip = 0x00007ff684b6138b
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO - 50  firefox.exe!__scrt_common_main_seh() [exe_common.inl : 288 + 0x21]
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     rsp = 0x0000004502dffd10   rip = 0x00007ff684c01798
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO - 51  kernel32.dll!BaseThreadInitThunk + 0x13
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     rsp = 0x0000004502dffd50   rip = 0x00007ff987b57034
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO - 52  ntdll.dll!RtlUserThreadStart + 0x20
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     rsp = 0x0000004502dffd80   rip = 0x00007ff987ea2651
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO -     Found by: call frame info
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO - 
[task 2022-01-27T11:25:42.323Z] 11:25:42     INFO - Thread 1 BrokerEvent

This is just an assertion about some code changing a pref late in shutdown. It doesn't need to be hidden.

Jens, this might be of interest to you.

Group: core-security
Flags: needinfo?(jstutte)
Keywords: regression
Regressed by: 1710018

It might be nice to dump out what the pref actually is in debug builds when this happens. This looks like it is happening from JS, so the stack is not useful AFAICT.

I actually had a patch ready on the regressing bug to remove the assertion. This way we should hopefully see a JS assertion from the caller. Do you think that is the right call?

Flags: needinfo?(jstutte) → needinfo?(continuation)

Ah, that might make sense, too. I don't do enough debugging of JS to know how useful the result will be.

Flags: needinfo?(continuation)

I'll keep an ni? until that lands.

Flags: needinfo?(jstutte)

All instances so far seem to come from JS callers. The assertion is gone now, so this specific intermittent will not happen anymore.
IIUC it depends now on the JS exception handling of the caller what happens:

  • if the caller does not handle NS_ERROR_ILLEGAL_DURING_SHUTDOWN we will probably see JS exceptions as new intermittents which point us directly to the culprit
  • if the caller does handle it well, nothing too bad will happen (at worst we did not write a preference change but should know we didn't)
  • if the caller does swallow it without any proper handling we might see some weird side effects (and the caller should be adjusted)

I assume/hope that in most cases the first option will apply. A proper fix would then probably ensure to not try to do preference writes such late at all. A less proper fix could just react well on the exception.

Status: NEW → RESOLVED
Closed: 3 years ago
Flags: needinfo?(jstutte)
Resolution: --- → FIXED
Has Regression Range: --- → yes
status-firefox96: --- → unaffected
status-firefox97: --- → unaffected
status-firefox98: --- → fixed
status-firefox-esr91: --- → unaffected
Target Milestone: --- → 98 Branch

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

All instances so far seem to come from JS callers. The assertion is gone now, so this specific intermittent will not happen anymore.
IIUC it depends now on the JS exception handling of the caller what happens:

  • if the caller does not handle NS_ERROR_ILLEGAL_DURING_SHUTDOWN we will probably see JS exceptions as new intermittents which point us directly to the culprit

I don't think such intermittents will appear, because JS errors just get logged to the console, and won't cause assertions or crashes and thus won't fail the relevant test jobs. They might not even appear in the stderr output . If there are uncaught exceptions while a specific test is running, they will fail the test, but because this case happens during shutdown, it's pretty much guaranteed no test is running and no test will fail.

Can we instead reopen this (or use a new separate bug) and in addition to the assertion, add debugonly code that dumps a JS stack when this happens, so that we can investigate what things are writing to prefs late? It would probably also help if the assertion printed the name of the pref that we're trying to write - generally speaking, it seems unlikely that there's a single pref that's written from more than a handful locations.

Flags: needinfo?(jstutte)
Blocks: 1753932
Flags: needinfo?(jstutte)
You need to log in before you can comment on or make changes to this bug.