Open Bug 1430977 Opened 7 years ago Updated 9 months ago

Intermittent browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1

Categories

(Firefox :: Session Restore, defect, P5)

Product:
Firefox
Component:
Session Restore
Type:
defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

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

Attachments

(2 files)

Skipped test on linux64 asan
760 bytes, patch
jmaher
: review+
Details | Diff | Splinter Review
Bug 1430977 - Disable browser_625016.js on Win-debug. r=aryx
47 bytes, text/x-phabricator-request
Details | Review 
There is a total of 63 failures in the last 7 days on windows7-32, linux32, linux64 and windows10-64.

Recent failure logs: https://treeherder.mozilla.org/logviewer.html#?job_id=194748589&repo=mozilla-central&lineNumber=2711

11:14:39     INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
11:14:41     INFO - TEST-INFO | started process screenshot
11:14:41     INFO - TEST-INFO | screenshot: exit 0
11:14:41     INFO - Buffered messages logged at 11:14:39
11:14:41     INFO - Entering test bound setup
11:14:41     INFO - Buffered messages logged at 11:14:40
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | starting with no closed windows - 
11:14:41     INFO - Leaving test bound setup
11:14:41     INFO - Entering test bound new_window
11:14:41     INFO - Buffered messages logged at 11:14:41
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save - 
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/prerendered/static/activity-stream-initial-state.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://browser/content/contentSearchUI.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://browser/content/contentTheme.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react-dom.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/prop-types.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react-intl.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/redux.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react-redux.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/prerendered/en-US/activity-stream-strings.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/data/content/activity-stream.bundle.js”." {file: "about:newtab" line: 1}]
11:14:41     INFO - Buffered messages finished
11:14:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
11:14:41     INFO - Stack trace:
11:14:41     INFO - chrome://mochikit/content/browser-test.js:test_is:1308
11:14:41     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:38
11:14:41     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
11:14:41     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
11:14:41     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:999
11:14:41     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk - 
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: 1 closed window according to API - 
11:14:41     INFO - Leaving test bound new_window
11:14:41     INFO - Entering test bound new_tab
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 window in data being written to disk - 
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window in data being written to disk - 
11:14:41     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window according to API - 
11:14:41     INFO - Leaving test bound new_tab
11:14:41     INFO - Entering test bound done
11:14:41     INFO - Leaving test bound done
11:14:41     INFO - GECKO(7672) | MEMORY STAT | vsize 17304007MB | vsizeMaxContiguous 115781028MB | residentFast 1693MB
11:14:41     INFO - TEST-OK | browser/components/sessionstore/test/browser_625016.js | took 1872ms
11:14:41     INFO - checking window state

Mike, can you take a look at this or point to someone who can?
Flags: needinfo?(mdeboer)
Whiteboard: [stockwell needswork]
There are 46 occurrence for this failure in the last 7 days. This is mainly happening on Linux 64 asan and windows 10 asan & debug.
Glancing over the test file, nothing really stands out as leaky and/ or blocking a window to close. Are there more tests like this that started leaking windows from two weeks ago onward?
Flags: needinfo?(mdeboer)
Update:
There have been 41 failures in the last week.

Failures per platform and build type: 
- linux64 / asan : 25
- windows10-64 / asan & debug : 10
- windows7-32 / debug: 4
- windows10-64-msvc / debug: 1
- windows7-32-msvc / debug: 1

Recent relevant log file
https://treeherder.mozilla.org/logviewer.html#?job_id=198167493&repo=autoland&lineNumber=1878

