Closed Bug 1394715 Opened 7 years ago Closed 5 years ago

Intermittent browser/base/content/test/tabcrashed/browser_shown.js | Test timed out -

Categories

(Firefox :: Tabbed Browser, defect, P5)

Product:
Firefox
Component:
Tabbed Browser
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=126650775&repo=autoland

https://queue.taskcluster.net/v1/task/I011c0GdRoaTibxf2YQu_w/runs/0/artifacts/public/logs/live_backing.log

23:34:15     INFO - Entering test bound test_default
23:34:15     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<html><body>A%20regular,%20everyday,%20normal%20page." line: 0}]
23:34:15     INFO - Buffered messages logged at 23:31:16
23:34:15     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
23:34:15     INFO - Buffered messages logged at 23:31:50
23:34:15     INFO - Console message: 1503988310661	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 3b429bfa-eb94-7242-92e4-e679fd4ffec8, overwrite: false
23:34:15     INFO - Console message: 1503988310662	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: e52dae8f-06b7-9444-8cbc-1a4b12afe44e, overwrite: false
23:34:15     INFO - Console message: 1503988310662	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: a3f76003-4e6b-e248-8136-1f83ab700d27, overwrite: false
23:34:15     INFO - Console message: 1503988310663	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 8723e3ca-02d2-a344-8764-ad4b85a56162, overwrite: false
23:34:15     INFO - Console message: 1503988310664	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 4cae1818-38ff-e540-bbc1-b5347b828856, overwrite: false
23:34:15     INFO - Buffered messages logged at 23:32:45
23:34:15     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
23:34:15     INFO - Buffered messages finished
23:34:15     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/tabcrashed/browser_shown.js | Test timed out -
There are 31 failures in the past 7 days, the occurrences can be seen on Linux x64 and OS X 10.10
Affected build types: debug, pgo and opt

A recent log example:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=159892718&lineNumber=18086

And a relevant part of it:
09:29:48     INFO - TEST-PASS | browser/base/content/test/tabcrashed/browser_shown.js | Crash report had the right extra value for URL - 
09:29:48     INFO - Leaving test bound test_send_URL
09:29:48     INFO - Entering test bound test_send_all
09:29:48     INFO - Buffered messages logged at 09:27:07
09:29:48     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
09:29:48     INFO - Buffered messages logged at 09:27:25
09:29:48     INFO - Console message: 1517506045531	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: cd2a2582-51b7-754e-88a6-bf7acefc7307, overwrite: false
09:29:48     INFO - Console message: 1517506045531	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 66815baf-8683-184b-81bb-92776989b750, overwrite: false
09:29:48     INFO - Console message: 1517506045531	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: fb51b9a2-b61b-824f-a4a2-822827dc3674, overwrite: false
09:29:48     INFO - Console message: 1517506045532	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 75fb52a1-7dbb-e246-9a9f-d21f3b0868ce, overwrite: false
09:29:48     INFO - Console message: 1517506045533	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 4b722a99-d76c-2f49-a894-094261934a58, overwrite: false
09:29:48     INFO - Console message: 1517506045533	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 734ec50e-dc1a-3649-ba02-d05edc292f19, overwrite: false
09:29:48     INFO - Console message: 1517506045533	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 724d149b-1e75-714c-97a8-b657b4d6eca8, overwrite: false
09:29:48     INFO - Console message: 1517506045534	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: e8d5bf36-8273-9543-aadd-a88c2ed8b79a, overwrite: false
09:29:48     INFO - Console message: 1517506045535	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 806ac287-1180-e64e-9f0d-92fdb3628829, overwrite: false
09:29:48     INFO - Console message: 1517506045536	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: 4c1e72db-a754-7142-b57c-2e5aa6aabd9f, overwrite: false
09:29:48     INFO - Console message: 1517506045537	Toolkit.Telemetry	WARN	TelemetryStorage::_scanArchive - have seen this id before: c0cfbf8e-4194-5145-af44-f7547131209e, overwrite: false
09:29:48     INFO - Buffered messages logged at 09:28:17
09:29:48     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
09:29:48     INFO - Buffered messages finished
09:29:48     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/tabcrashed/browser_shown.js | Test timed out - 
09:29:48     INFO - GECKO(800) | MEMORY STAT | vsize 4469MB | residentFast 425MB | heapAllocated 71MB
09:29:48     INFO - TEST-OK | browser/base/content/test/tabcrashed/browser_shown.js | took 180041ms
09:29:48     INFO - Not taking screenshot here: see the one that was previously logged
09:29:48     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/tabcrashed/browser_shown.js | Found a tab after previous test timed out: data:text/html,<html><body>A%20regular,%20everyday,%20normal%20page. - 
09:29:48     INFO - GECKO(800) | [Child 816, Main Thread] WARNING: NS_ENSURE_TRUE(node) failed: file /builds/worker/workspace/build/src/layout/base/nsDocumentViewer.cpp, line 3713
09:29:48     INFO - GECKO(800) | ++DOCSHELL 0x10c72b000 == 1 [pid = 818] [id = {023e2e99-3f62-4644-b126-d0e40c311d61}]
09:29:48     INFO - GECKO(800) | ++DOMWINDOW == 1 (0x11207e660) [pid = 818] [serial = 4] [outer = 0x0]

:dao could you please take a look?
Flags: needinfo?(dao+bmo)
Whiteboard: [stockwell needswork]
Sounds like we might need an even longer timeout for this test. Bug 1325530 already doubled it but maybe that isn't always enough. Although I'm not why we're getting "Test timed out" rather than "This test exceeded the timeout threshold...", so maybe this is different after all.
Flags: needinfo?(dao+bmo) → needinfo?(gbrown)
See Also: → 1325530
Yeah, I think this is different and a bigger timeout will not help. All the logs I checked have no activity for at least a minute or so before the timeout, so I think the test is hung. Maybe :mconley can have a look?
Flags: needinfo?(gbrown) → needinfo?(mconley)
No failures since Feb 8.
Flags: needinfo?(mconley)
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=211617076&repo=mozilla-inbound&lineNumber=11510
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 6 years ago → 5 years ago
Resolution: --- → INCOMPLETE

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=255881761&repo=mozilla-central&lineNumber=2979

17:42:47 INFO - TEST-PASS | browser/base/content/test/tabcrashed/browser_shown.js | Crash report had the right extra value for URL -
17:42:47 INFO - Leaving test bound test_no_email
17:42:47 INFO - Entering test bound test_yes_email
17:42:47 INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<html><body>A%20regular,%20everyday,%20normal%20page." line: 0}]
17:42:47 INFO - Console message: [JavaScript Error: "remote browser crashed while on data:text/html,<html><body>A%20regular,%20everyday,%20normal%20page.
17:42:47 INFO - " {file: "chrome://mochikit/content/mochitest-e10s-utils.js" line: 10}]
17:42:47 INFO - e10s_init/<@chrome://mochikit/content/mochitest-e10s-utils.js:10:10
17:42:47 INFO - EventListener.handleEvente10s_init@chrome://mochikit/content/mochitest-e10s-utils.js:6:10
17:42:47 INFO - testInit@chrome://mochikit/content/browser-test.js:131:5
17:42:47 INFO - setTimeout handler@chrome://mochikit/content/browser-test.js:41:1
17:42:47 INFO - loadChromeScripts@jar:file:///C:/Users/testdroid/AppData/Local/Temp/tmp8nyh96.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:21:25
17:42:47 INFO - loadMochitest@jar:file:///C:/Users/testdroid/AppData/Local/Temp/tmp8nyh96.mozrunner/extensions/mochikit@mozilla.org.xpi!/api.js:143:3
17:42:47 INFO - @C:\tasks\task_1562861903\build\tests\mochitest\runtests.py:1794:5
17:42:47 INFO - @C:\tasks\task_1562861903\build\tests\mochitest\runtests.py:1795:8
17:42:47 INFO - evaluate.sandbox/promise<@chrome://marionette/content/evaluate.js:136:10
17:42:47 INFO - evaluate.sandbox@chrome://marionette/content/evaluate.js:112:17
17:42:47 INFO - GeckoDriver.prototype.execute_@chrome://marionette/content/driver.js:1072:28
17:42:47 INFO - async*GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:947:30
17:42:47 INFO - despatch@chrome://marionette/content/server.js:305:40
17:42:47 INFO - execute@chrome://marionette/content/server.js:275:16
17:42:47 INFO - onPacket/<@chrome://marionette/content/server.js:248:20
17:42:47 INFO - onPacket@chrome://marionette/content/server.js:249:9
17:42:47 INFO - _onJSONObjectReady/<@chrome://marionette/content/transport.js:503:20
17:42:47 INFO -
17:42:47 INFO - Buffered messages logged at 17:42:01
17:42:47 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
17:42:47 INFO - Buffered messages finished
17:42:47 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/tabcrashed/browser_shown.js | Test timed out -
17:42:47 INFO - this test left a pending crash report; deleted C:\Users\testdroid\AppData\Roaming\Mozilla\Firefox\Crash Reports\pending\5d91a622-e4e1-4303-a8c7-72dac6eba9b6.dmp
17:42:47 INFO - this test left a pending crash report; could not delete C:\Users\testdroid\AppData\Roaming\Mozilla\Firefox\Crash Reports\pending\5d91a622-e4e1-4303-a8c7-72dac6eba9b6.extra
17:42:47 INFO - GECKO(9984) | MEMORY STAT | vsize 6998MB | vsizeMaxContiguous 70562041MB | residentFast 192MB | heapAllocated 67MB
17:42:47 INFO - TEST-OK | browser/base/content/test/tabcrashed/browser_shown.js | took 90059ms
17:42:47 INFO - Not taking screenshot here: see the one that was previously logged
17:42:47 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/tabcrashed/browser_shown.js | Found a tab after previous test timed out: data:text/html,<html><body>A%20regular,%20everyday,%20normal%20page. -
17:42:47 INFO - checking window state
17:42:47 INFO - GECKO(9984) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
17:42:47 INFO - TEST-START | browser/base/content/test/tabcrashed/browser_shownRestartRequired.js
17:42:47 INFO - GECKO(9984) | Et tu, Brute?
17:42:47 INFO - GECKO(9984) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1D0076,name=PBrowser::Msg_ChildToParentMatrix) Channel error: cannot send/recv
17:42:47 INFO - GECKO(9984) | ###!!! [Parent][MessageChannel] Error: (msgtype=0x1D0076,name=PBrowser::Msg_ChildToParentMatrix) Channel error: cannot send/recv
17:42:47 INFO - GECKO(9984) | [Parent 1504, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 160
17:42:54 INFO - GECKO(9984) | Crash cleaned up
17:42:54 INFO - Not taking screenshot here: see the one that was previously logged
17:42:54 INFO - Buffered messages logged at 17:42:46

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.