Closed Bug 1331853 Opened 7 years ago Closed 5 years ago

Intermittent browser/components/sessionstore/test/browser_dying_cache.js | the window has one closed tab - Got 0, expected 1

Categories

(Firefox :: Session Restore, defect)

Product:
Firefox
Component:
Session Restore
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Assigned: gbrown)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell disabled])

Attachments

(1 file)

skip test on windows
663 bytes, patch
wiwang
: review+
Details | Diff | Splinter Review 
this test has a moderate failure rate, possibly it changed a few days ago, but nothing serious enough to spend much time investigating.
Whiteboard: [stockwell unknown]
this test picked up on April 29th for win7 opt browser-chrome-e10s.

here is a failure log:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=97949932&lineNumber=2819

and a screenshot (just the book of mozilla single tab) and it looks like there are multiple firefox windows (which browser chrome always has a controller window):
https://public-artifacts.taskcluster.net/OnTjJnaUQyWMZKIA2WsXog/0/public/test_info/mozilla-test-fail-screenshot_ldxo8v.png

and here is an example of the failure:
08:01:19     INFO -  513 INFO TEST-START | browser/components/sessionstore/test/browser_dying_cache.js
08:01:19     INFO -  TEST-INFO | started process screenshot
08:01:19     INFO -  TEST-INFO | screenshot: exit 0
08:01:19     INFO -  Buffered messages logged at 08:01:19
08:01:19     INFO -  514 INFO Entering test bound test
08:01:19     INFO -  515 INFO TEST-PASS | browser/components/sessionstore/test/browser_dying_cache.js | window is being tracked by sessionstore -
08:01:19     INFO -  516 INFO TEST-PASS | browser/components/sessionstore/test/browser_dying_cache.js | the window has a single tab -
08:01:19     INFO -  517 INFO TEST-PASS | browser/components/sessionstore/test/browser_dying_cache.js | the tab is about:mozilla -
08:01:19     INFO -  Buffered messages finished
08:01:19    ERROR -  518 INFO TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | the window has one closed tab - Got 0, expected 1
08:01:19     INFO -  Stack trace:
08:01:19     INFO -      chrome://mochikit/content/browser-test.js:test_is:928
08:01:19     INFO -      chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:checkWindowState:50
08:01:19     INFO -      chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:test:28
08:01:19     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:752:9
08:01:19     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:672:7
08:01:19     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
08:01:19     INFO -  GECKO(5264) | *************************
08:01:19     INFO -  GECKO(5264) | A coding exception was thrown and uncaught in a Task.
08:01:19     INFO -  GECKO(5264) | Full message: TypeError: can't convert undefined to object
08:01:19     INFO -  GECKO(5264) | Full stack: checkWindowState@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:51:7
08:01:19     INFO -  GECKO(5264) | test@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:28:3
08:01:19     INFO -  GECKO(5264) | Tester_execTest@chrome://mochikit/content/browser-test.js:752:9
08:01:19     INFO -  GECKO(5264) | Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:672:7
08:01:19     INFO -  GECKO(5264) | SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
08:01:19     INFO -  GECKO(5264) | *************************
08:01:19     INFO -  Not taking screenshot here: see the one that was previously logged
08:01:19    ERROR -  519 INFO TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:51 - TypeError: can't convert undefined to object
08:01:19     INFO -  Stack trace:
08:01:19     INFO -      checkWindowState@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:51:7
08:01:19     INFO -      test@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:28:3
08:01:19 
    INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:752:9
08:01:19     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:672:7
08:01:19     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
08:01:19     INFO -      Tester_execTest@chrome://mochikit/content/browser-test.js:752:9
08:01:19     INFO -      Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:672:7
08:01:19     INFO -      SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
08:01:19     INFO -  520 INFO Leaving test bound test
08:01:19     INFO -  GECKO(5264) | MEMORY STAT | vsize 867MB | vsizeMaxContiguous 493MB | residentFast 388MB | heapAllocated 193MB
08:01:19     INFO -  521 INFO TEST-OK | browser/components/sessionstore/test/browser_dying_cache.js | took 488ms
08:01:19     INFO -  522 INFO checking window state
08:01:19     INFO -  Not taking screenshot here: see the one that was previously logged
08:01:19    ERROR -  523 INFO TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | Found an unexpected browser window at the end of test run -
08:01:19     INFO -  GECKO(5264) | must wait for focus


:mikedeboer, can you take a look at this or help find someone on the sessionrestore team to look at this failure?
Flags: needinfo?(mdeboer)
Whiteboard: [stockwell unknown] → [stockwell needswork]
I'm really cramped for time at the moment, so I'm hoping Will has a bit of time...?
Flags: needinfo?(mdeboer) → needinfo?(wiwang)
I will try to investigate as much as I can and I probably don't have much time for this, since I'm currently busy with some other Quantum Flow bugs..  :'(

Hi Yoric, Tim, it seems that you understood this test before, would it be possible for you to share some thoughts/clues about the first glance at the failure? 

Besides, from the orange factor history[1], I found that _almost_ all of the failures recently(from April to now) are on the windows platform, especially the 'windows7-32-vm'... I'm not sure the reason, it's likely the 'windows7-32-vm' is way too slow.


[1] https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1331853&entireHistory=true&tree=all
Flags: needinfo?(wiwang)
Flags: needinfo?(ttaubert)
Flags: needinfo?(dteller)
Sorry, I currently have no time to investigate :(
Flags: needinfo?(ttaubert)
Tim, thanks anyway! :)

==