[task 2018-09-07T23:19:40.176Z] 23:19:40     INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
[task 2018-09-07T23:19:42.112Z] 23:19:42     INFO - TEST-INFO | started process screentopng
[task 2018-09-07T23:19:43.148Z] 23:19:43     INFO - TEST-INFO | screentopng: exit 0
[task 2018-09-07T23:19:43.149Z] 23:19:43     INFO - Buffered messages logged at 23:19:40
[task 2018-09-07T23:19:43.149Z] 23:19:43     INFO - Entering test bound setup
[task 2018-09-07T23:19:43.149Z] 23:19:43     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | starting with no closed windows - 
[task 2018-09-07T23:19:43.150Z] 23:19:43     INFO - Leaving test bound setup
[task 2018-09-07T23:19:43.150Z] 23:19:43     INFO - Entering test bound new_window
[task 2018-09-07T23:19:43.150Z] 23:19:43     INFO - Buffered messages logged at 23:19:41
[task 2018-09-07T23:19:43.150Z] 23:19:43     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save - 
[task 2018-09-07T23:19:43.150Z] 23:19:43     INFO - Buffered messages finished
[task 2018-09-07T23:19:43.152Z] 23:19:43     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
[task 2018-09-07T23:19:43.153Z] 23:19:43     INFO - Stack trace:
[task 2018-09-07T23:19:43.154Z] 23:19:43     INFO - chrome://mochikit/content/browser-test.js:test_is:1304
[task 2018-09-07T23:19:43.156Z] 23:19:43     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:38
[task 2018-09-07T23:19:43.157Z] 23:19:43     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1102
[task 2018-09-07T23:19:43.160Z] 23:19:43     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1093
[task 2018-09-07T23:19:43.160Z] 23:19:43     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2018-09-07T23:19:43.161Z] 23:19:43     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
[task 2018-09-07T23:19:43.163Z] 23:19:43     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk -
In the last 7 days, there are 38 failures associated with this bug.
They occur on linux64 (asan), windows10-64 (asan).
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=199592598&repo=autoland&lineNumber=1863
This bug has failed 31 times in the last 7 days. These occur on windows10-64, windows7-32 and linux on debug and asan build types.

