Closed Bug 1416929 Opened 7 years ago Closed 6 years ago

Intermittent mochitest linux64-jsdcov Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--disable-e10s',

Categories

(Testing :: Mochitest, defect, P2)

Product:
Testing
Component:
Mochitest
Type:
defect

Tracking

(firefox61 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla61
Tracking Flags:
Tracking Status
firefox61 --- fixed

People

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

References

Details

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

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

https://treeherder.mozilla.org/logviewer.html#?job_id=144379689&repo=mozilla-central

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

[task 2017-11-13T20:04:01.095Z] 20:04:01     INFO - TEST-START | dom/html/test/test_bug566046.html
[task 2017-11-13T20:20:41.127Z] 20:20:41     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--disable-e10s', '--total-chunks', '10', '--this-chunk', '3', '--jscov-dir-prefix=/builds/worker/workspace/build/blobber_upload_dir', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/EkFxsgjlT4-0gA1p7kJQtQ/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/plain-chunked-coverage_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/plain-chunked-coverage_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--chunk-by-dir=4', '--timeout=1200']
[task 2017-11-13T20:20:41.132Z] 20:20:41    ERROR - timed out after 1000 seconds of no output
There had been 34 failures in the last week.
The failures occur on 	linux64-jsdcov / opt
This Blocks:	1433861

Here is a recent log file and a snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=165070721&lineNumber=2909

