Closed Bug 1718446 Opened 4 years ago Closed 1 year ago

Intermittent TEST-UNEXPECTED-FAIL | damp | webconsole/openwithcache.js: Test timed out

Categories

(DevTools :: Console, defect, P5)

defect

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=343974688&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ETrthOPjTHiItd7eFyp4JA/runs/0/artifacts/public/logs/live_backing.log


[task 2021-06-27T11:01:03.977Z] 11:01:03     INFO -  TEST-INFO | started process 1420 (C:\Users\task_1624760598\build\application\firefox\firefox -wait-for-browser -no-deelevate -profile C:\Users\task_1624760598\AppData\Local\Temp\tmpjnfivaxd\profile)
[task 2021-06-27T11:01:05.525Z] 11:01:05     INFO -  PID 1420 | [damp-api] Expose damp test path as a char preference
[task 2021-06-27T11:01:05.525Z] 11:01:05     INFO -  PID 1420 | [damp-api] Retrieve the main DevTools loader
[task 2021-06-27T11:01:05.529Z] 11:01:05     INFO -  PID 1420 | [damp-api] Retrieve the DAMP runner and start the test
[task 2021-06-27T11:01:05.529Z] 11:01:05     INFO -  PID 1420 | [DampLoad helper] Register DampLoad actors
[task 2021-06-27T11:01:07.035Z] 11:01:07     INFO -  PID 1420 | Garbage collect
[task 2021-06-27T11:01:07.208Z] 11:01:07     INFO -  PID 1420 | Loading test 'inspector/cold-open.js'
[task 2021-06-27T11:01:07.217Z] 11:01:07     INFO -  PID 1420 | Executing test 'inspector/cold-open.js'
[task 2021-06-27T11:01:07.229Z] 11:01:07     INFO -  PID 1420 | Wait for a pageshow event for browsing context 55
[task 2021-06-27T11:01:07.257Z] 11:01:07     INFO -  PID 1420 | Received pageshow event for 55
[task 2021-06-27T11:01:07.358Z] 11:01:07     INFO -  PID 1420 | Open toolbox on 'inspector'
[task 2021-06-27T11:01:07.359Z] 11:01:07     INFO -  PID 1420 | Open toolbox - Call showToolboxForTab
[task 2021-06-27T11:01:07.367Z] 11:01:07     INFO -  PID 1420 | Open toolbox - Wait for "toolbox-created"
[task 2021-06-27T11:01:07.388Z] 11:01:07     INFO -  PID 1420 | Open toolbox - Wait for showToolbox to resolve
[task 2021-06-27T11:01:07.791Z] 11:01:07     INFO -  PID 1420 | Wait for pending paints on 'cold.inspector.open'
[task 2021-06-27T11:01:07.792Z] 11:01:07     INFO -  PID 1420 | 'cold.inspector.open.settle.DAMP' took 0.047445325235912605ms.
[task 2021-06-27T11:01:07.792Z] 11:01:07     INFO -  PID 1420 | Garbage collect
[task 2021-06-27T11:01:08.008Z] 11:01:08     INFO -  PID 1420 | Garbage collect
[task 2021-06-27T11:01:08.209Z] 11:01:08     INFO -  PID 1420 | inspector/cold-open.js took 1002ms.
[task 2021-06-27T11:01:08.210Z] 11:01:08     INFO -  PID 1420 | Loading test 'debugger/cold-open.js'
[task 2021-06-27T11:01:08.210Z] 11:01:08     INFO -  PID 1420 | Executing test 'debugger/cold-open.js'
[task 2021-06-27T11:01:08.220Z] 11:01:08     INFO -  PID 1420 | Wait for a pageshow event for browsing context 61
[task 2021-06-27T11:01:08.241Z] 11:01:08     INFO -  PID 1420 | Received pageshow event for 61
[task 2021-06-27T11:01:08.343Z] 11:01:08     INFO -  PID 1420 | Open toolbox on 'jsdebugger'
<...>
[task 2021-06-27T11:10:59.561Z] 11:10:59     INFO -  PID 1420 | Open toolbox on 'webconsole'
[task 2021-06-27T11:10:59.561Z] 11:10:59     INFO -  PID 1420 | Open toolbox - Call showToolboxForTab
[task 2021-06-27T11:10:59.561Z] 11:10:59     INFO -  PID 1420 | Open toolbox - Wait for "toolbox-created"
[task 2021-06-27T11:10:59.565Z] 11:10:59     INFO -  PID 1420 | Open toolbox - Wait for showToolbox to resolve
[task 2021-06-27T11:11:02.512Z] 11:11:02     INFO -  PID 1420 | Close toolbox on 'console.objectexpanded'
[task 2021-06-27T11:11:02.578Z] 11:11:02     INFO -  PID 1420 | console.warn: "IGNORED REDUX ACTION:" "AUTOCOMPLETE_CLEAR"
[task 2021-06-27T11:11:02.589Z] 11:11:02     INFO -  PID 1420 | Garbage collect
[task 2021-06-27T11:11:05.088Z] 11:11:05     INFO -  PID 1420 | webconsole/objectexpand.js took 5662ms.
[task 2021-06-27T11:11:05.088Z] 11:11:05     INFO -  PID 1420 | Loading test 'webconsole/openwithcache.js'
[task 2021-06-27T11:11:05.088Z] 11:11:05     INFO -  PID 1420 | Executing test 'webconsole/openwithcache.js'
[task 2021-06-27T11:11:05.097Z] 11:11:05     INFO -  PID 1420 | Wait for a pageshow event for browsing context 609
[task 2021-06-27T11:11:05.102Z] 11:11:05     INFO -  PID 1420 | [Parent 8712, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2021-06-27T11:16:05.097Z] 11:16:05     INFO -  PID 1420 | TEST-UNEXPECTED-FAIL | damp | webconsole/openwithcache.js: Test timed out
[task 2021-06-27T11:16:05.101Z] 11:16:05     INFO -  Launcher process psutil.Process(pid=1420, name='firefox.exe', started='11:01:03') detected. Terminating parent process psutil.Process(pid=8712, name='firefox.exe', started='11:01:03') instead.
[task 2021-06-27T11:16:05.102Z] 11:16:05     INFO -  Terminating psutil.Process(pid=8712, name='firefox.exe', started='11:01:03')
[task 2021-06-27T11:16:05.102Z] 11:16:05     INFO -  PID 1420 | [DampLoad helper] Unregister DampLoad actors
[task 2021-06-27T11:16:05.112Z] 11:16:05     INFO -  PID 1420 | Exiting due to channel error.
[task 2021-06-27T11:16:05.440Z] 11:16:05     INFO -  mozcrash checking C:\Users\task_1624760598\AppData\Local\Temp\tmpjnfivaxd\profile\minidumps for minidumps...
[task 2021-06-27T11:16:05.441Z] 11:16:05     INFO -  TEST-UNEXPECTED-ERROR | damp | unexpected error
[task 2021-06-27T11:16:05.441Z] 11:16:05    ERROR -  Traceback (most recent call last):
[task 2021-06-27T11:16:05.441Z] 11:16:05     INFO -    File "C:\Users\task_1624760598\build\tests\talos\talos\run_tests.py", line 336, in run_tests
[task 2021-06-27T11:16:05.442Z] 11:16:05     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2021-06-27T11:16:05.442Z] 11:16:05     INFO -    File "C:\Users\task_1624760598\build\tests\talos\talos\ttest.py", line 65, in runTest
[task 2021-06-27T11:16:05.442Z] 11:16:05     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2021-06-27T11:16:05.443Z] 11:16:05     INFO -    File "C:\Users\task_1624760598\build\tests\talos\talos\ttest.py", line 215, in _runTest
[task 2021-06-27T11:16:05.443Z] 11:16:05     INFO -      debugger_args=browser_config["debugger_args"],
[task 2021-06-27T11:16:05.443Z] 11:16:05     INFO -    File "C:\Users\task_1624760598\build\tests\talos\talos\talos_process.py", line 191, in run_browser
[task 2021-06-27T11:16:05.444Z] 11:16:05     INFO -      raise TalosError("unexpected error")
[task 2021-06-27T11:16:05.444Z] 11:16:05     INFO -  talos.utils.TalosError: unexpected error
[task 2021-06-27T11:16:05.444Z] 11:16:05     INFO -  TEST-INFO took 4276523ms
[task 2021-06-27T11:16:05.445Z] 11:16:05     INFO -  SUITE-END | took 4276s
[task 2021-06-27T11:16:05.789Z] 11:16:05     INFO -  Exception ignored in: <bound method ProcessHandlerMixin.Process.__del__ of <mozprocess.processhandler.ProcessHandlerMixin.Process object at 0x000001EE7BE10EB8>>
[task 2021-06-27T11:16:05.789Z] 11:16:05    ERROR -  Traceback (most recent call last):
[task 2021-06-27T11:16:05.790Z] 11:16:05     INFO -    File "C:\Users\task_1624760598\build\venv\lib\site-packages\mozprocess\processhandler.py", line 190, in __del__
[task 2021-06-27T11:16:05.790Z] 11:16:05     INFO -      self._internal_poll(_deadstate=_maxint)
[task 2021-06-27T11:16:05.790Z] 11:16:05     INFO -    File "c:\mozilla-build\python3\lib\subprocess.py", line 1035, in _internal_poll
[task 2021-06-27T11:16:05.791Z] 11:16:05     INFO -      if _WaitForSingleObject(self._handle, 0) == _WAIT_OBJECT_0:
[task 2021-06-27T11:16:05.791Z] 11:16:05    ERROR -  TypeError: WaitForSingleObject() argument 1 must be int, not AutoHANDLE
[task 2021-06-27T11:16:05.813Z] 11:16:05    ERROR - Return code: 2
[task 2021-06-27T11:16:05.813Z] 11:16:05  WARNING - setting return code to 2
[task 2021-06-27T11:16:05.813Z] 11:16:05    ERROR - # TBPL FAILURE #
[task 2021-06-27T11:16:05.813Z] 11:16:05     INFO - Running post-action listener: _package_coverage_data
[task 2021-06-27T11:16:05.813Z] 11:16:05     INFO - Running post-action listener: _resource_record_post_action
[task 2021-06-27T11:16:05.814Z] 11:16:05     INFO - Running post-action listener: process_java_coverage_data
[task 2021-06-27T11:16:05.814Z] 11:16:05     INFO - [mozharness: 2021-06-27 11:16:05.814217Z] Finished run-tests step (success)
[task 2021-06-27T11:16:05.814Z] 11:16:05     INFO - Running post-run listener: _resource_record_post_run
[task 2021-06-27T11:16:06.098Z] 11:16:06     INFO - Total resource usage - Wall time: 4279s; CPU: 18%; Read bytes: 479500288; Write bytes: 3501336064; Read time: 7; Write time: 35
[task 2021-06-27T11:16:06.098Z] 11:16:06     INFO - TinderboxPrint: CPU usage<br/>18.5%
[task 2021-06-27T11:16:06.099Z] 11:16:06     INFO - TinderboxPrint: I/O read bytes / time<br/>479,500,288 / 7
[task 2021-06-27T11:16:06.099Z] 11:16:06     INFO - TinderboxPrint: I/O write bytes / time<br/>3,501,336,064 / 35
[task 2021-06-27T11:16:06.099Z] 11:16:06     INFO - TinderboxPrint: CPU idle<br/>27,919.3 (81.5%)
[task 2021-06-27T11:16:06.099Z] 11:16:06     INFO - TinderboxPrint: CPU system<br/>1,131.0 (3.3%)
[task 2021-06-27T11:16:06.099Z] 11:16:06     INFO - TinderboxPrint: CPU user<br/>5,183.4 (15.1%)
[task 2021-06-27T11:16:06.100Z] 11:16:06     INFO - install - Wall time: 2s; CPU: 14%; Read bytes: 0; Write bytes: 13905920; Read time: 0; Write time: 0
[task 2021-06-27T11:16:06.134Z] 11:16:06     INFO - run-tests - Wall time: 4277s; CPU: 18%; Read bytes: 479056896; Write bytes: 3487401472; Read time: 7; Write time: 35
[task 2021-06-27T11:16:07.267Z] 11:16:07  WARNING - returning nonzero exit status 2
[taskcluster 2021-06-27T11:16:07.335Z]    Exit Code: 2
[taskcluster 2021-06-27T11:16:07.335Z]    User Time: 0s
[taskcluster 2021-06-27T11:16:07.335Z]  Kernel Time: 15.625ms
[taskcluster 2021-06-27T11:16:07.335Z]    Wall Time: 1h13m0.4810336s
[taskcluster 2021-06-27T11:16:07.335Z]       Result: FAILED
[taskcluster 2021-06-27T11:16:07.335Z] === Task Finished ===
[taskcluster 2021-06-27T11:16:07.335Z] Task Duration: 1h13m0.4810336s
[taskcluster 2021-06-27T11:16:07.417Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2022-06-27T08:33:45.529Z
[taskcluster 2021-06-27T11:16:07.649Z] Uploading artifact public/test_info/damp_errorsummary.log from file build\blobber_upload_dir\damp_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2022-06-27T08:33:45.529Z
[taskcluster 2021-06-27T11:16:07.758Z] Uploading artifact public/test_info/damp_raw.log from file build\blobber_upload_dir\damp_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2022-06-27T08:33:45.529Z
[taskcluster 2021-06-27T11:16:08.057Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2022-06-27T08:33:45.529Z
[taskcluster 2021-06-27T11:16:08.346Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ETrthOPjTHiItd7eFyp4JA/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-06-27T08:33:45.529Z
[taskcluster:error] exit status 2
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Component: Talos → Console
Product: Testing → DevTools
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.