Closed Bug 1803723 Opened 1 year ago Closed 1 year ago

Intermittent remote/cdp/test/browser/security/browser_setIgnoreCertificateErrors.js | single tracking bug

Categories

(Remote Protocol :: CDP, defect, P5)

Product:
Remote Protocol
Component:
CDP
Type:
defect

Tracking

(firefox-esr102 unaffected, firefox108 unaffected, firefox109 affected, firefox110 affected)

Status:
RESOLVED DUPLICATE of bug 1801716
Tracking Flags:
Tracking Status
firefox-esr102 --- unaffected
firefox108 --- unaffected
firefox109 --- affected
firefox110 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, regression)

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

[task 2022-12-02T04:37:43.524Z] 04:37:43     INFO - TEST-PASS | remote/cdp/test/browser/security/browser_setIgnoreCertificateErrors.js | Expected state is insecure and actual state is insecure - 
[task 2022-12-02T04:37:43.524Z] 04:37:43     INFO - Navigating to https://mismatch.untrusted.example.com:443
[task 2022-12-02T04:37:43.525Z] 04:37:43     INFO - Console message: [JavaScript Warning: "Script terminated by timeout at:
[task 2022-12-02T04:37:43.525Z] 04:37:43     INFO - addLabel@chrome://global/content/aboutNetError.mjs:1071:19
[task 2022-12-02T04:37:43.525Z] 04:37:43     INFO - setTechnicalDetailsOnCertError/<@chrome://global/content/aboutNetError.mjs:1211:21
[task 2022-12-02T04:37:43.526Z] 04:37:43     INFO - " {file: "chrome://global/content/aboutNetError.mjs" line: 1071}]
[task 2022-12-02T04:37:43.527Z] 04:37:43     INFO - Buffered messages finished
[task 2022-12-02T04:37:43.530Z] 04:37:43     INFO - TEST-UNEXPECTED-FAIL | remote/cdp/test/browser/security/browser_setIgnoreCertificateErrors.js | Test timed out - 
[task 2022-12-02T04:37:43.531Z] 04:37:43     INFO - GECKO(5302) | 1669955863259	RemoteAgent	DEBUG	CDPConnection b2d8114a-9da9-4726-a7a5-2eebb7084d63 closed
[task 2022-12-02T04:37:43.531Z] 04:37:43     INFO - GECKO(5302) | [Parent 5302, Main Thread] WARNING: NS_ENSURE_TRUE(!mHasOrHasHadOwnerWindow || mOwnerWindow) failed: file /builds/worker/checkouts/gecko/dom/events/DOMEventTargetHelper.cpp:302
[task 2022-12-02T04:37:43.532Z] 04:37:43     INFO - GECKO(5302) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2022-12-02T04:37:43.532Z] 04:37:43     INFO - GECKO(5302) | MEMORY STAT | vsize 3310MB | residentFast 550MB | heapAllocated 249MB
[task 2022-12-02T04:37:43.533Z] 04:37:43     INFO - TEST-OK | remote/cdp/test/browser/security/browser_setIgnoreCertificateErrors.js | took 90341ms
[task 2022-12-02T04:37:43.533Z] 04:37:43     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-12-02T04:37:43.534Z] 04:37:43     INFO - TEST-UNEXPECTED-FAIL | remote/cdp/test/browser/security/browser_setIgnoreCertificateErrors.js | Found a tab after previous test timed out: https://mismatch.expired.example.com/ - 
[task 2022-12-02T04:37:43.534Z] 04:37:43     INFO - GECKO(5302) | 1669955863343	RemoteAgent	TRACE	CDPConnection b2d8114a-9da9-4726-a7a5-2eebb7084d63 <- {"method":"Target.targetDestroyed","params":{"targetId":"16e35180-92e8-41a8-b717-e00543983ae1"}}
[task 2022-12-02T04:37:43.535Z] 04:37:43     INFO - GECKO(5302) | [Parent 5302, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2022-12-02T04:37:43.535Z] 04:37:43     INFO - GECKO(5302) | [Parent 5302, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2022-12-02T04:37:43.536Z] 04:37:43     INFO - GECKO(5302) | [Child 5509: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f5e33931400 == 1 [pid = 5509] [id = 0]
[task 2022-12-02T04:37:43.538Z] 04:37:43     INFO - GECKO(5302) | [Child 5509: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (7f5e4ef919f0) [pid = 5509] [serial = 1] [outer = 0]
[task 2022-12-02T04:37:43.539Z] 04:37:43     INFO - GECKO(5302) | [Child 5509: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (7f5e33931800) [pid = 5509] [serial = 2] [outer = 7f5e4ef919f0]
[task 2022-12-02T04:37:43.540Z] 04:37:43     INFO - GECKO(5302) | 1669955863393	RemoteAgent	TRACE	CDPConnection b2d8114a-9da9-4726-a7a5-2eebb7084d63 <- {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"0bb1bd85-6ef4-45fb-a392-fc203487698b","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":null}}}
[task 2022-12-02T04:37:43.541Z] 04:37:43     INFO - GECKO(5302) | 1669955863468	RemoteAgent	TRACE	CDPConnection b2d8114a-9da9-4726-a7a5-2eebb7084d63 <- {"method":"Target.targetDestroyed","params":{"targetId":"ae8af274-929f-4d59-9069-9bdb930681f9"}}
[task 2022-12-02T04:37:43.542Z] 04:37:43     INFO - checking window state
[task 2022-12-02T04:37:43.640Z] 04:37:43     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 16 (7f0fef6ac400) [pid = 5302] [serial = 18] [outer = 7f0ffdae2bc0]
[task 2022-12-02T04:37:43.895Z] 04:37:43     INFO - GECKO(5302) | [Child 5446: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7fa440b36400 == 0 [pid = 5446] [id = 0] [url = about:blank]
[task 2022-12-02T04:37:43.995Z] 04:37:43     INFO - GECKO(5302) | [Child 5473: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7fcee5a23c00 == 0 [pid = 5473] [id = 0] [url = about:newtab]
[task 2022-12-02T04:37:44.069Z] 04:37:44     INFO - GECKO(5302) | [Child 5473: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7fcf010919f0) [pid = 5473] [serial = 1] [outer = 0] [url = about:newtab]
[task 2022-12-02T04:37:44.072Z] 04:37:44     INFO - GECKO(5302) | [Child 5473: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7fcee5a26c00) [pid = 5473] [serial = 3] [outer = 0] [url = about:newtab]
[task 2022-12-02T04:37:44.577Z] 04:37:44     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f0ff3212c00 == 6 [pid = 5302] [id = 5] [url = about:blank]
[task 2022-12-02T04:37:44.592Z] 04:37:44     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f0fef6b0400 == 5 [pid = 5302] [id = 6] [url = https://mismatch.expired.example.com/]
[task 2022-12-02T04:37:45.025Z] 04:37:45     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 15 (7f0ff3210000) [pid = 5302] [serial = 13] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:45.110Z] 04:37:45     INFO - GECKO(5302) | [Child 5446: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7fa440b36800) [pid = 5446] [serial = 2] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:45.111Z] 04:37:45     INFO - GECKO(5302) | [Child 5446: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7fa45c1919f0) [pid = 5446] [serial = 1] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:46.160Z] 04:37:46     INFO - GECKO(5302) | Completed ShutdownLeaks collections in process 5509
[task 2022-12-02T04:37:46.210Z] 04:37:46     INFO - GECKO(5302) | Completed ShutdownLeaks collections in process 5473
[task 2022-12-02T04:37:46.225Z] 04:37:46     INFO - GECKO(5302) | Completed ShutdownLeaks collections in process 5446
[task 2022-12-02T04:37:46.420Z] 04:37:46     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (7f0fef750c00) [pid = 5302] [serial = 17] [outer = 0] [url = about:tabcrashed?e=tabcrashed&u=https%3A//mismatch.expired.example.com/&c=UTF-8&d=undefined]
[task 2022-12-02T04:37:46.424Z] 04:37:46     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (7f0fef640090) [pid = 5302] [serial = 15] [outer = 0] [url = about:tabcrashed?e=tabcrashed&u=https%3A//mismatch.expired.example.com/&c=UTF-8&d=undefined]
[task 2022-12-02T04:37:46.426Z] 04:37:46     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (7f0ffb7efc00) [pid = 5302] [serial = 6] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:46.428Z] 04:37:46     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (7f0fefa9c300) [pid = 5302] [serial = 12] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:46.429Z] 04:37:46     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (7f0ff320c800) [pid = 5302] [serial = 14] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:46.510Z] 04:37:46     INFO - GECKO(5302) | Completed ShutdownLeaks collections in process 5372
[task 2022-12-02T04:37:46.893Z] 04:37:46     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (7f0fef420000) [pid = 5302] [serial = 19] [outer = 7f0ffdae2bc0]
[task 2022-12-02T04:37:46.950Z] 04:37:46     INFO - GECKO(5302) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpyjp5f4i2.mozrunner/runtests_leaks_tab_pid5543.log
[task 2022-12-02T04:37:46.952Z] 04:37:46     INFO - GECKO(5302) | [5543, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-12-02T04:37:46.979Z] 04:37:46     INFO - GECKO(5302) | [Child 5543, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:714
[task 2022-12-02T04:37:48.932Z] 04:37:48     INFO - GECKO(5302) | [Parent 5302: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (7f0fef6ac400) [pid = 5302] [serial = 18] [outer = 0] [url = about:blank]
[task 2022-12-02T04:37:49.355Z] 04:37:49     INFO - GECKO(5302) | Completed ShutdownLeaks collections in process 5302
[task 2022-12-02T04:37:49.359Z] 04:37:49     INFO - TEST-START | Shutdown

Somehow the navigation to the untrusted URL caused problems:

[task 2022-12-02T04:37:43.524Z] 04:37:43     INFO - Navigating to https://mismatch.untrusted.example.com:443
[task 2022-12-02T04:37:43.525Z] 04:37:43     INFO - Console message: [JavaScript Warning: "Script terminated by timeout at:
[task 2022-12-02T04:37:43.525Z] 04:37:43     INFO - addLabel@chrome://global/content/aboutNetError.mjs:1071:19
[task 2022-12-02T04:37:43.525Z] 04:37:43     INFO - setTechnicalDetailsOnCertError/<@chrome://global/content/aboutNetError.mjs:1211:21
[task 2022-12-02T04:37:43.526Z] 04:37:43     INFO - " {file: "chrome://global/content/aboutNetError.mjs" line: 1071}]

Lets see if that is still happening over the next days. So far we have 2 instances of it.

The recent failures here show a crash as caused by Fluent trying to format an error:
https://treeherder.mozilla.org/logviewer?job_id=399279840&repo=autoland&lineNumber=55306-55311

[task 2022-12-11T19:40:30.256Z] 19:40:30     INFO - GECKO(5681) | JavaScript warning: chrome://global/content/aboutNetError.mjs, line 1071: Script terminated by timeout at:
[task 2022-12-11T19:40:30.257Z] 19:40:30     INFO - GECKO(5681) | addLabel@chrome://global/content/aboutNetError.mjs:1071:19
[task 2022-12-11T19:40:30.258Z] 19:40:30     INFO - GECKO(5681) | addErrorCodeLink@chrome://global/content/aboutNetError.mjs:1075:13
[task 2022-12-11T19:40:30.258Z] 19:40:30     INFO - GECKO(5681) | setTechnicalDetailsOnCertError/<@chrome://global/content/aboutNetError.mjs:1231:9
[task 2022-12-11T19:40:30.261Z] 19:40:30     INFO - GECKO(5681) | [Child 5812, Main Thread] WARNING: NS_ENSURE_TRUE(JS_Stringify(aCx, &value, nullptr, JS::NullHandleValue, JSONCreator, &serializedValue)) failed: file /builds/worker/checkouts/gecko/dom/base/nsContentUtils.cpp:10574
[task 2022-12-11T19:40:30.288Z] 19:40:30     INFO - GECKO(5681) | Fluent error, the argument "$error" was not provided a value.
[task 2022-12-11T19:40:30.290Z] 19:40:30     INFO - GECKO(5681) | This error happened while formatting the following messages:
[task 2022-12-11T19:40:30.292Z] 19:40:30     INFO - GECKO(5681) |   "cert-error-domain-mismatch-single"
[task 2022-12-11T19:40:30.294Z] 19:40:30     INFO - GECKO(5681) |   "cert-error-code-prefix-link"
[task 2022-12-11T19:40:30.297Z] 19:40:30     INFO - GECKO(5681) | Hit MOZ_CRASH(Resolver error: Unknown variable: $error) at intl/l10n/rust/localization-ffi/src/lib.rs:620

Hm, bug 1771867 landed at that time when this bug got filed and I wonder if that could be related to this problem. Manuel, could you please have a look if that is a regression from your patch? Thanks.

status-firefox108: --- → unaffected
status-firefox109: --- → affected
Flags: needinfo?(manuel)
Keywords: regression, regressionwindow-wanted

Setting bug 1771867 as potential regressor for now.

Keywords: regressionwindow-wanted
Regressed by: 1771867

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

status-firefox110: --- → affected
status-firefox-esr102: --- → unaffected

In general this looks really unrelated to my change. My tests are not run in the same log and almost all the code from Bug 1771867 is disabled by default (behind the network.early-hint.enabled flag). I'll try to look a bit more into it, because the crash seem to stop after backing out my change(?), but do we have another potential regressor that got backed out?

My notes from looking into this so far: This code panics (last line, but comments above are interesting as well):

https://searchfox.org/mozilla-central/rev/17aeb39742eba71e0936ae44a51a54197100166d/intl/l10n/rust/localization-ffi/src/lib.rs#607-620

// This error needs to be actionable for Firefox engineers to fix
// their Fluent issues. It might be nicer to share the specific
// message, but at this point we don't have that information.
eprintln!(
    "Fluent error, the argument \"${}\" was not provided a value.",
    id
);
eprintln!("This error happened while formatting the following messages:");
for key in keys {
    eprintln!("  {:?}", to_string(key))
}

// Panic with the slightly more cryptic ResolverError.
panic!("{}", error.to_string());

These are the eprintln-lines:

Fluent error, the argument "$hostname" was not provided a value.
This error happened while formatting the following messages:
  "cert-error-domain-mismatch-multiple"

Error message directly above: (caused in https://searchfox.org/mozilla-central/rev/17aeb39742eba71e0936ae44a51a54197100166d/dom/base/nsContentUtils.cpp#10583-10584)

[Child 5393, Main Thread] WARNING: NS_ENSURE_TRUE(JS_Stringify(aCx, &value, nullptr, JS::NullHandleValue, JSONCreator, &serializedValue)) failed: file /builds/worker/checkouts/gecko/dom/base/nsContentUtils.cpp:10585
Flags: needinfo?(manuel)

Thank you Manual for having a look into it. As it looks like I missed one of the failures - maybe this result from a backfill job wasn't present at the time when I wrote my comment and I didn't check later again. I've triggered some more backfill jobs for now. Lets see if that gives us a better range:

https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=remote&tochange=6b91a7882aea3269c6fcc658b65331c6d3cea969&fromchange=77e286b67392ad29ddbb7d29cf276988fae34508

The only place where the ftl entry is used for about:neterror:
https://searchfox.org/mozilla-central/rev/f40d29a11f2eb4685256b59934e637012ea6fb78/toolkit/content/aboutNetError.mjs#1180

But hostname is getting assigned the value from HOST_NAME which gets set in getHostName():
https://searchfox.org/mozilla-central/rev/f40d29a11f2eb4685256b59934e637012ea6fb78/toolkit/content/aboutNetError.mjs#29-36

As such I cannot see how it could be null. Note that there is a similar failure complaining about the missing $error for cert-error-domain-mismatch-multiple and cert-error-code-prefix-link:

https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=remote&tochange=6b91a7882aea3269c6fcc658b65331c6d3cea969&fromchange=77e286b67392ad29ddbb7d29cf276988fae34508&selectedTaskRun=Gg61Qa8WTOuZBV1Kuc_Rew.0

Flod, any idea what could be wrong here with Fluent?

Flags: needinfo?(francesco.lodolo)

Redirecting to Eemeli, who's likely in a better position to help.

Flags: needinfo?(francesco.lodolo) → needinfo?(earo)

The getHostName() wrapper only landed on central 5 days ago in bug 1801716 (of which this may be a dupe).

Henrik, is this error still now showing up on builds that include that patch?

Flags: needinfo?(earo) → needinfo?(hskupin)
See Also: → 1801716, 1804829

Eemeli, the failures are still present on autoland for both $hostname and $error. Here two examples:

https://treeherder.mozilla.org/logviewer?job_id=400060915&repo=autoland&lineNumber=55363
https://treeherder.mozilla.org/logviewer?job_id=400094180&repo=autoland&lineNumber=55417

Flags: needinfo?(hskupin) → needinfo?(earo)

Sorry for my slowness; should've marked this explicitly as a dupe much earlier.

Status: NEW → RESOLVED
Closed: 1 year ago
Duplicate of bug: 1801716
Flags: needinfo?(earo)
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.