Closed Bug 1813353 Opened 2 years ago Closed 2 months ago

Intermittent Assertion failure: false (Try to init HttpHandler after shutdown), at /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpHandler.cpp:333

Categories

(Core :: DOM: Workers, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE
Tracking Status
firefox-esr102 --- unaffected
firefox109 --- unaffected
firefox110 --- unaffected
firefox111 --- wontfix
firefox112 --- wontfix
firefox113 --- wontfix
firefox114 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: assertion, intermittent-failure, regression, Whiteboard: [retriggered])

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


[task 2023-01-28T23:42:35.041Z] 23:42:35     INFO - TEST-START | browser/components/shell/test/browser_headless_screenshot_4.js
<...>
[task 2023-01-28T23:42:46.703Z] 23:42:46     INFO - GECKO(4593) | [Parent 7280, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-01-28T23:42:46.719Z] 23:42:46     INFO - GECKO(4593) | >>> expected format: --window-size width[,height]
[task 2023-01-28T23:42:47.136Z] 23:42:47     INFO - GECKO(4593) | [Child 4685: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7f3e5037c090) [pid = 4685] [serial = 9] [outer = 0] [url = about:blank]
[task 2023-01-28T23:42:47.180Z] 23:42:47     INFO - GECKO(4593) | [Parent 7280, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-01-28T23:42:47.349Z] 23:42:47     INFO - GECKO(4593) | [WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2023-01-28T23:42:47.379Z] 23:42:47     INFO - GECKO(4593) | >>> console.error: (new Error("IndexedDB: main/cookie-banner-rules-list getLastModified() IndexedDB:  execute() The application is shutting down", "resource://services-settings/IDBHelpers.jsm", 18))
[task 2023-01-28T23:42:47.540Z] 23:42:47     INFO - GECKO(4593) | Assertion failure: false (Try to init HttpHandler after shutdown), at /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpHandler.cpp:333
[task 2023-01-28T23:42:47.547Z] 23:42:47     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2023-01-28T23:43:11.732Z] 23:43:11     INFO - GECKO(4593) | #01: mozilla::net::nsHttpHandler::Init() [netwerk/protocol/http/nsHttpHandler.cpp:333]
[task 2023-01-28T23:43:11.733Z] 23:43:11     INFO - GECKO(4593) | #02: mozilla::net::nsHttpHandler::GetInstance() [netwerk/protocol/http/nsHttpHandler.cpp:197]
[task 2023-01-28T23:43:11.735Z] 23:43:11     INFO - GECKO(4593) | #03: mozCreateComponent<mozilla::net::nsHttpHandler>() [netwerk/build/nsNetModule.cpp:65]
[task 2023-01-28T23:43:11.737Z] 23:43:11     INFO - GECKO(4593) | #04: mozilla::xpcom::CreateInstanceImpl(mozilla::xpcom::ModuleID, nsID const&, void**) [s3:gecko-generated-sources:5251d764dd33ae83b21ba504fdc534268f0eea28725cb5fbd495aa230c58264497a65e6cee3656986235d23829552e49f9d9ae3330e2af227a5bb5e59e3883a8/xpcom/components/StaticComponents.cpp::10686]
[task 2023-01-28T23:43:11.739Z] 23:43:11     INFO - GECKO(4593) | #05: nsComponentManagerImpl::GetServiceLocked(mozilla::Maybe<mozilla::detail::BaseMonitorAutoLock<mozilla::Monitor> >&, (anonymous namespace)::EntryWrapper&, nsID const&, void**) [xpcom/components/nsComponentManager.cpp:975]
[task 2023-01-28T23:43:11.740Z] 23:43:11     INFO - GECKO(4593) | #06: nsComponentManagerImpl::GetServiceByContractID(char const*, nsID const&, void**) [xpcom/components/nsComponentManager.cpp:1164]
[task 2023-01-28T23:43:11.742Z] 23:43:11     INFO - GECKO(4593) | #07: nsGetServiceByContractIDWithError::operator()(nsID const&, void**) const [xpcom/components/nsComponentManagerUtils.cpp:251]
[task 2023-01-28T23:43:11.743Z] 23:43:11     INFO - GECKO(4593) | #08: nsCOMPtr<nsIHttpProtocolHandler>::assign_from_gs_contractid_with_error(nsGetServiceByContractIDWithError const&, nsID const&) [xpcom/base/nsCOMPtr.h:1244]
[task 2023-01-28T23:43:11.745Z] 23:43:11     INFO - GECKO(4593) | #09: mozilla::dom::Navigator::GetAppVersion(nsTSubstring<char16_t>&, mozilla::dom::Document*, bool) [dom/base/Navigator.cpp:2009]
[task 2023-01-28T23:43:11.747Z] 23:43:11     INFO - GECKO(4593) | #10: mozilla::dom::workerinternals::RuntimeService::RegisterWorker(mozilla::dom::WorkerPrivate&) [dom/workers/RuntimeService.cpp:1177]
[task 2023-01-28T23:43:11.748Z] 23:43:11     INFO - GECKO(4593) | #11: mozilla::dom::WorkerPrivate::Constructor(JSContext*, nsTSubstring<char16_t> const&, bool, mozilla::dom::WorkerKind, mozilla::dom::RequestCredentials, mozilla::dom::WorkerType, nsTSubstring<char16_t> const&, nsTSubstring<char> const&, mozilla::dom::WorkerLoadInfo*, mozilla::ErrorResult&, nsTString<char16_t>) [dom/workers/WorkerPrivate.cpp:2649]
[task 2023-01-28T23:43:11.750Z] 23:43:11     INFO - GECKO(4593) | #12: mozilla::dom::ChromeWorker::Constructor(mozilla::dom::GlobalObject const&, nsTSubstring<char16_t> const&, mozilla::ErrorResult&) [dom/workers/ChromeWorker.cpp:22]
[task 2023-01-28T23:43:11.751Z] 23:43:11     INFO - GECKO(4593) | #13: mozilla::dom::ChromeWorker_Binding::_constructor(JSContext*, unsigned int, JS::Value*) [s3:gecko-generated-sources:96fd512ceda46a08eabed8213d3d855ae74fba26af77b3d2c438a7da441d3105b50a8561f08c44986c9d87e5f29cc5ea075ab3cfce271686f5ffb76034e5d2b8/dom/bindings/WorkerBinding.cpp::313]
[task 2023-01-28T23:43:11.753Z] 23:43:11     INFO - GECKO(4593) | #14: CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [js/src/vm/Interpreter.cpp:459]
[task 2023-01-28T23:43:11.755Z] 23:43:11     INFO - GECKO(4593) | #15: CallJSNativeConstructor(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) [js/src/vm/Interpreter.cpp:475]
[task 2023-01-28T23:43:11.757Z] 23:43:11     INFO - GECKO(4593) | #16: InternalConstruct(JSContext*, js::AnyConstructArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:0]
[task 2023-01-28T23:43:11.758Z] 23:43:11     INFO - GECKO(4593) | #17: Interpret(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:3347]
[task 2023-01-28T23:43:11.760Z] 23:43:11     INFO - GECKO(4593) | #18: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:431]
[task 2023-01-28T23:43:11.761Z] 23:43:11     INFO - GECKO(4593) | #19: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:0]
[task 2023-01-28T23:43:11.763Z] 23:43:11     INFO - GECKO(4593) | #20: 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:646]
[task 2023-01-28T23:43:11.765Z] 23:43:11     INFO - GECKO(4593) | #21: js::CallSelfHostedFunction(JSContext*, JS::Handle<js::PropertyName*>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) [js/src/vm/SelfHosting.cpp:1489]
[task 2023-01-28T23:43:11.766Z] 23:43:11     INFO - GECKO(4593) | #22: js::jit::InterpretResume(JSContext*, JS::Handle<JSObject*>, JS::Value*, JS::MutableHandle<JS::Value>) [js/src/jit/VMFunctions.cpp:1088]
[task 2023-01-28T23:43:11.767Z] 23:43:11     INFO - GECKO(4593) | #23: ??? (???:???)
[task 2023-01-28T23:43:11.769Z] 23:43:11     INFO - GECKO(4593) | ExceptionHandler::GenerateDump cloned child 7332
[task 2023-01-28T23:43:11.770Z] 23:43:11     INFO - GECKO(4593) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2023-01-28T23:43:11.772Z] 23:43:11     INFO - GECKO(4593) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2023-01-28T23:43:11.773Z] 23:43:11     INFO - TEST-INFO | started process screentopng
[task 2023-01-28T23:43:12.057Z] 23:43:12     INFO - TEST-INFO | screentopng: exit 0
[task 2023-01-28T23:43:12.059Z] 23:43:12     INFO - Buffered messages logged at 23:42:35
[task 2023-01-28T23:43:12.060Z] 23:43:12     INFO - Entering test bound 
[task 2023-01-28T23:43:12.061Z] 23:43:12     INFO - Buffered messages logged at 23:42:38
[task 2023-01-28T23:43:12.062Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | Firefox process should exit with code 0 - 
[task 2023-01-28T23:43:12.065Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | A screenshot should be saved in the tmp directory - 
[task 2023-01-28T23:43:12.066Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | Screenshot should be 800 pixels wide - 
[task 2023-01-28T23:43:12.067Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | Screenshot should be 600 pixels tall - 
[task 2023-01-28T23:43:12.069Z] 23:43:12     INFO - Buffered messages logged at 23:42:42
[task 2023-01-28T23:43:12.073Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | Firefox process should exit with code 0 - 
[task 2023-01-28T23:43:12.074Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | A screenshot should be saved in the tmp directory - 
[task 2023-01-28T23:43:12.075Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | Screenshot should be 1234 pixels wide - 
[task 2023-01-28T23:43:12.076Z] 23:43:12     INFO - Buffered messages logged at 23:42:46
[task 2023-01-28T23:43:12.077Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | Firefox process should exit with code 0 - 
[task 2023-01-28T23:43:12.078Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | A screenshot should not be saved - 
[task 2023-01-28T23:43:12.079Z] 23:43:12     INFO - Buffered messages finished
[task 2023-01-28T23:43:12.080Z] 23:43:12     INFO - TEST-UNEXPECTED-FAIL | browser/components/shell/test/browser_headless_screenshot_4.js | Firefox process should exit with code 0 - Got 11, expected +0
[task 2023-01-28T23:43:12.081Z] 23:43:12     INFO - Stack trace:
[task 2023-01-28T23:43:12.082Z] 23:43:12     INFO - chrome://mochikit/content/browser-test.js:test_is:1484
[task 2023-01-28T23:43:12.083Z] 23:43:12     INFO - chrome://mochitests/content/browser/browser/components/shell/test/head.js:runFirefox:44
[task 2023-01-28T23:43:12.089Z] 23:43:12     INFO - TEST-PASS | browser/components/shell/test/browser_headless_screenshot_4.js | A screenshot should not be saved - 
[task 2023-01-28T23:43:12.090Z] 23:43:12     INFO - Leaving test bound 
[task 2023-01-28T23:43:12.092Z] 23:43:12     INFO - GECKO(4593) | MEMORY STAT | vsize 3036MB | residentFast 427MB | heapAllocated 181MB
[task 2023-01-28T23:43:12.093Z] 23:43:12     INFO - TEST-OK | browser/components/shell/test/browser_headless_screenshot_4.js | took 12627ms
[task 2023-01-28T23:43:12.095Z] 23:43:12     INFO - GECKO(4593) | [Child 4685: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f3e4b123c00 == 1 [pid = 4685] [id = 4]
[task 2023-01-28T23:43:12.096Z] 23:43:12     INFO - GECKO(4593) | [Child 4685: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f3e5037c090) [pid = 4685] [serial = 11] [outer = 0]
[task 2023-01-28T23:43:12.098Z] 23:43:12     INFO - GECKO(4593) | [Child 4685: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (7f3e4b124400) [pid = 4685] [serial = 12] [outer = 7f3e5037c090]
[task 2023-01-28T23:43:12.099Z] 23:43:12     INFO - checking window state
[task 2023-01-28T23:43:12.100Z] 23:43:12     INFO - TEST-START | browser/components/shell/test/browser_headless_screenshot_cross_origin.js

First range of retriggers and backfills were inconclusive.

Kershaw, this might be related to Bug 1802910.
Do you have a bit of time to look at this?
Thank you.

Flags: needinfo?(kershaw)
Regressed by: 1802910
Whiteboard: [retriggered]

Set release status flags based on info from the regressing bug 1802910

Looks like we are trying to create a worker during shutdown.

[task 2023-01-28T23:43:11.745Z] 23:43:11     INFO - GECKO(4593) | #09: mozilla::dom::Navigator::GetAppVersion(nsTSubstring<char16_t>&, mozilla::dom::Document*, bool) [dom/base/Navigator.cpp:2009]
[task 2023-01-28T23:43:11.747Z] 23:43:11     INFO - GECKO(4593) | #10: mozilla::dom::workerinternals::RuntimeService::RegisterWorker(mozilla::dom::WorkerPrivate&) [dom/workers/RuntimeService.cpp:1177]
[task 2023-01-28T23:43:11.748Z] 23:43:11     INFO - GECKO(4593) | #11: mozilla::dom::WorkerPrivate::Constructor(JSContext*, nsTSubstring<char16_t> const&, bool, mozilla::dom::WorkerKind, mozilla::dom::RequestCredentials, mozilla::dom::WorkerType, nsTSubstring<char16_t> const&, nsTSubstring<char> const&, mozilla::dom::WorkerLoadInfo*, mozilla::ErrorResult&, nsTString<char16_t>) [dom/workers/WorkerPrivate.cpp:2649]
[task 2023-01-28T23:43:11.750Z] 23:43:11     INFO - GECKO(4593) | #12: mozilla::dom::ChromeWorker::Constructor(mozilla::dom::GlobalObject const&, nsTSubstring<char16_t> const&, mozilla::ErrorResult&) [dom/workers/ChromeWorker.cpp:22]

Jens, could you find someone to take a look? Thanks.

Component: Networking: HTTP → DOM: Workers
Flags: needinfo?(kershaw) → needinfo?(jstutte)

Set release status flags based on info from the regressing bug 1802910

Joshua, would you mind to take a look? Even if it is not frequent, the stack might be interesting enough to look at.

Flags: needinfo?(jstutte) → needinfo?(jmarshall)
Assignee: nobody → jmarshall
Flags: needinfo?(jmarshall)

Just a bit if context:

nsHttpHandler is doing a AppShutdown::IsInOrBeyond(ShutdownPhase::AppShutdown) check. The stack passes through WorkerPrivate::Constructor and probably we should not allow the creation of new workers after we entered shutdown in general.

I assume that if we let the Constructor return nullptr the calling JS will throw and we might have a chance to see who was actually calling us here. And/or we could print out the JS stack when this happens.

See Also: → 1827207
Assignee: jmarshall → nobody

So bug 1827207 now gives us:

[task 2023-05-08T18:32:25.827Z] 18:32:25     INFO - GECKO(20087) | >>> 0 _execute(method = ""importJSONDump"", args = "main,anti-tracking-url-decoration", options = "[object Object]") ["resource://services-settings/RemoteSettingsWorker.sys.mjs":70:20]
[task 2023-05-08T18:32:25.828Z] 18:32:25     INFO - GECKO(20087) |     this = [object Object]
[task 2023-05-08T18:32:25.829Z] 18:32:25     INFO - GECKO(20087) | 1 importJSONDump(bucket = ""main"", collection = ""anti-tracking-url-decoration"") ["resource://services-settings/RemoteSettingsWorker.sys.mjs":171:16]
[task 2023-05-08T18:32:25.830Z] 18:32:25     INFO - GECKO(20087) |     this = [object Object]
[task 2023-05-08T18:32:25.831Z] 18:32:25     INFO - GECKO(20087) | 2 _importJSONDump() ["resource://services-settings/RemoteSettingsClient.sys.mjs":966:51]
[task 2023-05-08T18:32:25.832Z] 18:32:25     INFO - GECKO(20087) |     this = [object Object]
[task 2023-05-08T18:32:25.833Z] 18:32:25     INFO - GECKO(20087) | 3 get/this._importingPromise<() ["resource://services-settings/RemoteSettingsClient.sys.mjs":457:27]
[task 2023-05-08T18:32:25.834Z] 18:32:25     INFO - GECKO(20087) | 4 get() ["resource://services-settings/RemoteSettingsClient.sys.mjs":472:12]
[task 2023-05-08T18:32:25.835Z] 18:32:25     INFO - GECKO(20087) | 5 InterpretGeneratorResume(gen = "[object Object]", val = "null", kind = ""next"") ["self-hosted":1359:33]
[task 2023-05-08T18:32:25.836Z] 18:32:25     INFO - GECKO(20087) | 6 AsyncFunctionNext(val = "null") ["self-hosted":756:26]
[task 2023-05-08T18:32:25.837Z] 18:32:25     INFO - GECKO(20087) |     this = [object Object]
[task 2023-05-08T18:32:25.838Z] 18:32:25     INFO - GECKO(20087) | 7 observe("null", ""profile-before-change"", "null") ["resource://gre/modules/AsyncShutdown.sys.mjs":575:16]
[task 2023-05-08T18:32:25.838Z] 18:32:25     INFO - GECKO(20087) |     this = [object Object]

coming from this async operation in RemoteSettingsClient. Could it be that we miss a shutdown blocker here?

Flags: needinfo?(standard8)

Mathieu knows this code better than me.

Flags: needinfo?(standard8) → needinfo?(mathieu)

This intermittent looks pretty moot now, but every few months it shows up. I filed bug 1890278 for the remote settings piece.

Flags: needinfo?(mathieu)
See Also: → 1890278
Status: NEW → RESOLVED
Closed: 5 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 months ago3 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 months ago2 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.