Log:
INFO - TEST-OK | browser/components/sessionstore/test/browser_624727.js | took 313ms
[task 2018-09-25T06:25:35.189Z] 06:25:35     INFO - checking window state
[task 2018-09-25T06:25:35.267Z] 06:25:35     INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
[task 2018-09-25T06:25:36.800Z] 06:25:36     INFO - TEST-INFO | started process screentopng
[task 2018-09-25T06:25:37.475Z] 06:25:37     INFO - TEST-INFO | screentopng: exit 0
[task 2018-09-25T06:25:37.476Z] 06:25:37     INFO - Buffered messages logged at 06:25:35
[task 2018-09-25T06:25:37.477Z] 06:25:37     INFO - Entering test bound setup
[task 2018-09-25T06:25:37.477Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | starting with no closed windows - 
[task 2018-09-25T06:25:37.477Z] 06:25:37     INFO - Leaving test bound setup
[task 2018-09-25T06:25:37.478Z] 06:25:37     INFO - Entering test bound new_window
[task 2018-09-25T06:25:37.479Z] 06:25:37     INFO - Buffered messages logged at 06:25:36
[task 2018-09-25T06:25:37.479Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save - 
[task 2018-09-25T06:25:37.481Z] 06:25:37     INFO - Buffered messages finished
[task 2018-09-25T06:25:37.483Z] 06:25:37     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
[task 2018-09-25T06:25:37.485Z] 06:25:37     INFO - Stack trace:
[task 2018-09-25T06:25:37.486Z] 06:25:37     INFO - chrome://mochikit/content/browser-test.js:test_is:1304
[task 2018-09-25T06:25:37.487Z] 06:25:37     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:38
[task 2018-09-25T06:25:37.488Z] 06:25:37     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1102
[task 2018-09-25T06:25:37.489Z] 06:25:37     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1093
[task 2018-09-25T06:25:37.490Z] 06:25:37     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
[task 2018-09-25T06:25:37.494Z] 06:25:37     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
[task 2018-09-25T06:25:37.497Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk - 
[task 2018-09-25T06:25:37.500Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: 1 closed window according to API - 
[task 2018-09-25T06:25:37.502Z] 06:25:37     INFO - Leaving test bound new_window
[task 2018-09-25T06:25:37.504Z] 06:25:37     INFO - Entering test bound new_tab
[task 2018-09-25T06:25:37.505Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 window in data being written to disk - 
[task 2018-09-25T06:25:37.507Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window in data being written to disk - 
[task 2018-09-25T06:25:37.510Z] 06:25:37     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window according to API - 
[task 2018-09-25T06:25:37.512Z] 06:25:37     INFO - Leaving test bound new_tab
[task 2018-09-25T06:25:37.513Z] 06:25:37     INFO - Entering test bound done
[task 2018-09-25T06:25:37.515Z] 06:25:37     INFO - Leaving test bound done
[task 2018-09-25T06:25:37.517Z] 06:25:37     INFO - GECKO(1075) | MEMORY STAT | vsize 20974348MB | residentFast 1476MB
[task 2018-09-25T06:25:37.520Z] 06:25:37     INFO - TEST-OK | browser/components/sessionstore/test/browser_625016.js | took 1813ms

mikedeboer: Can you please take a look at this bug?
Flags: needinfo?(mdeboer)
There is no activity on this bug so I created a patch to disable this on linux64 asan.
Attachment #9013932 - Flags: review?(jmaher)
Comment on attachment 9013932 [details] [diff] [review]
Skipped test on linux64 asan

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

thanks!
Attachment #9013932 - Flags: review?(jmaher) → review+
Keywords: checkin-needed, leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by aciure@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f8492f0fea58
Disable browser_625016.js on linux64 asan for frequent failures. r=jmaher
Keywords: checkin-needed
Mike, there is also bug 1348583 that seems related. 

This one has 28 total failures in the last 7 days on  windows10-64, windows7-32, linux64 and windows10-64-ccov.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=209494382&repo=autoland&lineNumber=3284

19:12:10     INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
19:12:12     INFO - TEST-INFO | started process screenshot
19:12:12     INFO - TEST-INFO | screenshot: exit 0
19:12:12     INFO - Buffered messages logged at 19:12:10
19:12:12     INFO - Entering test bound setup
19:12:12     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | starting with no closed windows - 
19:12:12     INFO - Leaving test bound setup
19:12:12     INFO - Entering test bound new_window
19:12:12     INFO - Buffered messages logged at 19:12:12
19:12:12     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save - 
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/prerendered/static/activity-stream-initial-state.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://browser/content/contentSearchUI.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “chrome://browser/content/contentTheme.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react-dom.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/prop-types.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react-intl.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/redux.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/vendor/react-redux.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/prerendered/en-US/activity-stream-strings.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “resource://activity-stream/data/content/activity-stream.bundle.js”." {file: "about:newtab" line: 1}]
19:12:12     INFO - Buffered messages finished
19:12:12     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
19:12:12     INFO - Stack trace:
19:12:12     INFO - chrome://mochikit/content/browser-test.js:test_is:1307
19:12:12     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:38
19:12:12     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1097
19:12:12     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1088
19:12:12     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:986
19:12:12     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
19:12:12     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk - 
19:12:12     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: 1 closed window according to API - 
19:12:12     INFO - Leaving test bound new_window

Can you please take a look at this? 
Thank you.
Flags: needinfo?(mdeboer)
See Also: → 1348583, 1230992
Flags: needinfo?(mdeboer)
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
Mike are there any updates here?
Flags: needinfo?(mdeboer)
Flags: needinfo?(mdeboer)
This bug failed 36 times in the last 7 days. Occurs on windows7-32 and windows10-64 on debug and asan build type.

Recent log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=213728205&repo=mozilla-inbound&lineNumber=17936

mikedeboer: Can you please take a look at this bug?
In the last 7 days, there have been 42 failures.

For failure pattern please see comment 61

An example of a recent log file: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=218438184&repo=mozilla-inbound&lineNumber=2321

And the relevant part of the log:

23:22:03     INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save - 
23:22:03     INFO - Buffered messages finished
23:22:03     INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
23:22:03     INFO - Stack trace:
23:22:03     INFO - chrome://mochikit/content/browser-test.js:test_is:1316
23:22:03     INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:38
23:22:03     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
23:22:03     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
23:22:03     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
23:22:03     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:focusedOrLoaded/<:803


:mikedeboer As you are the triage owner of this component, could you please take a look at this?
Thank you!
Flags: needinfo?(mdeboer)

There are 33 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-08&endday=2019-07-15&tree=trunk&bug=1430977

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=256465905&repo=autoland&lineNumber=22292

03:15:27 INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
03:15:29 INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
03:15:29 INFO - Stack trace:
03:15:29 INFO - chrome://mochikit/content/browser-test.js:test_is:1591
03:15:29 INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:41
03:15:29 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1346
03:15:29 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1381
03:15:29 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1209
03:15:29 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
03:15:29 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk -
03:15:29 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: 1 closed window according to API -
03:15:29 INFO - Leaving test bound new_window
03:15:29 INFO - Entering test bound new_tab
03:15:29 INFO - GECKO(7528) | ++DOCSHELL 00000206C7859000 == 78 [pid = 8236] [id = {603a7193-e841-47a6-81b8-414ac1ff13ea}]
03:15:29 INFO - GECKO(7528) | ++DOMWINDOW == 226 (00000206D23C0A60) [pid = 8236] [serial = 521] [outer = 0000000000000000]
03:15:29 INFO - GECKO(7528) | ++DOMWINDOW == 227 (00000206E422A800) [pid = 8236] [serial = 522] [outer = 00000206D23C0A60]
03:15:29 INFO - GECKO(7528) | ++DOMWINDOW == 228 (00000206E422D400) [pid = 8236] [serial = 523] [outer = 00000206D23C0A60]
03:15:29 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 window in data being written to disk -
03:15:29 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window in data being written to disk -
03:15:29 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window according to API -
03:15:29 INFO - Leaving test bound new_tab
03:15:29 INFO - Entering test bound done
03:15:29 INFO - Leaving test bound done
03:15:29 INFO - GECKO(7528) | MEMORY STAT | vsize 2104726MB | vsizeMaxContiguous 65789291MB | residentFast 867MB | heapAllocated 476MB
03:15:29 INFO - TEST-OK | browser/components/sessionstore/test/browser_625016.js | took 1646ms
03:15:29 INFO - GECKO(7528) | ++DOCSHELL 000002441F045000 == 5 [pid = 1296] [id = {c641fa71-81aa-461b-a2d4-a76c92e47aec}]
03:15:29 INFO - GECKO(7528) | ++DOMWINDOW == 27 (0000024425A14020) [pid = 1296] [serial = 182] [outer = 0000000000000000]
03:15:29 INFO - GECKO(7528) | [Child 1296, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
03:15:29 INFO - GECKO(7528) | [Child 1296, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
03:15:29 INFO - GECKO(7528) | ++DOMWINDOW == 28 (0000024424DA3000) [pid = 1296] [serial = 183] [outer = 0000024425A14020]
03:15:29 INFO - checking window state
03:15:29 INFO - GECKO(7528) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object

Mike, could you assign this to someone?

Flags: needinfo?(mdeboer)

Hi Joel. Seems like this is continuously failing but not "enough" to reach the disable queue https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-06-27&endday=2019-07-27&tree=trunk&bug=1430977

The owner did not reply so far, can you please take a look and advise?

There are 18 total failures in the last 7 days on:

*debug: windows7-32, windows10-64-qr, windows10-64
*opt: windows10-aarch64, linux64-shippable, linux64
*asan: windows10-64

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=258573378&repo=mozilla-inbound&lineNumber=19754

[task 2019-07-26T22:57:22.188Z] 22:57:22 INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
[task 2019-07-26T22:57:22.189Z] 22:57:22 INFO - GECKO(3508) | ++DOCSHELL 207A1800 == 37 [pid = 3860] [id = {5f005ef4-2f58-4c51-9e6a-e9aff665ed7c}]
[task 2019-07-26T22:57:22.189Z] 22:57:22 INFO - GECKO(3508) | ++DOMWINDOW == 222 (20CF7EE0) [pid = 3860] [serial = 521] [outer = 00000000]
[task 2019-07-26T22:57:22.189Z] 22:57:22 INFO - GECKO(3508) | ++DOMWINDOW == 223 (21144400) [pid = 3860] [serial = 522] [outer = 20CF7EE0]

[task 2019-07-26T22:57:22.334Z] 22:57:22 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | starting with no closed windows -
[task 2019-07-26T22:57:22.335Z] 22:57:22 INFO - Leaving test bound setup
[task 2019-07-26T22:57:22.335Z] 22:57:22 INFO - Entering test bound new_window
[task 2019-07-26T22:57:22.335Z] 22:57:22 INFO - Buffered messages logged at 22:56:56
[task 2019-07-26T22:57:22.336Z] 22:57:22 INFO - Console message: SessionStore: [process-switch]: type (web) is compatible - ignoring
[task 2019-07-26T22:57:22.336Z] 22:57:22 INFO - Buffered messages logged at 22:56:57
[task 2019-07-26T22:57:22.337Z] 22:57:22 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save -
[task 2019-07-26T22:57:22.337Z] 22:57:22 INFO - Buffered messages finished
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - Stack trace:
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - chrome://mochikit/content/browser-test.js:test_is:1591
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:41
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1346
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1381
[task 2019-07-26T22:57:22.338Z] 22:57:22 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1209
[task 2019-07-26T22:57:22.339Z] 22:57:22 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
[task 2019-07-26T22:57:22.339Z] 22:57:22 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk -

Flags: needinfo?(jmaher)

this test is not hitting our max limits, nor is there anything else I see as a pattern. I am inclined to let this continue on and see if it increases in frequency.

Flags: needinfo?(jmaher)

There are 32 total failures in the last 7 days on:

*debug: windows7-32, windows10-64-qr, windows10-64
*opt: windows10-aarch64
*asan: windows10-64

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266783365&repo=mozilla-inbound&lineNumber=23758

[task 2019-09-15T23:28:10.741Z] 23:28:10 INFO - TEST-START | browser/components/sessionstore/test/browser_625016.js
[task 2019-09-15T23:28:10.776Z] 23:28:10 INFO - GECKO(5800) | ++DOCSHELL 18D3C000 == 21 [pid = 2036] [id = {7e89bb15-44ef-4476-9e4d-f62b6424f1cc}]
[task 2019-09-15T23:28:10.776Z] 23:28:10 INFO - GECKO(5800) | ++DOMWINDOW == 71 (16DB1160) [pid = 2036] [serial = 521] [outer = 00000000]
[task 2019-09-15T23:28:10.776Z] 23:28:10 INFO - GECKO(5800) | ++DOMWINDOW == 72 (18D41800) [pid = 2036] [serial = 522] [outer = 16DB1160]
[task 2019-09-15T23:28:10.791Z] 23:28:10 INFO - GECKO(5800) | [Parent 2036, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/dom/base/ThirdPartyUtil.cpp, line 415
[task 2019-09-15T23:28:10.886Z] 23:28:10 INFO - GECKO(5800) | ++DOCSHELL 18E08800 == 22 [pid = 2036] [id = {1c7c8a60-f48c-4ca5-9626-3bace8170456}]
[task 2019-09-15T23:28:10.886Z] 23:28:10 INFO - GECKO(5800) | ++DOMWINDOW == 73 (16DB13A0) [pid = 2036] [serial = 523] [outer = 00000000]
[task 2019-09-15T23:28:10.901Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0B357000 == 14 [pid = 4924] [id = {684972e0-8204-4200-8d5a-f1d1acca9b1c}] [url = about:blank]
[task 2019-09-15T23:28:10.901Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0B404C00 == 13 [pid = 4924] [id = {1b4de857-ee17-4a22-8824-ad1f612eb4c1}] [url = about:rights]
[task 2019-09-15T23:28:10.901Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 088B0C00 == 12 [pid = 4924] [id = {9e478d2d-44d7-44a7-8a5c-d9692a5305e7}] [url = about:blank]
[task 2019-09-15T23:28:10.901Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0A374C00 == 11 [pid = 4924] [id = {8becb674-6f85-40a7-bdfb-399b709ab9f4}] [url = about:blank]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0B40A000 == 10 [pid = 4924] [id = {0cb9fff1-c57b-4657-813d-025406c3a7e8}] [url = about:blank]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0A372C00 == 9 [pid = 4924] [id = {9b86fcf9-f0a0-4885-b7e0-7377d1f87d93}] [url = http://example.com/#3]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0A36B400 == 8 [pid = 4924] [id = {f8a632e9-6815-4dec-925a-1cb8f0b1ace0}] [url = http://example.org/]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOCSHELL 0B3EC800 == 7 [pid = 4924] [id = {7824b246-583c-4218-9dac-f115680bdd27}] [url = http://example.com/#3]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 36 (0B343820) [pid = 4924] [serial = 284] [outer = 00000000] [url = http://example.com/#3]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 35 (0B343700) [pid = 4924] [serial = 282] [outer = 00000000] [url = about:blank]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 34 (00974B80) [pid = 4924] [serial = 274] [outer = 00000000] [url = about:blank]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 33 (00974CA0) [pid = 4924] [serial = 276] [outer = 00000000] [url = about:blank]
[task 2019-09-15T23:28:10.902Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 32 (00974A60) [pid = 4924] [serial = 272] [outer = 00000000] [url = about:blank]
[task 2019-09-15T23:28:10.903Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 31 (0B3435E0) [pid = 4924] [serial = 280] [outer = 00000000] [url = about:blank]
[task 2019-09-15T23:28:10.903Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 30 (00974DC0) [pid = 4924] [serial = 278] [outer = 00000000] [url = about:blank]
[task 2019-09-15T23:28:10.903Z] 23:28:10 INFO - GECKO(5800) | --DOMWINDOW == 29 (00974940) [pid = 4924] [serial = 268] [outer = 00000000] [url = http://example.com/#3]
[task 2019-09-15T23:28:10.943Z] 23:28:10 INFO - GECKO(5800) | ++DOCSHELL 19469400 == 23 [pid = 2036] [id = {5bc9acf0-fd2f-41ce-8289-8da7f77f3b82}]
[task 2019-09-15T23:28:10.943Z] 23:28:10 INFO - GECKO(5800) | ++DOMWINDOW == 74 (16DB14C0) [pid = 2036] [serial = 524] [outer = 00000000]
[task 2019-09-15T23:28:11.042Z] 23:28:11 INFO - GECKO(5800) | ++DOCSHELL 08FAFC00 == 6 [pid = 2968] [id = {8bcb4da4-9633-4021-b890-ce54d15397e7}]
[task 2019-09-15T23:28:11.042Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 19 (016775E0) [pid = 2968] [serial = 185] [outer = 00000000]
[task 2019-09-15T23:28:11.042Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 20 (0A688000) [pid = 2968] [serial = 186] [outer = 016775E0]
[task 2019-09-15T23:28:11.102Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 75 (18E0A000) [pid = 2036] [serial = 525] [outer = 16DB13A0]
[task 2019-09-15T23:28:11.109Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 76 (18EE9400) [pid = 2036] [serial = 526] [outer = 16DB14C0]
[task 2019-09-15T23:28:11.249Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 21 (0C36C000) [pid = 2968] [serial = 187] [outer = 016775E0]
[task 2019-09-15T23:28:11.304Z] 23:28:11 INFO - GECKO(5800) | [Parent 2036, Main Thread] WARNING: Ignoring duplicate observer.: file z:/build/build/src/modules/libpref/Preferences.cpp, line 2696
[task 2019-09-15T23:28:11.345Z] 23:28:11 INFO - GECKO(5800) | ++DOCSHELL 09E64400 == 6 [pid = 5192] [id = {2e643361-5608-4bbf-96cf-d553987abc94}]
[task 2019-09-15T23:28:11.345Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 30 (00CC9820) [pid = 5192] [serial = 235] [outer = 00000000]
[task 2019-09-15T23:28:11.345Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 31 (0AD57400) [pid = 5192] [serial = 236] [outer = 00CC9820]
[task 2019-09-15T23:28:11.432Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 32 (0ADDB400) [pid = 5192] [serial = 237] [outer = 00CC9820]
[task 2019-09-15T23:28:11.487Z] 23:28:11 INFO - GECKO(5800) | ++DOCSHELL 08FAC400 == 10 [pid = 4964] [id = {ac455e36-edbd-4277-8534-742ff8e32e14}]
[task 2019-09-15T23:28:11.487Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 22 (015C4940) [pid = 4964] [serial = 141] [outer = 00000000]
[task 2019-09-15T23:28:11.487Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 23 (0A75EC00) [pid = 4964] [serial = 142] [outer = 015C4940]
[task 2019-09-15T23:28:11.522Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 24 (0B709C00) [pid = 4964] [serial = 143] [outer = 015C4940]
[task 2019-09-15T23:28:11.557Z] 23:28:11 INFO - GECKO(5800) | --DOMWINDOW == 75 (26AF63A0) [pid = 2036] [serial = 204] [outer = 00000000] [url = chrome://browser/content/browser.xhtml]
[task 2019-09-15T23:28:11.557Z] 23:28:11 INFO - GECKO(5800) | --DOMWINDOW == 74 (266A05E0) [pid = 2036] [serial = 198] [outer = 00000000] [url = chrome://browser/content/browser.xhtml]
[task 2019-09-15T23:28:11.872Z] 23:28:11 INFO - TEST-INFO | started process screenshot
[task 2019-09-15T23:28:11.931Z] 23:28:11 INFO - TEST-INFO | screenshot: exit 0
[task 2019-09-15T23:28:11.931Z] 23:28:11 INFO - Buffered messages logged at 23:28:10
[task 2019-09-15T23:28:11.931Z] 23:28:11 INFO - Entering test bound setup
[task 2019-09-15T23:28:11.931Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | starting with no closed windows -
[task 2019-09-15T23:28:11.931Z] 23:28:11 INFO - Leaving test bound setup
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - Entering test bound new_window
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - Buffered messages logged at 23:28:11
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - Console message: SessionStore: [process-switch]: type (web) is compatible - ignoring
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | no closed windows on first save -
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - Buffered messages finished
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - TEST-UNEXPECTED-FAIL | browser/components/sessionstore/test/browser_625016.js | observe1: 1 window in data written to disk - Got 2, expected 1
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - Stack trace:
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - chrome://mochikit/content/browser-test.js:test_is:1595
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_625016.js:new_window:41
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-09-15T23:28:11.932Z] 23:28:11 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: no closed windows in data written to disk -
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe1: 1 closed window according to API -
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - Leaving test bound new_window
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - Entering test bound new_tab
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - GECKO(5800) | ++DOCSHELL 18D4A400 == 24 [pid = 2036] [id = {b5aeeae2-2431-4e79-8650-592335104eff}]
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 75 (16DB15E0) [pid = 2036] [serial = 527] [outer = 00000000]
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 76 (18E03800) [pid = 2036] [serial = 528] [outer = 16DB15E0]
[task 2019-09-15T23:28:11.933Z] 23:28:11 INFO - GECKO(5800) | ++DOMWINDOW == 77 (18EED000) [pid = 2036] [serial = 529] [outer = 16DB15E0]
[task 2019-09-15T23:28:11.980Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 window in data being written to disk -
[task 2019-09-15T23:28:11.980Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window in data being written to disk -
[task 2019-09-15T23:28:11.980Z] 23:28:11 INFO - TEST-PASS | browser/components/sessionstore/test/browser_625016.js | observe2: 1 closed window according to API -
[task 2019-09-15T23:28:11.987Z] 23:28:11 INFO - Leaving test bound new_tab
[task 2019-09-15T23:28:11.987Z] 23:28:11 INFO - Entering test bound done
[task 2019-09-15T23:28:11.987Z] 23:28:11 INFO - Leaving test bound done
[task 2019-09-15T23:28:12.007Z] 23:28:12 INFO - GECKO(5800) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-09-15T23:28:12.007Z] 23:28:12 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-09-15T23:28:12.034Z] 23:28:12 INFO - GECKO(5800) | MEMORY STAT | vsize 1254MB | vsizeMaxContiguous 195MB | residentFast 533MB | heapAllocated 179MB
[task 2019-09-15T23:28:12.034Z] 23:28:12 INFO - TEST-OK | browser/components/sessionstore/test/browser_625016.js | took 1295ms
[task 2019-09-15T23:28:12.041Z] 23:28:12 INFO - GECKO(5800) | ++DOCSHELL 0A68B000 == 7 [pid = 2968] [id = {8c9f2c06-b2f7-4362-95ef-6640985d49f1}]
[task 2019-09-15T23:28:12.041Z] 23:28:12 INFO - GECKO(5800) | ++DOMWINDOW == 22 (01677A60) [pid = 2968] [serial = 188] [outer = 00000000]
[task 2019-09-15T23:28:12.041Z] 23:28:12 INFO - GECKO(5800) | ++DOMWINDOW == 23 (0B402400) [pid = 2968] [serial = 189] [outer = 01677A60]
[task 2019-09-15T23:28:12.060Z] 23:28:12 INFO - checking window state

There are 31 failures on this bug over the last 7 days. These happen on windows7-32, windows10-64-qr, windows10-64, linux64

Here is the most recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269310408&repo=mozilla-central&lineNumber=24325

This started to fail very frequently (~140 failures since yesterday) with the landing of bug 1573839.

Neil, Mike, can you drive one of these options?

  • Fix test failure
  • Backout bug 1573839
  • Disable test if not avoidable and create a bug to re-enable it
Flags: needinfo?(enndeakin)
Regressed by: 1573839
Whiteboard: [stockwell disabled][stockwell needswork:owner] → [stockwell needswork:owner]
Pushed by nbeleuzu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ef6ba5cf5d2d
Disable browser_625016.js on Win-debug. r=aryx
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]

This doesn't really have anything to do with bug 1573839. Almost none of the tests in that directory use BrowserTestUtils.synthesizeXXX More likely, the test is relying on some timing that happened to work before and now doesn't. Possibly the removal of the framescript by bug 1573839, assuming that bug was the cause.

Flags: needinfo?(enndeakin)
Has Regression Range: --- → yes
Severity: normal → S3
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: