Closed
Bug 1691972
Opened 4 years ago
Closed 4 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js | application timed out after 370 seconds with no output
Categories
(Toolkit :: Add-ons Manager, defect, P5)
Toolkit
Add-ons Manager
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=329476798&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HMAitGgLSNS_sLXqT6WB9Q/runs/1/artifacts/public/logs/live_backing.log
[task 2021-02-10T11:07:21.656Z] 11:07:21 INFO - TEST-START | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js
[task 2021-02-10T11:07:24.808Z] 11:07:24 INFO - GECKO(1561) | Manager window unload handler
[task 2021-02-10T11:07:24.864Z] 11:07:24 INFO - GECKO(1561) | JavaScript error: resource://gre/actors/BrowserElementParent.jsm, line 24: TypeError: can't access property "ownerGlobal", browser is null
[task 2021-02-10T11:07:28.667Z] 11:07:28 INFO - GECKO(1561) | Manager window unload handler
[task 2021-02-10T11:07:28.805Z] 11:07:28 INFO - GECKO(1561) | JavaScript error: resource://gre/actors/BrowserElementParent.jsm, line 24: TypeError: can't access property "ownerGlobal", browser is null
[task 2021-02-10T11:07:31.937Z] 11:07:31 INFO - GECKO(1561) | Manager window unload handler
[task 2021-02-10T11:07:32.080Z] 11:07:32 INFO - GECKO(1561) | JavaScript error: resource://gre/actors/BrowserElementParent.jsm, line 24: TypeError: can't access property "ownerGlobal", browser is null
[task 2021-02-10T11:07:45.692Z] 11:07:45 INFO - GECKO(1561) | Manager window unload handler
[task 2021-02-10T11:07:45.946Z] 11:07:45 INFO - GECKO(1561) | JavaScript error: resource://gre/actors/BrowserElementParent.jsm, line 24: TypeError: can't access property "ownerGlobal", browser is null
[task 2021-02-10T11:07:55.257Z] 11:07:55 INFO - GECKO(1561) | Manager window unload handler
[task 2021-02-10T11:08:03.246Z] 11:08:03 INFO - GECKO(1561) | JavaScript error: resource://gre/actors/BrowserElementParent.jsm, line 24: TypeError: can't access property "ownerGlobal", browser is null
[task 2021-02-10T11:14:21.305Z] 11:14:20 INFO - Buffered messages logged at 11:07:21
[task 2021-02-10T11:14:24.215Z] 11:14:23 INFO - Entering test bound setup
[task 2021-02-10T11:14:26.675Z] 11:14:26 INFO - Leaving test bound setup
[task 2021-02-10T11:14:30.343Z] 11:14:29 INFO - Entering test bound testNotRecommended
[task 2021-02-10T11:14:35.070Z] 11:14:34 INFO - Extension loaded
[task 2021-02-10T11:14:38.441Z] 11:14:37 INFO - Console message: 1612955241808 addons.xpi-utils DEBUG Make addon app-temporary:not-recommended@mochi.test visible
[task 2021-02-10T11:14:40.570Z] 11:14:39 INFO - Console message: 1612955241809 addons.xpi DEBUG XPIStates adding add-on not-recommended@mochi.test in {}: /tmp/generated-extension.xpi
[task 2021-02-10T11:14:46.596Z] 11:14:45 INFO - Console message: 1612955241815 addons.xpi DEBUG Updating XPIState for {"id":"not-recommended@mochi.test","syncGUID":"{4c0f5600-78db-46e8-9956-abe5686edbe3}","version":"1.0","type":"extension","loader":null,"updateURL":null,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1612955241807,"applyBackgroundUpdates":1,"path":"/tmp/generated-extension.xpi","skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":0,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":[],"origins":[]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///tmp/generated-extension.xpi!/","location":"app-temporary"}
[task 2021-02-10T11:14:48.824Z] 11:14:48 INFO - Console message: 1612955241818 addons.xpi DEBUG Loading bootstrap scope from jar:file:///tmp/generated-extension.xpi!/
[task 2021-02-10T11:14:51.379Z] 11:14:50 INFO - Console message: 1612955241819 addons.xpi DEBUG Calling bootstrap method install on not-recommended@mochi.test version 1.0
[task 2021-02-10T11:14:57.821Z] 11:14:56 INFO - Console message: 1612955241820 addons.xpi DEBUG Calling bootstrap method startup on not-recommended@mochi.test version 1.0
[task 2021-02-10T11:15:00.413Z] 11:14:59 INFO - Console message: 1612955241875 addons.xpi DEBUG Install of temporary addon in /tmp/generated-extension.xpi completed.
[task 2021-02-10T11:15:02.625Z] 11:15:00 INFO - Loading manager window in tab
[task 2021-02-10T11:15:07.753Z] 11:15:06 INFO - Buffered messages logged at 11:07:24
[task 2021-02-10T11:15:10.601Z] 11:15:09 INFO - TEST-PASS | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js | Should have an add-ons manager window -
[task 2021-02-10T11:15:16.882Z] 11:15:16 INFO - TEST-PASS | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js | Should be displaying the correct UI -
[task 2021-02-10T11:15:21.088Z] 11:15:20 INFO - window has focus, waiting for manager load
[task 2021-02-10T11:15:23.060Z] 11:15:22 INFO - Waiting for initialization
[task 2021-02-10T11:15:26.722Z] 11:15:25 INFO - Manager waiting for view load
[task 2021-02-10T11:15:30.811Z] 11:15:30 INFO - TEST-PASS | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js | badge recommended is hidden -
<...>
[task 2021-02-10T11:22:55.387Z] 11:22:55 INFO - TEST-PASS | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js | links to sumo correctly http://support.allizom.org/support-dummy/add-on-badges?utm_source=firefox-browser&utm_medium=firefox-browser&utm_content=promoted-addon-badge -
[task 2021-02-10T11:22:56.021Z] 11:22:55 INFO - Verify the verified badge links to the support page
[task 2021-02-10T11:22:56.781Z] 11:22:56 INFO - Buffered messages finished
[task 2021-02-10T11:22:57.250Z] 11:22:56 ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/extensions/test/browser/browser_html_recommendations.js | application timed out after 370 seconds with no output
[task 2021-02-10T11:22:58.132Z] 11:22:56 ERROR - Force-terminating active process(es).
[task 2021-02-10T11:22:58.788Z] 11:22:56 INFO - Determining child pids from psutil...
[task 2021-02-10T11:22:59.562Z] 11:22:56 INFO - [1626, 1710, 1742, 1777, 1836, 1814, 1848, 1871, 1651]
[task 2021-02-10T11:22:59.923Z] 11:22:56 INFO - ==> process 1561 launched child process 1576
[task 2021-02-10T11:23:00.987Z] 11:22:57 INFO - ==> process 1561 launched child process 1626
[task 2021-02-10T11:23:02.587Z] 11:22:58 INFO - ==> process 1561 launched child process 1651
[task 2021-02-10T11:23:04.204Z] 11:22:59 INFO - ==> process 1561 launched child process 1710
[task 2021-02-10T11:23:05.505Z] 11:22:59 INFO - ==> process 1561 launched child process 1742
[task 2021-02-10T11:23:07.401Z] 11:23:00 INFO - ==> process 1561 launched child process 1777
[task 2021-02-10T11:23:08.259Z] 11:23:03 INFO - ==> process 1561 launched child process 1814
[task 2021-02-10T11:23:09.594Z] 11:23:03 INFO - ==> process 1561 launched child process 1848
[task 2021-02-10T11:23:10.814Z] 11:23:04 INFO - ==> process 1561 launched child process 1871
[task 2021-02-10T11:23:11.976Z] 11:23:05 INFO - Found child pids: set([1576, 1836, 1742, 1871, 1777, 1651, 1710, 1814, 1848, 1626])
[task 2021-02-10T11:23:13.729Z] 11:23:06 INFO - Failed to get child procs
[task 2021-02-10T11:23:15.029Z] 11:23:07 INFO - Killing process: 1576
[task 2021-02-10T11:23:16.542Z] 11:23:11 INFO - TEST-INFO | started process screentopng
[task 2021-02-10T11:39:51.430Z] 11:39:51 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', u'toolkit/mozapps/extensions/test/browser/browser.ini', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', u'--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/R8T8t-9-SLOelbzYbcHvIQ/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-browser-chrome_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_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']
[task 2021-02-10T11:39:51.444Z] 11:39:51 ERROR - timed out after 1000 seconds of no output
[task 2021-02-10T11:39:51.444Z] 11:39:51 ERROR - Return code: -15
[task 2021-02-10T11:39:51.444Z] 11:39:51 ERROR - No suite end message was emitted by this harness.
[task 2021-02-10T11:39:51.444Z] 11:39:51 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>211/0/0
[task 2021-02-10T11:39:51.444Z] 11:39:51 ERROR - # TBPL FAILURE #
[task 2021-02-10T11:39:51.444Z] 11:39:51 WARNING - setting return code to 2
[task 2021-02-10T11:39:51.444Z] 11:39:51 ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2021-02-10T11:39:51.444Z] 11:39:51 INFO - Running post-action listener: _package_coverage_data
[task 2021-02-10T11:39:51.444Z] 11:39:51 INFO - Running post-action listener: _resource_record_post_action
[task 2021-02-10T11:39:51.444Z] 11:39:51 INFO - Running post-action listener: process_java_coverage_data
[task 2021-02-10T11:39:51.444Z] 11:39:51 INFO - [mozharness: 2021-02-10 11:39:51.389165Z] Finished run-tests step (success)
[task 2021-02-10T11:39:51.444Z] 11:39:51 INFO - Running post-run listener: _resource_record_post_run
[task 2021-02-10T11:39:51.908Z] 11:39:51 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-02-10T11:39:51.910Z] 11:39:51 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 13.94717765042979}, {"name": "io_write_bytes", "value": 2176708608}, {"name": "io.read_bytes", "value": 653056708608}, {"name": "io_write_time", "value": 285348}, {"name": "io_read_time", "value": 60523076}], "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.017827987670898438}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 32.03609108924866}, {"name": "cpu_percent", "value": 25.201612903225808}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.00017786026000976562}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 2612.1003789901733}, {"name": "cpu_percent", "value": 13.73890186915887}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2021-02-10T11:39:51.910Z] 11:39:51 INFO - Total resource usage - Wall time: 2644s; CPU: 14.0%; Read bytes: 653056708608; Write bytes: 2176708608; Read time: 60523076; Write time: 285348
[task 2021-02-10T11:39:51.910Z] 11:39:51 INFO - TinderboxPrint: CPU usage<br/>13.7%
[task 2021-02-10T11:39:51.910Z] 11:39:51 INFO - TinderboxPrint: I/O read bytes / time<br/>653,056,708,608 / 60,523,076
[task 2021-02-10T11:39:51.911Z] 11:39:51 INFO - TinderboxPrint: I/O write bytes / time<br/>2,176,708,608 / 285,348
[task 2021-02-10T11:39:51.911Z] 11:39:51 INFO - TinderboxPrint: CPU idle<br/>2,124.9 (20.3%)
[task 2021-02-10T11:39:51.911Z] 11:39:51 INFO - TinderboxPrint: CPU iowait<br/>7,266.4 (69.3%)
[task 2021-02-10T11:39:51.911Z] 11:39:51 INFO - TinderboxPrint: CPU system<br/>309.6 (3.0%)
[task 2021-02-10T11:39:51.911Z] 11:39:51 INFO - TinderboxPrint: CPU user<br/>784.4 (7.5%)
[task 2021-02-10T11:39:51.911Z] 11:39:51 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-02-10T11:39:51.912Z] 11:39:51 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-02-10T11:39:51.913Z] 11:39:51 INFO - install - Wall time: 32s; CPU: 25.0%; Read bytes: 8192; Write bytes: 1296629760; Read time: 0; Write time: 105628
[task 2021-02-10T11:39:51.913Z] 11:39:51 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-02-10T11:39:51.925Z] 11:39:51 INFO - run-tests - Wall time: 2612s; CPU: 14.0%; Read bytes: 653056364544; Write bytes: 610570240; Read time: 60521592; Write time: 140044
[task 2021-02-10T11:39:52.259Z] 11:39:52 WARNING - returning nonzero exit status 2
[task 2021-02-10T11:39:52.347Z] cleanup
[task 2021-02-10T11:39:52.347Z] + cleanup
[task 2021-02-10T11:39:52.347Z] + local rv=2
[task 2021-02-10T11:39:52.348Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-02-10T11:39:52.348Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-02-10T11:39:52.426Z] + '[' ']'
[task 2021-02-10T11:39:52.426Z] + true
[task 2021-02-10T11:39:52.426Z] + cleanup_xvfb
[task 2021-02-10T11:39:52.427Z] ++ pidof Xvfb
[task 2021-02-10T11:39:52.441Z] + local xvfb_pid=50
[task 2021-02-10T11:39:52.441Z] + local vnc=false
[task 2021-02-10T11:39:52.441Z] + local interactive=false
[task 2021-02-10T11:39:52.441Z] + '[' -n 50 ']'
[task 2021-02-10T11:39:52.441Z] + [[ false == false ]]
[task 2021-02-10T11:39:52.441Z] + [[ false == false ]]
[task 2021-02-10T11:39:52.441Z] + kill 50
[task 2021-02-10T11:39:52.441Z] + screen -XS xvfb quit
[task 2021-02-10T11:39:52.694Z] + exit 2
[taskcluster 2021-02-10 11:39:54.110Z] === Task Finished ===
[taskcluster 2021-02-10 11:39:57.634Z] Unsuccessful task run with exit code: 2 completed in 2943.562 seconds```
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•