Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=348374400&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LJltGCV0QL-7ue0CTB0JIg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LJltGCV0QL-7ue0CTB0JIg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2021-08-13T17:46:01.424Z] 17:46:01     INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js
[task 2021-08-13T17:46:02.762Z] 17:46:02     INFO - TEST-INFO | started process screencapture
[task 2021-08-13T17:46:02.875Z] 17:46:02     INFO - TEST-INFO | screencapture: exit 0
[task 2021-08-13T17:46:02.876Z] 17:46:02     INFO - Buffered messages logged at 17:46:01
[task 2021-08-13T17:46:02.876Z] 17:46:02     INFO - Entering test bound test_discarded
[task 2021-08-13T17:46:02.876Z] 17:46:02     INFO - Extension loaded
[task 2021-08-13T17:46:02.877Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | non-lazy tab onCreated discard property - Expected: true, Actual: true - 
[task 2021-08-13T17:46:02.877Z] 17:46:02     INFO - webNav onCompleted received for 51
[task 2021-08-13T17:46:02.878Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | lazy to non-lazy update discard property - Expected: false, Actual: false - 
[task 2021-08-13T17:46:02.878Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | test-finished - 
[task 2021-08-13T17:46:02.879Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | test result correct - 
[task 2021-08-13T17:46:02.879Z] 17:46:02     INFO - Leaving test bound test_discarded
[task 2021-08-13T17:46:02.879Z] 17:46:02     INFO - Entering test bound test_create_then_discard
[task 2021-08-13T17:46:02.880Z] 17:46:02     INFO - Extension loaded
[task 2021-08-13T17:46:02.880Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | created tab navigation is completed - Expected: 52, Actual: 52 - 
[task 2021-08-13T17:46:02.881Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | created tab url is correct - Expected: http://example.com/, Actual: http://example.com/ - 
[task 2021-08-13T17:46:02.881Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | created tab url is correct - Expected: http://example.com/, Actual: http://example.com/ - 
[task 2021-08-13T17:46:02.882Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | test-finished - 
[task 2021-08-13T17:46:02.882Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | test result correct - 
[task 2021-08-13T17:46:02.883Z] 17:46:02     INFO - Leaving test bound test_create_then_discard
[task 2021-08-13T17:46:02.883Z] 17:46:02     INFO - Entering test bound test_create_discarded
[task 2021-08-13T17:46:02.884Z] 17:46:02     INFO - Extension loaded
[task 2021-08-13T17:46:02.884Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | lazy tab is not active - Expected: false, Actual: false - 
[task 2021-08-13T17:46:02.885Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | lazy tab is discarded - Expected: true, Actual: true - 
[task 2021-08-13T17:46:02.885Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | lazy tab url is correct - Expected: http://example.com/, Actual: http://example.com/ - 
[task 2021-08-13T17:46:02.886Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | lazy tab title is correct - Expected: discarded tab, Actual: discarded tab - 
[task 2021-08-13T17:46:02.886Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | restored tab url matches active tab url - Expected: http://example.com/, Actual: http://example.com/ - 
[task 2021-08-13T17:46:02.887Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | restored tab title is correct - Expected: mochitest index /, Actual: mochitest index / - 
[task 2021-08-13T17:46:02.888Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | test-finished - 
[task 2021-08-13T17:46:02.888Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | test result correct - 
[task 2021-08-13T17:46:02.889Z] 17:46:02     INFO - Leaving test bound test_create_discarded
[task 2021-08-13T17:46:02.889Z] 17:46:02     INFO - Entering test bound test_discarded_private_tab_restored
[task 2021-08-13T17:46:02.889Z] 17:46:02     INFO - Extension loaded
[task 2021-08-13T17:46:02.890Z] 17:46:02     INFO - Buffered messages logged at 17:46:02
[task 2021-08-13T17:46:02.890Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | private tab should be discarded - 
[task 2021-08-13T17:46:02.890Z] 17:46:02     INFO - Switching to the discarded background tab
[task 2021-08-13T17:46:02.891Z] 17:46:02     INFO - Wait for the restored tab to complete loading
[task 2021-08-13T17:46:02.891Z] 17:46:02     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | discarded private tab should have been restored - 
[task 2021-08-13T17:46:02.892Z] 17:46:02     INFO - Buffered messages finished
[task 2021-08-13T17:46:02.892Z] 17:46:02     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | Got the expected url on the restored tab - Got "about:blank", expected "https://example.com/"
[task 2021-08-13T17:46:02.892Z] 17:46:02     INFO - Stack trace:
[task 2021-08-13T17:46:02.892Z] 17:46:02     INFO - chrome://mochikit/content/browser-test.js:test_is:1364
[task 2021-08-13T17:46:02.892Z] 17:46:02     INFO - chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_tabs_discarded.js:test_discarded_private_tab_restored:230
[task 2021-08-13T17:46:02.902Z] 17:46:02     INFO - Leaving test bound test_discarded_private_tab_restored
[task 2021-08-13T17:46:02.902Z] 17:46:02     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-08-13T17:46:02.903Z] 17:46:02     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | message queue is empty - Got "[\"tab-discarded\"]", expected "[]"
[task 2021-08-13T17:46:02.903Z] 17:46:02     INFO - Stack trace:
[task 2021-08-13T17:46:02.903Z] 17:46:02     INFO - chrome://mochikit/content/browser-test.js:test_is:1364
[task 2021-08-13T17:46:02.903Z] 17:46:02     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:32
[task 2021-08-13T17:46:02.903Z] 17:46:02     INFO - chrome://mochikit/content/browser-test.js:nextTest:561
[task 2021-08-13T17:46:02.907Z] 17:46:02     INFO - GECKO(3056) | MEMORY STAT | vsize 7966MB | residentFast 362MB | heapAllocated 166MB
[task 2021-08-13T17:46:02.907Z] 17:46:02     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | took 1483ms
[task 2021-08-13T17:46:02.915Z] 17:46:02     INFO - checking window state
[task 2021-08-13T17:46:02.922Z] 17:46:02     INFO - GECKO(3056) | Completed ShutdownLeaks collections in process 3056

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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Update:
There have been 31 failures within the last 7 days:
• 7 failures on Linux 18.04 x64 WebRender opt
• 17 failures on Linux 18.04 x64 WebRender debug
• 6 failures on Linux 18.04 x64 WebRender Shippable opt
• 1 failures on Windows 10 x64 2004 WebRender debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=373901355&repo=autoland&lineNumber=7020

[task 2022-04-08T18:52:53.720Z] 18:52:53     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | discarded private tab should have been restored - 
[task 2022-04-08T18:52:53.722Z] 18:52:53     INFO - Buffered messages finished
[task 2022-04-08T18:52:53.725Z] 18:52:53     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | Got the expected url on the restored tab - Got "about:blank", expected "https://example.com/"
[task 2022-04-08T18:52:53.725Z] 18:52:53     INFO - Stack trace:
[task 2022-04-08T18:52:53.726Z] 18:52:53     INFO - chrome://mochikit/content/browser-test.js:test_is:1422
[task 2022-04-08T18:52:53.726Z] 18:52:53     INFO - chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_tabs_discarded.js:test_discarded_private_tab_restored:230
[task 2022-04-08T18:52:53.726Z] 18:52:53     INFO - chrome://mochikit/content/browser-test.js:handleTask:989
[task 2022-04-08T18:52:53.726Z] 18:52:53     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1061
[task 2022-04-08T18:52:53.726Z] 18:52:53     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1189
[task 2022-04-08T18:52:53.727Z] 18:52:53     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:978
[task 2022-04-08T18:52:53.728Z] 18:52:53     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041
[task 2022-04-08T18:52:53.729Z] 18:52:53     INFO - Leaving test bound test_discarded_private_tab_restored
[task 2022-04-08T18:52:53.730Z] 18:52:53     INFO - GECKO(7456) | MEMORY STAT | vsize 12635MB | residentFast 769MB | heapAllocated 660MB
[task 2022-04-08T18:52:53.730Z] 18:52:53     INFO - TEST-OK | browser/components/extensions/test/browser/browser_ext_tabs_discarded.js | took 2582ms
[task 2022-04-08T18:52:53.731Z] 18:52:53     INFO - checking window state
[task 2022-04-08T18:52:53.732Z] 18:52:53     INFO - GECKO(7456) | must wait for focus
[task 2022-04-08T18:52:53.745Z] 18:52:53     INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_tabs_duplicate.js

Hi Shane! Can you please take a look at this? Maybe you could help us assign this to someone.
Thank you!

Lets see if the patch in this try push will address this.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2e5ea468e6f52892f04d03e19950bd3a74d517dd

and one more attempt.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c1ef803be2cbbdf240c3d4825f7e6dab33e96914

I've been able to trigger this locally often and quickly enough by setting the MOZ_CHAOSMODE=3 environment var along with mach mochitest --verify.

After digging into it more, I confirmed that this intermittent become more frequent after the changes landed for Bug 1760936 (as I did mention in Bug 1760936 comment 10 I was already suspecting that may have been the case).

The underlying issue seems to be similar to the one described in Bug 1724205 comment 15:

• SessionStore TabListener is likely being executed before resetBrowserToLazyState and be able to set the single "isPrivate" property into the tabStateCache
• when resetBrowserToLazyState gets called after SessionStore's TabListener has set the isPrivate property, the tab cacheState is not undefined and the tab may or may not be already started loading
• it did already start to load the test pass, otherwise it fails because the userTypedValue isn't getting stored in the tabStateCache anymore and the tab is going to be restored as about:blank

The patch attached makes sure to check if the tab cacheState does only include the "isPrivate" property, and if that is the case it does store the userTypedValue into the tab state as it would if the cacheState was undefined, which was making the test to pass consistently for me locally.

I've pushed it to try here to confirm if that also consistently prefer the intermittent failures when running on the build infrastucture:

• https://treeherder.mozilla.org/#/jobs?repo=try&revision=a355ae0ae9f67f8db0c7401b1cc6e28b9acab4af

As a side note:
I'm not really that thrilled about the attached patch, the fact that we have to keep adding special cases to the resetBrowserToLazyState to handle properly the various corner cases suggests that, as we have been discussing with Gijs in https://phabricator.services.mozilla.com/D142372, it may be reasonable to consider what kind of changes could make it easier for SessionStore internals to distinguish tabs that never completely load or were discarded right away from tabs where an url was already loaded and user typed a value in the urlbar in a less fragile way, which is tracked by Bug 1763159 (and so I'm adding it as a "seealso" for this issue).

Backed out for causing mochitest failures on browser_ext_tabs_discarded.js. CLOSED TREE

Backout link : https://hg.mozilla.org/integration/autoland/rev/d1b733de4e35bb57af798c88e06373615a710213

Push with failures : https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Crunnable&revision=37b175d0a9fc3e95f507a88bc841cfeb1e00d8ab&selectedTaskRun=V6kDDN-pQQuTIh-_fFrT_g.0

Link to failure log : https://treeherder.mozilla.org/logviewer?job_id=376945724&repo=autoland&lineNumber=22201

(In reply to Cristina Cozmuta (:CrissCozmuta) from comment #44)

Backed out for causing mochitest failures on browser_ext_tabs_discarded.js. CLOSED TREE

Backout link : https://hg.mozilla.org/integration/autoland/rev/d1b733de4e35bb57af798c88e06373615a710213

Push with failures : https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Crunnable&revision=37b175d0a9fc3e95f507a88bc841cfeb1e00d8ab&selectedTaskRun=V6kDDN-pQQuTIh-_fFrT_g.0

Link to failure log : https://treeherder.mozilla.org/logviewer?job_id=376945724&repo=autoland&lineNumber=22201

Apologies for not being able to get back to this any sooner.

After having looked closely to the failure that triggered the backout I noticed that it was happening in a job running in non-fission mode,
and it is actually not an intermittent failure but a permanent one while running the two "early discard" test tasks.

I can trigger the failure consistently also on my local linux64 system, using mach mochitest browser/components/extensions/test/browser/browser_ext_tabs_discarded.js --disable-fission (while it passes consistently with fission enabled).

After digging a bit more into what was going on and having added some tracing logs for the values set for userTypedValue, hasStartedLoad etc. when that failure gets triggered, I noticed that:

• userTypedValue is null (and so that makes shouldUpdateCacheState to also be set to null)
• hasNoCacheState is true (and so it is undefined or it has only the isPrivate property)
• browser.currentURI.spec is set to the url that the test expects to be restored

browser.currentURI.spec is actually stored as an url property into TAB_LAZY_STATES, but it doesn't seem that we are picking that url anywhere when we are sending the data to be restored as part of the onTabBrowserInserted method and so ContentRestore.restoreTabContent is definitely setting about:blank as the url restored on that tab in the end.

Another interesting detail to notice is that the frequency of this intermittent did actually drop a lot over the last month, which seems to suggest that we may have landed some other change in the area that has making the failure way less frequent.

As an additional confirmation I tried locally:

• to revert all the changes applied on the SessionStore.jsm in the attached patch
• and run the improved version of the "early discarded tabs" tests with MOZ_CHAOSMODE=3 and --verify

but I've not been able to trigger the intermittent failure that I was able to trigger a month ago.

Besides that, the fact that the test case as is in mozilla-central isn't failing on non fission makes me think that the coverage provided by the current one may not be able to catch it, but I can't yet see which part of the changes to the test from the attached patch may trigger that change in behavior.

In the end, the permafailure on non-fission seems a legit bug, but I'm not sure if it is as critical as to justify further changes to special case the corner case in a non-fission config.

I verified that technically storing the value got from browser.currentURI.spec into TabStateCache in place of a null userTypedValue when the tab didn't already start to load would make those tests in the attached patch to pass consistently with and without fission.

It would basically look like:

    let shouldUpdateCacheState =
      hasNoCacheState ||
      (hasStartedLoad && !cacheState.userTypedValue);

    if (shouldUpdateCacheState) {
      // Discard was likely called before state can be cached.  Update
      // the persistent tab state cache with browser information so a
      // restore will be successful.  This information is necessary for
      // restoreTabContent in ContentRestore.jsm to work properly.
      TabStateCache.update(browser.permanentKey, {
        userTypedValue: userTypedValue || browser.currentURI.spec,
        userTypedClear: 1,
      });
    }

but honestly I'm on thrilled of resorting to that kind of change, especially if that would be only needed for a configuration (non-fission) that should be "fading away" and be fully replaced with fission on all configs.

I'd like to get Gijs perspective before planning another update on the attached patch (or to just dropping it and marking it as obsolete, e.g. if the lower frequency of the current intermittent failures and the non-fission corner case doesn't seem worth doing more work on it).

Hey Gijs,
sorry to bother you again for this issue, I looked into the failure that triggered the backout and it looks like a non-fission issue

I'd like to hear your opinion and perspective about what I observed and described in comment 46, would you mind to take a look?

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #47)

Hey Gijs,
sorry to bother you again for this issue, I looked into the failure that triggered the backout and it looks like a non-fission issue

I'd like to hear your opinion and perspective about what I observed and described in comment 46, would you mind to take a look?

Storing the currently-loading/loaded URL as userTypedValue is something we used to do when restoring history was complete, which Nika removed in https://phabricator.services.mozilla.com/D145389 . Adding it back for discarded tabs feels like it's going in the opposite direction... but I don't know, perhaps that's justified in the circumstances. So passing the buck to Nika in case she has ideas here.

In places like bug 610357 we might need to investigate a similar approach. Either way, I don't know that I have a strong opinion - I guess I'm missing the piece of why this doesn't work with fission disabled. Is it "just" a race condition or is something "actually" related to fission going on that determines whether or not things fail? E.g. for this:

• userTypedValue is null (and so that makes shouldUpdateCacheState to also be set to null)
• hasNoCacheState is true (and so it is undefined or it has only the isPrivate property)
• browser.currentURI.spec is set to the url that the test expects to be restored

What are the passing values in the fission / non-fission case?

I haven't had the brainpower yet this week to read through the sessionstore code again and figure out where the issue is here so I can understand it. My basic understanding right now is there is some case during session restore where a tab has been partially restored, but not fully enough , and then it's lazified while loading, and that causes breakage in the non-fission case? I suppose that this could be caused by the fact that the Fission case synchronously can populate & read from session history, whereas the async nature of the non-fission case could break for that.

FWIW I chatted with :peterv recently and I think we're quite close to being able to get rid of the non-SHIP codepath completely, which might also simplify things here a lot.

Adding :farre in case he has more insight into what might be happening here.

Yeah, so the restore steps are my weak point in session restore. If I get some time left this week I can take a look.

(In reply to :Gijs (he/him) from comment #49)

In places like bug 610357 we might need to investigate a similar approach. Either way, I don't know that I have a strong opinion - I guess I'm missing the piece of why this doesn't work with fission disabled. Is it "just" a race condition or is something "actually" related to fission going on that determines whether or not things fail? E.g. for this:

• userTypedValue is null (and so that makes shouldUpdateCacheState to also be set to null)
• hasNoCacheState is true (and so it is undefined or it has only the isPrivate property)
• browser.currentURI.spec is set to the url that the test expects to be restored

What are the passing values in the fission / non-fission case?

:Gijs apologies for not being able to reply sooner, in both cases (fission, where both test case in the attached patch passes, and non fission, where are both passing) are exactly the same as the following dump (besides the value set on the fissionAutostart one):

 0:05.70 GECKO(1245448) CANARY {
 0:05.70 GECKO(1245448)   "fissionAutostart": true,
 0:05.70 GECKO(1245448)   "browserCurrentURI": "https://example.com/",
 0:05.70 GECKO(1245448)   "shouldUpdateCacheState": null,
 0:05.70 GECKO(1245448)   "userTypedValue": null,
 0:05.70 GECKO(1245448)   "hasNoCacheState": true,
 0:05.70 GECKO(1245448)   "hasStartedLoad": false
 0:05.70 GECKO(1245448) }

Let me know if I misunderstood your question and these weren't the details you were interested to.

In case it can be helpful to reproduce the same again locally, it can be reproduced by applying the patch attached and on top of that the following small diff:

diff --git a/browser/components/sessionstore/SessionStore.jsm b/browser/components/sessionstore/SessionStore.jsm
--- a/browser/components/sessionstore/SessionStore.jsm
+++ b/browser/components/sessionstore/SessionStore.jsm
@@ -2628,6 +2628,16 @@ var SessionStoreInternal = {
       userTypedValue &&
       (hasNoCacheState || (hasStartedLoad && !cacheState.userTypedValue));
 
+    dump(`CANARY ${JSON.stringify({
+      fissionAutostart: Services.appinfo.fissionAutostart,
+      browserCurrentURI: browser.currentURI.spec,
+      shouldUpdateCacheState,
+      userTypedValue,
+      hasNoCacheState,
+      hasStartedLoad,
+      cacheStateUserTypedValue: cacheState?.userTypedValue,
+    }, null, 2)}\n`);
+
     if (shouldUpdateCacheState) {
       // Discard was likely called before state can be cached.  Update
       // the persistent tab state cache with browser information so a

I don't think there is currently any need to rush on digging more into the unexpected behavior in non-fission, given that the patch attached was initially prompted by a pretty high intermittent failure of the test in the default fission-enabled config (which doesn't seem to be happening that frequently anymore), but the help investigating it is not any less appreciated!

Thanks a lot to everyone (Gijs, Nika and Adreas) helping investigating the unexpected difference in behavior between fission and non-fission mode.

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:rpl, could you have a look please?
If you still have some work to do, you can add an action "Plan Changes" in Phabricator.
For more information, please visit auto_nag documentation.