Closed
Bug 1716501
Opened 4 years ago
Closed 4 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_webconsole_visibility_messages.js | application timed out after 370 seconds with no output
Categories
(DevTools :: Console, defect, P5)
DevTools
Console
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=342790508&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/L6TPlArsQoKr-qrFwPK6vg/runs/0/artifacts/public/logs/live_backing.log
[task 2021-06-15T05:48:22.597Z] 05:48:22 INFO - TEST-START | devtools/client/webconsole/test/browser/browser_webconsole_visibility_messages.js
[task 2021-06-15T05:48:43.065Z] 05:48:43 INFO - GECKO(2670) | console.log: "[DISPATCH] action type:" "UPDATE_GRIDS"
[task 2021-06-15T05:48:43.911Z] 05:48:43 INFO - GECKO(2670) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
[task 2021-06-15T05:48:46.233Z] 05:48:46 INFO - GECKO(2670) | console.log: "[DISPATCH] action type:" "UPDATE_GRIDS"
[task 2021-06-15T05:48:46.256Z] 05:48:46 INFO - GECKO(2670) | console.log: "[DISPATCH] action type:" "UPDATE_OFFSET_PARENT"
[task 2021-06-15T05:48:46.267Z] 05:48:46 INFO - GECKO(2670) | console.log: "[DISPATCH] action type:" "UPDATE_LAYOUT"
[task 2021-06-15T05:48:47.084Z] 05:48:47 INFO - GECKO(2670) | console.log: "[DISPATCH] action type:" "CLEAR_FLEXBOX"
[task 2021-06-15T05:57:22.305Z] 05:57:20 INFO - Buffered messages logged at 05:48:22
[task 2021-06-15T05:57:41.867Z] 05:57:39 INFO - Entering test bound
[task 2021-06-15T05:58:59.382Z] 05:58:52 INFO - Adding a new tab with URL: data:text/html;charset=utf-8,%0A%20%20%3C!DOCTYPE%20html%3E%0A%20%20%3Chtml%3E%0A%20%20%20%20%3Cbody%3E%0A%20%20%20%20%20%20%3Ch1%3ETest%20console%20visibility%20update%3C/h1%3E%0A%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20function%20log(str)%20%7B%0A%20%20%20%20%20%20%20%20%20%20console.log(str);%0A%20%20%20%20%20%20%20%20%7D%0A%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%3C/body%3E%0A%20%20%3C/html%3E%0A
[task 2021-06-15T06:00:24.649Z] 06:00:24 INFO - Buffered messages logged at 05:48:23
[task 2021-06-15T06:00:39.247Z] 06:00:37 INFO - Tab added and finished loading
[task 2021-06-15T06:02:02.961Z] 06:02:02 INFO - Opening the toolbox
[task 2021-06-15T06:02:12.656Z] 06:02:07 INFO - Buffered messages logged at 05:48:29
[task 2021-06-15T06:04:19.299Z] 06:04:15 INFO - Toolbox opened and focused
[task 2021-06-15T06:05:34.448Z] 06:05:32 INFO - Log one message in the console
[task 2021-06-15T06:07:15.659Z] 06:07:13 INFO - Buffered messages logged at 05:48:30
[task 2021-06-15T06:07:26.077Z] 06:07:25 INFO - select the inspector
[task 2021-06-15T06:07:27.037Z] 06:07:26 INFO - Buffered messages logged at 05:48:46
[task 2021-06-15T06:07:28.249Z] 06:07:27 INFO - Wait for console to be hidden
[task 2021-06-15T06:07:29.719Z] 06:07:29 INFO - Buffered messages logged at 05:48:47
[task 2021-06-15T06:07:30.582Z] 06:07:30 INFO - Waiting for all messages to be logged into the store
[task 2021-06-15T06:07:32.286Z] 06:07:31 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_visibility_messages.js | No messages from the inspector actually appear in the console -
[task 2021-06-15T06:07:34.680Z] 06:07:34 INFO - select back the console
[task 2021-06-15T06:07:34.697Z] 06:07:34 INFO - Buffered messages logged at 05:48:48
[task 2021-06-15T06:07:34.697Z] 06:07:34 INFO - And wait for all messages to be visible
[task 2021-06-15T06:07:37.360Z] 06:07:37 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_webconsole_visibility_messages.js | All the messages logged when the console was hidden were displayed. -
[task 2021-06-15T06:07:40.918Z] 06:07:40 INFO - Leaving test bound
[task 2021-06-15T06:07:42.888Z] 06:07:42 INFO - Entering test bound
[task 2021-06-15T06:07:44.446Z] 06:07:43 INFO - Adding a new tab with URL: data:text/html;charset=utf-8,%0A%20%20%3C!DOCTYPE%20html%3E%0A%20%20%3Chtml%3E%0A%20%20%20%20%3Cbody%3E%0A%20%20%20%20%20%20%3Ch1%3ETest%20console%20visibility%20update%3C/h1%3E%0A%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20function%20log(str)%20%7B%0A%20%20%20%20%20%20%20%20%20%20console.log(str);%0A%20%20%20%20%20%20%20%20%7D%0A%20%20%20%20%20%20%3C/script%3E%0A%20%20%20%20%3C/body%3E%0A%20%20%3C/html%3E%0A
[task 2021-06-15T06:07:45.161Z] 06:07:44 INFO - Buffered messages logged at 05:48:53
[task 2021-06-15T06:07:45.756Z] 06:07:45 INFO - Tab added and finished loading
[task 2021-06-15T06:07:46.369Z] 06:07:46 INFO - Opening the toolbox
[task 2021-06-15T06:07:47.030Z] 06:07:46 INFO - Buffered messages logged at 05:49:07
[task 2021-06-15T06:07:47.039Z] 06:07:47 INFO - Toolbox opened and focused
[task 2021-06-15T06:07:47.046Z] 06:07:47 INFO - Log one message in the console
[task 2021-06-15T06:07:47.061Z] 06:07:47 INFO - Buffered messages logged at 05:49:08
[task 2021-06-15T06:07:47.061Z] 06:07:47 INFO - select the inspector
[task 2021-06-15T06:07:47.061Z] 06:07:47 INFO - Buffered messages finished
[task 2021-06-15T06:07:47.062Z] 06:07:47 ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_webconsole_visibility_messages.js | application timed out after 370 seconds with no output
[task 2021-06-15T06:07:47.062Z] 06:07:47 ERROR - Force-terminating active process(es).
[task 2021-06-15T06:07:47.627Z] 06:07:47 INFO - Determining child pids from psutil...
[task 2021-06-15T06:07:47.670Z] 06:07:47 INFO - [2738, 2758, 2834, 2866, 2916, 2963]
[task 2021-06-15T06:07:48.532Z] 06:07:48 INFO - ==> process 2670 launched child process 2690
[task 2021-06-15T06:07:48.577Z] 06:07:48 INFO - ==> process 2670 launched child process 2738
[task 2021-06-15T06:07:48.591Z] 06:07:48 INFO - ==> process 2670 launched child process 2758
[task 2021-06-15T06:07:48.591Z] 06:07:48 INFO - ==> process 2670 launched child process 2834
[task 2021-06-15T06:07:48.592Z] 06:07:48 INFO - ==> process 2670 launched child process 2866
[task 2021-06-15T06:07:48.592Z] 06:07:48 INFO - ==> process 2670 launched child process 2916
[task 2021-06-15T06:07:48.592Z] 06:07:48 INFO - ==> process 2670 launched child process 2963
[task 2021-06-15T06:07:48.592Z] 06:07:48 INFO - Found child pids: {2690, 2916, 2758, 2738, 2834, 2866, 2963}
[task 2021-06-15T06:07:50.701Z] 06:07:49 INFO - Failed to get child procs
[task 2021-06-15T06:07:51.600Z] 06:07:50 INFO - Killing process: 2690
[task 2021-06-15T06:07:52.949Z] 06:07:52 INFO - TEST-INFO | started process screentopng
[task 2021-06-15T06:16:37.558Z] 06:16:37 INFO - TEST-INFO | screentopng: exit 0
[task 2021-06-15T06:16:37.560Z] 06:16:37 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:16:37.560Z] 06:16:37 INFO - Error: Failed to kill process 2690: psutil.NoSuchProcess no process found with pid 2690
[task 2021-06-15T06:16:37.560Z] 06:16:37 INFO - Killing process: 2916
[task 2021-06-15T06:16:37.560Z] 06:16:37 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:16:37.560Z] 06:16:37 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:17:07.540Z] 06:17:07 INFO - failed to kill pid 2916 after 30s
[task 2021-06-15T06:17:07.540Z] 06:17:07 INFO - Killing process: 2758
[task 2021-06-15T06:17:07.540Z] 06:17:07 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:17:07.540Z] 06:17:07 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:17:37.546Z] 06:17:37 INFO - failed to kill pid 2758 after 30s
[task 2021-06-15T06:17:37.546Z] 06:17:37 INFO - Killing process: 2738
[task 2021-06-15T06:17:37.546Z] 06:17:37 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:17:37.546Z] 06:17:37 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:18:07.563Z] 06:18:07 INFO - failed to kill pid 2738 after 30s
[task 2021-06-15T06:18:07.564Z] 06:18:07 INFO - Killing process: 2834
[task 2021-06-15T06:18:07.564Z] 06:18:07 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:18:07.564Z] 06:18:07 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:18:37.569Z] 06:18:37 INFO - failed to kill pid 2834 after 30s
[task 2021-06-15T06:18:37.569Z] 06:18:37 INFO - Killing process: 2866
[task 2021-06-15T06:18:37.569Z] 06:18:37 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:18:37.570Z] 06:18:37 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:19:07.575Z] 06:19:07 INFO - failed to kill pid 2866 after 30s
[task 2021-06-15T06:19:07.576Z] 06:19:07 INFO - Killing process: 2963
[task 2021-06-15T06:19:07.576Z] 06:19:07 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:19:07.576Z] 06:19:07 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:19:37.582Z] 06:19:37 INFO - failed to kill pid 2963 after 30s
[task 2021-06-15T06:19:37.582Z] 06:19:37 INFO - Killing process: 2670
[task 2021-06-15T06:19:37.583Z] 06:19:37 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-15T06:19:37.583Z] 06:19:37 INFO - Can't trigger Breakpad, just killing process
[task 2021-06-15T06:20:07.591Z] 06:20:07 INFO - psutil found pid 2670 dead
[task 2021-06-15T06:20:07.593Z] 06:20:07 INFO - failed to kill pid 3178 after 30s
[task 2021-06-15T06:20:07.593Z] 06:20:07 INFO - failed to kill pid 2866 after 30s
[task 2021-06-15T06:20:07.593Z] 06:20:07 INFO - failed to kill pid 2758 after 30s
[task 2021-06-15T06:20:07.593Z] 06:20:07 INFO - failed to kill pid 2963 after 30s
[task 2021-06-15T06:20:07.594Z] 06:20:07 INFO - failed to kill pid 2916 after 30s
[task 2021-06-15T06:20:07.594Z] 06:20:07 INFO - failed to kill pid 2738 after 30s
[task 2021-06-15T06:20:07.594Z] 06:20:07 INFO - failed to kill pid 2834 after 30s
[task 2021-06-15T06:20:07.594Z] 06:20:07 INFO - psutil found pid 2670 dead
[task 2021-06-15T06:20:07.594Z] 06:20:07 INFO - TEST-INFO | Main app process: exit 0
[task 2021-06-15T06:20:07.595Z] 06:20:07 INFO - runtests.py | Application ran for: 0:42:57.520863
[task 2021-06-15T06:20:07.596Z] 06:20:07 INFO - zombiecheck | Reading PID log: /tmp/tmpdoifjeyhpidlog
[task 2021-06-15T06:20:07.597Z] 06:20:07 INFO - ==> process 2670 launched child process 2690
[task 2021-06-15T06:20:07.597Z] 06:20:07 INFO - ==> process 2670 launched child process 2738
[task 2021-06-15T06:20:07.597Z] 06:20:07 INFO - ==> process 2670 launched child process 2758
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - ==> process 2670 launched child process 2834
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - ==> process 2670 launched child process 2866
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - ==> process 2670 launched child process 2916
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - ==> process 2670 launched child process 2963
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - ==> process 2670 launched child process 3178
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2690
[task 2021-06-15T06:20:07.598Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2916
[task 2021-06-15T06:20:07.599Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2758
[task 2021-06-15T06:20:07.599Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 3178
[task 2021-06-15T06:20:07.599Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2738
[task 2021-06-15T06:20:07.599Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2834
[task 2021-06-15T06:20:07.599Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2866
[task 2021-06-15T06:20:07.600Z] 06:20:07 INFO - zombiecheck | Checking for orphan process with PID: 2963
[task 2021-06-15T06:20:07.600Z] 06:20:07 INFO - Stopping web server
[task 2021-06-15T06:20:07.605Z] 06:20:07 INFO - Server shut down.
[task 2021-06-15T06:20:07.635Z] 06:20:07 INFO - Web server killed.
[task 2021-06-15T06:20:07.636Z] 06:20:07 INFO - Stopping web socket server
[task 2021-06-15T06:20:07.656Z] 06:20:07 INFO - Stopping ssltunnel
[task 2021-06-15T06:20:07.676Z] 06:20:07 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-06-15T06:20:07.677Z] 06:20:07 INFO - runtests.py | Running tests: end.
[task 2021-06-15T06:20:07.715Z] 06:20:07 INFO - Buffered messages finished
[task 2021-06-15T06:20:07.715Z] 06:20:07 INFO - TEST-INFO | checking window state
[task 2021-06-15T06:20:07.715Z] 06:20:07 INFO - Browser Chrome Test Summary
[task 2021-06-15T06:20:07.715Z] 06:20:07 INFO - Passed: 6015
[task 2021-06-15T06:20:07.716Z] 06:20:07 INFO - Failed: 0
[task 2021-06-15T06:20:07.716Z] 06:20:07 INFO - Todo: 0
[task 2021-06-15T06:20:07.716Z] 06:20:07 INFO - Mode: e10s
[task 2021-06-15T06:20:07.716Z] 06:20:07 INFO - *** End BrowserChrome Test Results ***
[task 2021-06-15T06:20:07.717Z] 06:20:07 INFO - Buffered messages finished
[task 2021-06-15T06:20:07.717Z] 06:20:07 INFO - SUITE-END | took 2788s
[task 2021-06-15T06:20:07.778Z] 06:20:07 INFO - Return code: 0
[task 2021-06-15T06:20:07.780Z] 06:20:07 INFO - TinderboxPrint: mochitest-mochitest-devtools-chrome<br/>356/0/0
[task 2021-06-15T06:20:07.780Z] 06:20:07 ERROR - # TBPL FAILURE #
[task 2021-06-15T06:20:07.780Z] 06:20:07 WARNING - setting return code to 2
[task 2021-06-15T06:20:07.780Z] 06:20:07 ERROR - The mochitest suite: mochitest-devtools-chrome ran with return status: FAILURE
[task 2021-06-15T06:20:07.781Z] 06:20:07 INFO - Running post-action listener: _package_coverage_data
[task 2021-06-15T06:20:07.781Z] 06:20:07 INFO - Running post-action listener: _resource_record_post_action
[task 2021-06-15T06:20:07.781Z] 06:20:07 INFO - Running post-action listener: process_java_coverage_data
[task 2021-06-15T06:20:07.781Z] 06:20:07 INFO - [mozharness: 2021-06-15 06:20:07.781139Z] Finished run-tests step (success)
[task 2021-06-15T06:20:07.781Z] 06:20:07 INFO - Running post-run listener: _resource_record_post_run
[task 2021-06-15T06:20:07.945Z] 06:20:07 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-devtools-chrome.overall", "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "subtests": [{"name": "cpu_percent", "value": 28.215147503782156}, {"name": "io_write_bytes", "value": 3884199936}, {"name": "io.read_bytes", "value": 609369858048}, {"name": "io_write_time", "value": 476728}, {"name": "io_read_time", "value": 77891384}]}, {"name": "mochitest.mochitest-devtools-chrome.start-pulseaudio", "subtests": [{"name": "time", "value": 0.018673419952392578}]}, {"name": "mochitest.mochitest-devtools-chrome.install", "subtests": [{"name": "time", "value": 51.74980688095093}, {"name": "cpu_percent", "value": 25.155500000000004}]}, {"name": "mochitest.mochitest-devtools-chrome.stage-files", "subtests": [{"name": "time", "value": 0.0003218650817871094}]}, {"name": "mochitest.mochitest-devtools-chrome.run-tests", "subtests": [{"name": "time", "value": 2789.512736082077}, {"name": "cpu_percent", "value": 28.33903543307087}]}]}
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - Total resource usage - Wall time: 2840s; CPU: 28%; Read bytes: 609369858048; Write bytes: 3884199936; Read time: 77891384; Write time: 476728
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - TinderboxPrint: CPU usage<br/>28.3%
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - TinderboxPrint: I/O read bytes / time<br/>609,369,858,048 / 77,891,384
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - TinderboxPrint: I/O write bytes / time<br/>3,884,199,936 / 476,728
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - TinderboxPrint: CPU idle<br/>3,573.4 (31.7%)
[task 2021-06-15T06:20:07.947Z] 06:20:07 INFO - TinderboxPrint: CPU iowait<br/>5,832.3 (51.7%)
[task 2021-06-15T06:20:07.948Z] 06:20:07 INFO - TinderboxPrint: CPU system<br/>465.2 (4.1%)
[task 2021-06-15T06:20:07.948Z] 06:20:07 INFO - TinderboxPrint: CPU user<br/>1,413.9 (12.5%)
[task 2021-06-15T06:20:07.948Z] 06:20:07 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-06-15T06:20:07.948Z] 06:20:07 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-06-15T06:20:07.949Z] 06:20:07 INFO - install - Wall time: 52s; CPU: 25%; Read bytes: 7077888; Write bytes: 1792122880; Read time: 172; Write time: 217724
[task 2021-06-15T06:20:07.949Z] 06:20:07 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-06-15T06:20:07.956Z] 06:20:07 INFO - run-tests - Wall time: 2790s; CPU: 28%; Read bytes: 609362755584; Write bytes: 1980321792; Read time: 77891212; Write time: 253644
[task 2021-06-15T06:20:08.127Z] 06:20:08 WARNING - returning nonzero exit status 2
[task 2021-06-15T06:20:08.164Z] cleanup
[task 2021-06-15T06:20:08.164Z] + cleanup
[task 2021-06-15T06:20:08.164Z] + local rv=2
[task 2021-06-15T06:20:08.164Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-06-15T06:20:08.164Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-06-15T06:20:08.174Z] + '[' ']'
[task 2021-06-15T06:20:08.174Z] + true
[task 2021-06-15T06:20:08.174Z] + cleanup_xvfb
[task 2021-06-15T06:20:08.174Z] ++ pidof Xvfb
[task 2021-06-15T06:20:08.181Z] + local xvfb_pid=50
[task 2021-06-15T06:20:08.181Z] + local vnc=false
[task 2021-06-15T06:20:08.181Z] + local interactive=false
[task 2021-06-15T06:20:08.181Z] + '[' -n 50 ']'
[task 2021-06-15T06:20:08.181Z] + [[ false == false ]]
[task 2021-06-15T06:20:08.181Z] + [[ false == false ]]
[task 2021-06-15T06:20:08.181Z] + kill 50
[task 2021-06-15T06:20:08.181Z] + screen -XS xvfb quit
[task 2021-06-15T06:20:08.205Z] + exit 2
[taskcluster 2021-06-15 06:20:09.017Z] === Task Finished ===
[taskcluster 2021-06-15 06:20:10.940Z] Unsuccessful task run with exit code: 2 completed in 2935.107 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
•