1961034 - GeckoView wpt-reftest logcat logs are 30% logspam from `TypeError: can't access property "nodePrincipal", this.contentDocument is null` and `TypeError: can't access property "title", this.contentDocument is null`

Status: NEW

(GeckoView :: General, defect, P5)

Description

[Daniel Holbert [:dholbert]]

STR:

1. Look at the parsed log for a recent opt-geckoview-web-platform-tests-reftest run, e.g. any of the logs here:
   https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=opt-geckoview-web-platform-tests-reftest&revision=6e2e24c9d89bd8cb69d2e6af7c7ebd730523d461 (I'll use this log from the first "Wr1" linked there as my example: https://treeherder.mozilla.org/logviewer?job_id=504331581&repo=autoland )

2. Scroll down in the top left part of the header and click through to the logcat-*.log -- in my example, that takes you here:
   https://firefoxci.taskcluster-artifacts.net/W9Wqzz29RRm47NJSvbpidw/0/public/test_info/logcat-emulator-5554.log

3. Use Ctrl+F or grep to find matches for TypeError: can't access property "nodePrincipal", this.contentDocument is null

ACTUAL RESULTS:
Many thousands of copies of that line -- 7843 copies in the log that I linked. Each instance of that line is actually part of a 3-line error...

E GeckoConsole: [JavaScript Error: "TypeError: can't access property "nodePrincipal", this.contentDocument is null" {file: "chrome://global/content/elements/browser-custom-element.js" line: 661}]
E GeckoConsole: get contentPrincipal@chrome://global/content/elements/browser-custom-element.js:661:1
E GeckoConsole: onLocationChange@resource://gre/modules/GeckoViewNavigation.sys.mjs:640:34

...so (including that backtrace) this logging actually takes up 7843 * 3 = 23529 lines in the logcat log, which is 18% of the lines of the log (there are 130394 lines total).

EXPECTED RESULTS:
Ideally no such TypeErrors being triggered by our UI filling up our logcat logs.

Comment 1

[Daniel Holbert [:dholbert]]

Relatedly, there are also a bunch of these similar errors about title (instead of nodePrincipal), often appearing alongside the nodePrincipal one that I quoted above:

E GeckoConsole: [JavaScript Error: "TypeError: can't access property "title", this.contentDocument is null" {file: "chrome://global/content/elements/browser-custom-element.js" line: 630}]
E GeckoConsole: get contentTitle@chrome://global/content/elements/browser-custom-element.js:630:1
E GeckoConsole: handleEvent@resource://gre/modules/GeckoViewContent.sys.mjs:379:11

grep tells me there are 5919 matches for "TypeError: can't access property "title", this.contentDocument is null". Assuming each is part of a 3-line pattern (with the backtrace as quoted above), that means this error is responsible for 5919*3 = 17757 lines in this log, which is 13.6% of the log.

So these two errors combined (and their backtraces) are responsible for (7843+5919)*3 / 130394 * 100% = 31.66% of the lines in this logcat log.

Comment 2

[Daniel Holbert [:dholbert]]

The backtrace in comment 0 links to GeckoViewNavigation.sys.mjs:640 which is the final line here:
https://searchfox.org/mozilla-central/rev/3b95c8dbe724b10390c96c1b9dd0f12c873e2f2e/mobile/shared/modules/geckoview/GeckoViewNavigation.sys.mjs#622,640

onLocationChange(aWebProgress, aRequest, aLocationURI) {
...
  const { contentPrincipal } = this.browser;

This is implicitly querying this.browser.contentPrincipal which is defined in browser-custom-element.js here:
https://searchfox.org/mozilla-central/rev/3b95c8dbe724b10390c96c1b9dd0f12c873e2f2e/toolkit/content/widgets/browser-custom-element.js#658-661

get contentPrincipal() {
  return this.isRemoteBrowser
    ? this._contentPrincipal
    : this.contentDocument.nodePrincipal;

The backtrace in comment 1 links back to GeckoViewContent.sys.mjs:379 which is the final line here:
https://searchfox.org/mozilla-central/rev/3b95c8dbe724b10390c96c1b9dd0f12c873e2f2e/mobile/shared/modules/geckoview/GeckoViewContent.sys.mjs#343,346,376-379

handleEvent(aEvent) {
...
  switch (aEvent.type) {
...
    case "pagetitlechanged":
      this.eventDispatcher.sendRequest({
        type: "GeckoView:PageTitleChanged",
        title: this.browser.contentTitle,

...and this.browser.contentTitle there maps to this in browser-custom-element.js:
https://searchfox.org/mozilla-central/rev/3b95c8dbe724b10390c96c1b9dd0f12c873e2f2e/toolkit/content/widgets/browser-custom-element.js#626-631

get contentTitle() {
  return (
    (this.isRemoteBrowser
      ? this.browsingContext?.currentWindowGlobal?.documentTitle
      : this.contentDocument.title) ?? ""
  );

In both cases, we end up reading this.contentDocument.[something] which is problematic since the error logspam is telling us that the browser object's this.contentDocument is null.

Comment 3

[Daniel Holbert [:dholbert]]

So I guess the questions here are:
(1) Why/how do we end up with a this.browser whose contentDocument is null?

(2) Whatever the explanation is: should we fix it up to somehow ensure that this.browser has a contentDocument that is not null? Or, should we change things to gracefully handle the possibility that it might be null? (i.e. adding null-checks somewhere)