Closed
Bug 1709891
Opened 4 years ago
Closed 2 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/tabs/browser_pinnedTabs_clickOpen.js | application timed out after 370 seconds with no output
Categories
(Firefox :: Tabbed Browser, defect, P5)
Firefox
Tabbed Browser
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=338951624&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FLM2cPBaSAKqg_TI5KSf7w/runs/1/artifacts/public/logs/live_backing.log
[task 2021-05-06T15:03:29.887Z] 15:03:29 INFO - TEST-START | browser/base/content/test/tabs/browser_pinnedTabs_clickOpen.js
[task 2021-05-06T15:09:41.177Z] 15:09:41 INFO - Buffered messages logged at 15:03:29
[task 2021-05-06T15:09:41.179Z] 15:09:41 INFO - Entering test bound test_pinned_content_click
[task 2021-05-06T15:09:41.180Z] 15:09:41 INFO - Buffered messages logged at 15:03:31
[task 2021-05-06T15:09:41.181Z] 15:09:41 INFO - TEST-PASS | browser/base/content/test/tabs/browser_pinnedTabs_clickOpen.js | clicked tab is in correct position -
[task 2021-05-06T15:09:41.182Z] 15:09:41 INFO - Buffered messages finished
[task 2021-05-06T15:09:41.183Z] 15:09:41 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/tabs/browser_pinnedTabs_clickOpen.js | application timed out after 370 seconds with no output
[task 2021-05-06T15:09:41.184Z] 15:09:41 ERROR - Force-terminating active process(es).
[task 2021-05-06T15:09:41.185Z] 15:09:41 INFO - Determining child pids from psutil...
[task 2021-05-06T15:09:41.186Z] 15:09:41 INFO - [1647, 1672, 1723, 1757, 1790, 1794, 1827, 1859, 1894, 1991, 2024, 2169, 2198, 2228, 2250, 2282, 2296, 2336, 2391]
[task 2021-05-06T15:09:41.187Z] 15:09:41 INFO - ==> process 1581 launched child process 1596
[task 2021-05-06T15:09:41.188Z] 15:09:41 INFO - ==> process 1581 launched child process 1647
[task 2021-05-06T15:09:41.190Z] 15:09:41 INFO - ==> process 1581 launched child process 1672
[task 2021-05-06T15:09:41.191Z] 15:09:41 INFO - ==> process 1581 launched child process 1723
[task 2021-05-06T15:09:41.192Z] 15:09:41 INFO - ==> process 1581 launched child process 1757
[task 2021-05-06T15:09:41.192Z] 15:09:41 INFO - ==> process 1581 launched child process 1794
[task 2021-05-06T15:09:41.193Z] 15:09:41 INFO - ==> process 1581 launched child process 1827
[task 2021-05-06T15:09:41.194Z] 15:09:41 INFO - ==> process 1581 launched child process 1859
[task 2021-05-06T15:09:41.194Z] 15:09:41 INFO - ==> process 1581 launched child process 1894
[task 2021-05-06T15:09:41.194Z] 15:09:41 INFO - ==> process 1581 launched child process 1991
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2024
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2169
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2198
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2228
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2250
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2282
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2296
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2336
[task 2021-05-06T15:09:41.195Z] 15:09:41 INFO - ==> process 1581 launched child process 2391
[task 2021-05-06T15:09:41.196Z] 15:09:41 INFO - Found child pids: {2336, 1794, 1827, 1859, 1894, 1991, 1672, 2024, 2250, 2282, 1647, 2228, 2198, 2391, 2296, 2169, 1723, 1596, 1757, 1790}
[task 2021-05-06T15:09:41.196Z] 15:09:41 INFO - Failed to get child procs
[task 2021-05-06T15:09:41.196Z] 15:09:41 INFO - Killing process: 2336
[task 2021-05-06T15:09:41.196Z] 15:09:41 INFO - TEST-INFO | started process screentopng
[task 2021-05-06T15:09:41.421Z] 15:09:41 INFO - TEST-INFO | screentopng: exit 0
[task 2021-05-06T15:09:41.422Z] 15:09:41 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:10:11.435Z] 15:10:11 INFO - failed to kill pid 2336 after 30s
[task 2021-05-06T15:10:11.436Z] 15:10:11 INFO - Killing process: 1794
[task 2021-05-06T15:10:11.436Z] 15:10:11 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:10:11.436Z] 15:10:11 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:10:41.476Z] 15:10:41 INFO - failed to kill pid 1794 after 30s
[task 2021-05-06T15:10:41.476Z] 15:10:41 INFO - Killing process: 1827
[task 2021-05-06T15:10:41.476Z] 15:10:41 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:10:41.476Z] 15:10:41 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:11:11.497Z] 15:11:11 INFO - failed to kill pid 1827 after 30s
[task 2021-05-06T15:11:11.497Z] 15:11:11 INFO - Killing process: 1859
[task 2021-05-06T15:11:11.498Z] 15:11:11 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:11:11.498Z] 15:11:11 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:11:41.524Z] 15:11:41 INFO - failed to kill pid 1859 after 30s
[task 2021-05-06T15:11:41.526Z] 15:11:41 INFO - Killing process: 1894
[task 2021-05-06T15:11:41.526Z] 15:11:41 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:11:41.526Z] 15:11:41 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:11.553Z] 15:12:11 INFO - failed to kill pid 1894 after 30s
[task 2021-05-06T15:12:11.553Z] 15:12:11 INFO - Killing process: 1991
[task 2021-05-06T15:12:11.554Z] 15:12:11 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:11.555Z] 15:12:11 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:41.579Z] 15:12:41 INFO - failed to kill pid 1991 after 30s
[task 2021-05-06T15:12:41.580Z] 15:12:41 INFO - Killing process: 1672
[task 2021-05-06T15:12:41.580Z] 15:12:41 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:41.580Z] 15:12:41 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.677Z] 15:12:53 INFO - psutil found pid 1672 dead
[task 2021-05-06T15:12:53.680Z] 15:12:53 INFO - Killing process: 2024
[task 2021-05-06T15:12:53.680Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.680Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.680Z] 15:12:53 INFO - Error: Failed to kill process 2024: psutil.NoSuchProcess no process found with pid 2024
[task 2021-05-06T15:12:53.680Z] 15:12:53 INFO - Killing process: 2250
[task 2021-05-06T15:12:53.680Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.684Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.688Z] 15:12:53 INFO - Error: Failed to kill process 2250: psutil.NoSuchProcess no process found with pid 2250
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Killing process: 2282
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Error: Failed to kill process 2282: psutil.NoSuchProcess no process found with pid 2282
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Killing process: 1647
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Error: Failed to kill process 1647: psutil.NoSuchProcess no process found with pid 1647
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Killing process: 2228
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Error: Failed to kill process 2228: psutil.NoSuchProcess no process found with pid 2228
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Killing process: 2198
[task 2021-05-06T15:12:53.689Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.690Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.692Z] 15:12:53 INFO - Error: Failed to kill process 2198: psutil.NoSuchProcess no process found with pid 2198
[task 2021-05-06T15:12:53.693Z] 15:12:53 INFO - Killing process: 2391
[task 2021-05-06T15:12:53.694Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.695Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.695Z] 15:12:53 INFO - Error: Failed to kill process 2391: psutil.NoSuchProcess no process found with pid 2391
[task 2021-05-06T15:12:53.696Z] 15:12:53 INFO - Killing process: 2296
[task 2021-05-06T15:12:53.696Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.697Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.697Z] 15:12:53 INFO - Error: Failed to kill process 2296: psutil.NoSuchProcess no process found with pid 2296
[task 2021-05-06T15:12:53.697Z] 15:12:53 INFO - Killing process: 2169
[task 2021-05-06T15:12:53.697Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.697Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.697Z] 15:12:53 INFO - Error: Failed to kill process 2169: psutil.NoSuchProcess no process found with pid 2169
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Killing process: 1723
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Error: Failed to kill process 1723: psutil.NoSuchProcess no process found with pid 1723
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Killing process: 1596
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.698Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Error: Failed to kill process 1596: psutil.NoSuchProcess no process found with pid 1596
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Killing process: 1757
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Error: Failed to kill process 1757: psutil.NoSuchProcess no process found with pid 1757
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Killing process: 1790
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:12:53.699Z] 15:12:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:13:23.700Z] 15:13:23 INFO - failed to kill pid 1790 after 30s
[task 2021-05-06T15:13:23.700Z] 15:13:23 INFO - Killing process: 1581
[task 2021-05-06T15:13:23.701Z] 15:13:23 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:13:23.701Z] 15:13:23 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-06T15:13:23.704Z] 15:13:23 INFO - psutil found pid 1581 dead
[task 2021-05-06T15:13:23.705Z] 15:13:23 INFO - psutil found pid 1581 dead
[task 2021-05-06T15:13:23.705Z] 15:13:23 INFO - TEST-INFO | Main app process: exit 0
[task 2021-05-06T15:13:23.705Z] 15:13:23 INFO - runtests.py | Application ran for: 0:21:19.107105
<...>
[task 2021-05-06T15:13:23.727Z] 15:13:23 INFO - zombiecheck | Checking for orphan process with PID: 2685
[task 2021-05-06T15:13:23.727Z] 15:13:23 INFO - Stopping web server
[task 2021-05-06T15:13:23.734Z] 15:13:23 INFO - Server shut down.
[task 2021-05-06T15:13:23.774Z] 15:13:23 INFO - Web server killed.
[task 2021-05-06T15:13:23.775Z] 15:13:23 INFO - Stopping web socket server
[task 2021-05-06T15:13:23.795Z] 15:13:23 INFO - Stopping ssltunnel
[task 2021-05-06T15:13:23.815Z] 15:13:23 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-05-06T15:13:23.816Z] 15:13:23 INFO - runtests.py | Running tests: end.
[task 2021-05-06T15:13:23.830Z] 15:13:23 INFO - Buffered messages finished
[task 2021-05-06T15:13:23.830Z] 15:13:23 INFO - TEST-INFO | checking window state
[task 2021-05-06T15:13:23.830Z] 15:13:23 INFO - Browser Chrome Test Summary
[task 2021-05-06T15:13:23.831Z] 15:13:23 INFO - Passed: 0
[task 2021-05-06T15:13:23.831Z] 15:13:23 INFO - Failed: 0
[task 2021-05-06T15:13:23.831Z] 15:13:23 INFO - Todo: 0
[task 2021-05-06T15:13:23.831Z] 15:13:23 INFO - Mode: e10s
[task 2021-05-06T15:13:23.832Z] 15:13:23 INFO - *** End BrowserChrome Test Results ***
[task 2021-05-06T15:13:23.832Z] 15:13:23 INFO - Buffered messages finished
[task 2021-05-06T15:13:23.833Z] 15:13:23 INFO - SUITE-END | took 1283s
[task 2021-05-06T15:13:23.873Z] 15:13:23 ERROR - Return code: 1
[task 2021-05-06T15:13:23.874Z] 15:13:23 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>65/0/0
[task 2021-05-06T15:13:23.874Z] 15:13:23 ERROR - # TBPL FAILURE #
[task 2021-05-06T15:13:23.874Z] 15:13:23 WARNING - setting return code to 2
[task 2021-05-06T15:13:23.874Z] 15:13:23 ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2021-05-06T15:13:23.875Z] 15:13:23 INFO - Running post-action listener: _package_coverage_data
[task 2021-05-06T15:13:23.875Z] 15:13:23 INFO - Running post-action listener: _resource_record_post_action
[task 2021-05-06T15:13:23.875Z] 15:13:23 INFO - Running post-action listener: process_java_coverage_data
[task 2021-05-06T15:13:23.875Z] 15:13:23 INFO - [mozharness: 2021-05-06 15:13:23.875251Z] Finished run-tests step (success)
[task 2021-05-06T15:13:23.875Z] 15:13:23 INFO - Running post-run listener: _resource_record_post_run
[task 2021-05-06T15:13:23.979Z] 15:13:23 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-browser-chrome.overall", "extraOptions": ["e10s", "taskcluster-m5d.xlarge"], "subtests": [{"name": "cpu_percent", "value": 38.11838012139607}, {"name": "io_write_bytes", "value": 2506985472}, {"name": "io.read_bytes", "value": 10887168}, {"name": "io_write_time", "value": 904084}, {"name": "io_read_time", "value": 36}]}, {"name": "mochitest.mochitest-browser-chrome.start-pulseaudio", "subtests": [{"name": "time", "value": 0.014786005020141602}]}, {"name": "mochitest.mochitest-browser-chrome.install", "subtests": [{"name": "time", "value": 36.45570468902588}, {"name": "cpu_percent", "value": 25.307142857142857}]}, {"name": "mochitest.mochitest-browser-chrome.stage-files", "subtests": [{"name": "time", "value": 0.0002474784851074219}]}, {"name": "mochitest.mochitest-browser-chrome.run-tests", "subtests": [{"name": "time", "value": 1283.7778766155243}, {"name": "cpu_percent", "value": 38.48643637782983}]}]}
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - Total resource usage - Wall time: 1320s; CPU: 38%; Read bytes: 10887168; Write bytes: 2506985472; Read time: 36; Write time: 904084
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: CPU usage<br/>38.5%
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: I/O read bytes / time<br/>10,887,168 / 36
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: I/O write bytes / time<br/>2,506,985,472 / 904,084
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: CPU idle<br/>3,247.2 (61.7%)
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: CPU system<br/>142.7 (2.7%)
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: CPU user<br/>1,863.1 (35.4%)
[task 2021-05-06T15:13:23.982Z] 15:13:23 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-05-06T15:13:23.983Z] 15:13:23 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-05-06T15:13:23.983Z] 15:13:23 INFO - install - Wall time: 36s; CPU: 25%; Read bytes: 0; Write bytes: 864419840; Read time: 0; Write time: 259136
[task 2021-05-06T15:13:23.984Z] 15:13:23 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-05-06T15:13:23.993Z] 15:13:23 INFO - run-tests - Wall time: 1284s; CPU: 38%; Read bytes: 10887168; Write bytes: 1363775488; Read time: 36; Write time: 496768
[task 2021-05-06T15:13:24.178Z] 15:13:24 WARNING - returning nonzero exit status 2
[task 2021-05-06T15:13:24.216Z] cleanup
[task 2021-05-06T15:13:24.216Z] + cleanup
[task 2021-05-06T15:13:24.216Z] + local rv=2
[task 2021-05-06T15:13:24.216Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-05-06T15:13:24.216Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-05-06T15:13:24.218Z] + '[' ']'
[task 2021-05-06T15:13:24.218Z] + true
[task 2021-05-06T15:13:24.218Z] + cleanup_xvfb
[task 2021-05-06T15:13:24.219Z] ++ pidof Xvfb
[task 2021-05-06T15:13:24.223Z] + local xvfb_pid=50
[task 2021-05-06T15:13:24.223Z] + local vnc=false
[task 2021-05-06T15:13:24.223Z] + local interactive=false
[task 2021-05-06T15:13:24.223Z] + '[' -n 50 ']'
[task 2021-05-06T15:13:24.223Z] + [[ false == false ]]
[task 2021-05-06T15:13:24.223Z] + [[ false == false ]]
[task 2021-05-06T15:13:24.223Z] + kill 50
[task 2021-05-06T15:13:24.223Z] + screen -XS xvfb quit
[task 2021-05-06T15:13:24.251Z] + exit 2
[taskcluster 2021-05-06 15:13:24.588Z] === Task Finished ===
[taskcluster 2021-05-06 15:13:25.945Z] Unsuccessful task run with exit code: 2 completed in 1421.237 seconds```
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•