[task 2018-03-01T01:07:06.852Z] 01:07:06     INFO - GECKO(1329) | JavaScript error: , line 0: Error: Permission denied for <http://example.com> to create wrapper for object of class UnnamedClass
[task 2018-03-01T01:07:06.861Z] 01:07:06     INFO - GECKO(1329) | JavaScript error: , line 0: Error: Permission denied for <http://example.com> to create wrapper for object of class UnnamedClass
[task 2018-03-01T01:23:46.867Z] 01:23:46     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--disable-e10s', '--total-chunks', '8', '--this-chunk', '2', '--jscov-dir-prefix=/builds/worker/workspace/build/blobber_upload_dir', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/DFa2e44-SBKaWkXnBNFFsA/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/mochitest-devtools-chrome-coverage_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-devtools-chrome-coverage_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--subsuite=devtools', '--chunk-by-runtime', '--timeout=1200']
[task 2018-03-01T01:23:46.872Z] 01:23:46    ERROR - timed out after 1000 seconds of no output
[task 2018-03-01T01:23:46.873Z] 01:23:46    ERROR - Return code: -15
Flags: needinfo?(overholt)
Blake, do you know why nsScriptSecurityManager::CanCreateWrapper is throwing this error (looks like https://searchfox.org/mozilla-central/source/caps/nsScriptSecurityManager.cpp#1270) for https://searchfox.org/mozilla-central/source/dom/html/test/test_bug566046.html? Lots of the same "Permission denied for <http://example.com> to create wrapper ..." errors in the log referenced in comment 17: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=165070721&lineNumber=2909.
Flags: needinfo?(overholt) → needinfo?(mrbkap)
Priority: -- → P2
Something about jsdcov seems to be confusing XPconnect, I'm investigating that now. This is hitting many different tests, many of them have some sort of XPConnect wrapping error in the logs (not all of them do, but enough that it seems like a worthy line of research).

This doesn't appear to be related to test_bug566046.html directly.
Some additional thoughts: this is very hard to track down. It isn't very clear what's cause and what's effect in the logs. Do we have documentation on JS code coverage anywhere? It would be interesting to understand how it's implemented (and if it could possibly lead to garbage collection happening where previously it would be impossible).

One final thing that would be nice would be the callstack when the job is killed (to ensure that we're not busy-waiting on something or doing some insanely expensive operation). Is that possible?
Flags: needinfo?(mrbkap)
There are not only tests under DOM which experience this problems with jsdcov but lots of others too. So best is to move this bug to Testing / Mochitest for further inspection, and to cover all those different cases.
Component: DOM: Core & HTML → Mochitest
Product: Core → Testing
Summary: Intermittent dom/html/test/test_bug566046.html Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--disable-e10s', → Intermittent mochitest linux64-jsdcov Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--disable-e10s',
:sparky- could you add more chunks or extend the timeout of this?
Flags: needinfo?(gmierz2)
I'll try to increase the chunks and see if it works. Looking at the last OF post, the reasons for the failure are quite various and I don't think any of them are genuinely running out of time. Here's one, for instance, that cannot be fixed by increasing timeouts/chunks:

[task 2018-03-28T11:00:07.615Z] 11:00:07     INFO - GECKO(4548) | *** Blocklist::notify: Requesting http://127.0.0.1:8888/extensions-dummy/blocklistURL
[task 2018-03-28T11:00:07.631Z] 11:00:07     INFO - GECKO(4548) | *** Blocklist::onXMLLoad: there was an error during load, got status: 404
[task 2018-03-28T11:16:47.646Z] 11:16:47     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', '--disable-e10s', '--total-chunks', '7', '--this-chunk', '1', '--jscov-dir-prefix=/builds/worker/workspace/build/blobber_upload_dir', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/AXhu7Ld6Q4KF4aCPOb35jQ/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/browser-chrome-coverage_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/browser-chrome-coverage_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime', '--timeout=1200']
[task 2018-03-28T11:16:47.663Z] 11:16:47    ERROR - timed out after 1000 seconds of no output
[task 2018-03-28T11:16:47.664Z] 11:16:47    ERROR - Return code: -15
[task 2018-03-28T11:16:47.664Z] 11:16:47    ERROR - No suite end message was emitted by this harness.
[task 2018-03-28T11:16:47.664Z] 11:16:47     INFO - TinderboxPrint: mochitest-browser-chrome-coverage<br/>772/0/3
[task 2018-03-28T11:16:47.665Z] 11:16:47    ERROR - # TBPL FAILURE #
[task 2018-03-28T11:16:47.665Z] 11:16:47  WARNING - setting return code to 2
[task 2018-03-28T11:16:47.665Z] 11:16:47    ERROR - The mochitest suite: browser-chrome-coverage ran with return status: FAILURE


I also see these tests failing:
[1]: https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/sidebar/browser_sidebar_switcher.js?q=browser_sidebar_switcher.js&redirect_type=direct

[2]: https://dxr.mozilla.org/mozilla-central/source/browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser_policy_disable_developer_tools.js?q=browser_policy_disable_developer_tools.js&redirect_type=direct

[3]: https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/contextMenu/browser_contextmenu_linkopen.js?q=browser_contextmenu_linkopen.js&redirect_type=direct


It seems like most of them may be having trouble opening new tabs on jsdcov. 
For [2], here is the error: 

[task 2018-03-26T21:42:38.991Z] 21:42:38     INFO - TEST-PASS | browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser_policy_disable_developer_tools.js | devtools dedicated disabled pref can not be updated - 
[task 2018-03-26T21:42:38.992Z] 21:42:38     INFO - Wait for about:devtools to open the net error page
[task 2018-03-26T21:42:38.992Z] 21:42:38     INFO - Buffered messages finished
[task 2018-03-26T21:42:38.994Z] 21:42:38     INFO - TEST-UNEXPECTED-FAIL | browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser_policy_disable_developer_tools.js | DevTools about: page should display the net error page - false == true - 
[task 2018-03-26T21:42:38.994Z] 21:42:38     INFO - Stack trace:
[task 2018-03-26T21:42:38.995Z] 21:42:38     INFO - resource://testing-common/content-task.js line 50 > eval:null:4
[task 2018-03-26T21:42:38.995Z] 21:42:38     INFO - Wait for about:devtools-toolbox to open the net error page
[task 2018-03-26T21:42:38.996Z] 21:42:38     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-03-26T21:42:38.996Z] 21:42:38     INFO - TEST-UNEXPECTED-FAIL | browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser_policy_disable_developer_tools.js | DevTools about: page should display the net error page - false == true - 
[task 2018-03-26T21:42:38.996Z] 21:42:38     INFO - Stack trace:
[task 2018-03-26T21:42:38.997Z] 21:42:38     INFO - resource://testing-common/content-task.js line 50 > eval:null:4
[task 2018-03-26T21:42:38.997Z] 21:42:38     INFO - Wait for about:debugging to open the net error page
[task 2018-03-26T21:42:38.999Z] 21:42:38     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-03-26T21:42:39.000Z] 21:42:39     INFO - TEST-UNEXPECTED-FAIL | browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser_policy_disable_developer_tools.js | DevTools about: page should display the net error page - false == true - 
[task 2018-03-26T21:42:39.000Z] 21:42:39     INFO - Stack trace:
[task 2018-03-26T21:42:39.001Z] 21:42:39     INFO - resource://testing-common/content-task.js line 50 > eval:null:4
[task 2018-03-26T21:42:39.077Z] 21:42:39     INFO - Check that devtools menu items are hidden
[task 2018-03-26T21:42:39.078Z] 21:42:39     INFO - TEST-PASS | browser/components/enterprisepolicies/tests/browser/disable_developer_tools/browser_policy_disable_developer_tools.js | The Web Developer item of the tools menu is hidden -
Depends on: 1451849
Greg, since bug 1451849 has been fixed on April 6th I can no longer see such test failures! That's great. Maybe you have a look yourself later again, and close out this bug.
This bug is fixed now with bug 1451849 (as :whimboo stated).
Status: NEW → RESOLVED
Closed: 6 years ago
Flags: needinfo?(gmierz2)
Resolution: --- → FIXED
Assignee: nobody → gmierz2
status-firefox61: --- → fixed
Target Milestone: --- → mozilla61
You need to log in before you can comment on or make changes to this bug.