Closed Bug 919060 Opened 6 years ago Closed 6 years ago

Intermittent TEST-UNEXPECTED-FAIL | browser_625016.js | Test timed out

Categories

(Firefox :: Session Restore, defect)

All
Windows 8
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 28
Tracking Status
firefox26 --- fixed
firefox27 --- fixed
firefox28 --- fixed
firefox-esr24 --- fixed
b2g-v1.2 --- fixed

People

(Reporter: KWierso, Assigned: ttaubert)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

Attached image screenshot.png
https://tbpl.mozilla.org/php/getParsedLog.php?id=28153441&tree=Mozilla-Inbound
slave: t-w864-ix-016

06:43:20  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | Test timed out
06:43:20     INFO -  INFO | automation.py | Launching: C:\slave\test\build\tests\bin\screenshot.exe c:\users\cltbld~1.t-w\appdata\local\temp\mozilla-test-fail_wzvqex
06:43:20     INFO -  SCREENSHOT: [SEE ATTACHMENT]
06:43:21     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | finished in 60025ms




Up above that in the log, there's this, though I'm not sure it's relevant: 06:42:25     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js | no closed windows on first save
06:42:25     INFO -  ++DOCSHELL 429BC4C0 == 106 [id = 2411]
06:42:25     INFO -  ++DOMWINDOW == 459 (35FBBF98) [serial = 6469] [outer = 00000000]
06:42:25     INFO -  ++DOMWINDOW == 460 (35FC11B8) [serial = 6470] [outer = 35FBBF98]
06:42:25     INFO -  [Parent 2308] WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/docshell/base/nsDocShell.cpp, line 8442
06:42:25     INFO -  [Parent 2308] WARNING: Subdocument container has no frame: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/layout/base/nsDocumentViewer.cpp, line 2339
06:42:25     INFO -  ++DOMWINDOW == 461 (35FCEA70) [serial = 6471] [outer = 35F9E518]
06:42:25     INFO -  [Parent 2308] WARNING: Subdocument container has no frame: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/layout/base/nsDocumentViewer.cpp, line 2339
Tim, do you know who would be best to own this? :-)
Flags: needinfo?(ttaubert)
I investigated this and one thing looks suspicious:

21:31:07 | browser_625016.js | starting with no closed windows
21:31:07 | browser_625016.js | no closed windows on first save

And now a succeeding run:

02:15:37 | browser_625016.js | starting with no closed windows
02:15:42 | browser_625016.js | no closed windows on first save

The second run here looks as expected. We wait roughly 4s for the next saveState() call. The first run though continues on the same second which indicates that something else caused a saveState() call before the window was loaded. We then close the window and time out because an untracked window doesn't invalidate the state. (We start tracking windows when they are loaded because we can't determine the window type before that.)

I'll try to reproduce this locally and in case I'm not successful I can add some debug logs and push to try.
Assignee: nobody → ttaubert
Status: NEW → ASSIGNED
Flags: needinfo?(ttaubert)
Ah, thank you :-)
No luck reproducing locally. Pushed to try:

https://tbpl.mozilla.org/?tree=Try&rev=1b5fff93d6fb
Blocks: 824021
Nothing on try :( Pushed debugging code to fx-team, that might be more efficient.

https://hg.mozilla.org/integration/fx-team/rev/8ec18a4f747e
Whiteboard: [leave open]
The stack trace is unfortunately not very helpful in figuring out what's causing the saveState() call as it's mostly native code. Without the ability to reproduce it locally or on try it's going to be hard to figure out the cause.
Duplicate of this bug: 937471
Blocks: 930967
I can reproduce it on my Windows machine, finally. The saveState() call is triggered by an async collection running in the background, introduced with bug 894595. This is going away soon (see 930967) but for now we'll need some tiny fix.
My windows machine was able to confirm that this is the right fix and can rescue the test in case the async bg collection interferes.
Attachment #8336132 - Flags: review?(dteller)
Comment on attachment 8336132 [details] [diff] [review]
0001-Bug-919060-Make-browser_625016.js-wait-for-another-s.patch

The one who reviews first wins my gratitude :)
Attachment #8336132 - Flags: review?(smacleod)
Comment on attachment 8336132 [details] [diff] [review]
0001-Bug-919060-Make-browser_625016.js-wait-for-another-s.patch

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

LGTM
Attachment #8336132 - Flags: review?(smacleod) → review+
Comment on attachment 8336132 [details] [diff] [review]
0001-Bug-919060-Make-browser_625016.js-wait-for-another-s.patch

Thanks!
Attachment #8336132 - Flags: review?(dteller)
Whiteboard: [leave open]
https://hg.mozilla.org/mozilla-central/rev/8baab80b86f0
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 28
You need to log in before you can comment on or make changes to this bug.