Keep NI myself for tracking.
Flags: needinfo?(wiwang)
I don't remember anything about that test, I'm afraid. Sorry about that :/
Flags: needinfo?(dteller)
:WillWang - Thanks for your efforts here! Since it looks like it may take some time to find a solution here, let's disable the test on Windows for now.
Attachment #8871796 - Flags: review?(wiwang)
Comment on attachment 8871796 [details] [diff] [review]
skip test on windows

Review of attachment 8871796 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for your work, Geoff!

== Some note for the investigation afterwards == 

From several similar logs, the test failed at:
    ERROR -  418 INFO TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | the window has one closed tab - Got 0, expected 1
which is from the code here:
    is(ss.getClosedTabCount(window), 1, "the window has one closed tab"); ......[1]
which is about after we call promiseRemoveTab(win.gBrowser.tabs[0]); ......[2]

I suspect that the test needs more time for the gap between [1] and [2], to get the correct closed tab count(we expect 1).

Set as r+ since this might not introduce too much risk, from my limited experience; and other platforms are still running this test.


[1] is(ss.getClosedTabCount(window), 1, "the window has one closed tab");
http://searchfox.org/mozilla-central/rev/1a0d9545b9805f50a70de703a3c04fc0d22e3839/browser/components/sessionstore/test/browser_dying_cache.js#50

[2] await promiseRemoveTab(win.gBrowser.tabs[0]);
http://searchfox.org/mozilla-central/rev/1a0d9545b9805f50a70de703a3c04fc0d22e3839/browser/components/sessionstore/test/browser_dying_cache.js#22
Attachment #8871796 - Flags: review?(wiwang) → review+
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/299efa8c78ee
Skip browser_dying_cache.js on Windows, for intermittent failures; r=WillWang
Keywords: leave-open
Whiteboard: [stockwell needswork] → [stockwell disabled]
Blocks: 1373708
In the last 7 days we have 67 failures, they started to increase with 10th of Jan.
They occur on Linux, Linux x64-disabled, linux32-nightly, disabled, OS X 10.10.
The affected build types are asan, debug, opt, pgo.
Recent log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=155793512&lineNumber=3962
and a relevant part of it:

[task 2018-01-12T01:08:33.505Z] 01:08:33     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | the window has one closed tab - Got 0, expected 1
3963
[task 2018-01-12T01:08:33.505Z] 01:08:33     INFO - Stack trace:
3964
[task 2018-01-12T01:08:33.506Z] 01:08:33     INFO - chrome://mochikit/content/browser-test.js:test_is:1269
3965
[task 2018-01-12T01:08:33.506Z] 01:08:33     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:checkWindowState:50
3966
[task 2018-01-12T01:08:33.507Z] 01:08:33     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:test:28
3967
[task 2018-01-12T01:08:33.508Z] 01:08:33     INFO - Not taking screenshot here: see the one that was previously logged
3968
[task 2018-01-12T01:08:33.512Z] 01:08:33     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | Uncaught exception - at chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:51 - TypeError: JSON.parse(...)[Symbol.iterator](...).next(...).value is undefined
3969
[task 2018-01-12T01:08:33.512Z] 01:08:33     INFO - Stack trace:
3970
[task 2018-01-12T01:08:33.513Z] 01:08:33     INFO -     checkWindowState@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:51:7
3971
[task 2018-01-12T01:08:33.514Z] 01:08:33     INFO -     test@chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_dying_cache.js:28:3
3972
[task 2018-01-12T01:08:33.515Z] 01:08:33     INFO -     Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1065:21
3973
[task 2018-01-12T01:08:33.515Z] 01:08:33     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:1056:9
3974
[task 2018-01-12T01:08:33.516Z] 01:08:33     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:956:9
3975
[task 2018-01-12T01:08:33.518Z] 01:08:33     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
3976
[task 2018-01-12T01:08:33.519Z] 01:08:33     INFO - Leaving test bound test
3977
[task 2018-01-12T01:08:33.521Z] 01:08:33     INFO - GECKO(2812) | MEMORY STAT | vsize 2767MB | residentFast 419MB | heapAllocated 163MB
3978
[task 2018-01-12T01:08:33.522Z] 01:08:33     INFO - TEST-OK | browser/components/sessionstore/test/browser_dying_cache.js | took 588ms
3979
[task 2018-01-12T01:08:33.523Z] 01:08:33     INFO - checking window state
3980
[task 2018-01-12T01:08:33.523Z] 01:08:33     INFO - Not taking screenshot here: see the one that was previously logged
3981
[task 2018-01-12T01:08:33.524Z] 01:08:33     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_dying_cache.js | Found an unexpected browser window at the end of test run - 
3982
[task 2018-01-12T01:08:33.525Z] 01:08:33     INFO - GECKO(2812) | must wait for focus
:mikedeboer, can you please take a look at this?
No longer blocks: 1373708
Flags: needinfo?(mdeboer)
Whiteboard: [stockwell disabled] → [stockwell needswork]
The frequency uptick got fixed by the backout of bug 1373708.
Blocks: 1373708
Flags: needinfo?(mdeboer)
Whiteboard: [stockwell needswork] → [stockwell disabled]
No longer blocks: 1373708
The leave-open keyword is there and there is no activity for 6 months.
:mikedeboer, maybe it's time to close this bug?
Flags: needinfo?(mdeboer)
Assignee: nobody → gbrown
Status: NEW → RESOLVED
Closed: 5 years ago
Flags: needinfo?(mdeboer)
Keywords: leave-open
Resolution: --- → FIXED
Flags: needinfo?(wiwang)

This test remains skipped on Windows. Do we plan to investigate fixing and re-enabling it there?

Flags: needinfo?(mdeboer)

No, I don't have any cycles to investigate this further than Will has tried.

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

Attachment

General

Creator:
Created:
Updated:
Size: