Open Bug 1660854 Opened 4 years ago Updated 2 months ago

Intermittent TEST-UNEXPECTED-FAIL | damp | accessibility/simple.js: Test timed out

Categories

(DevTools :: Accessibility Tools, defect, P5)

Product:
DevTools
Component:
Accessibility Tools
Type:
defect

Tracking

(Not tracked)

Status:
REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

Attachments

(1 file)

Bug 1660854 - disable accessibility/simple.js on Win due to frequent failures r=jdescottes
48 bytes, text/x-phabricator-request
Details | Review

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=313823274&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NxUw-7GYQRyA-TvaghCFHQ/runs/0/artifacts/public/logs/live_backing.log

[task 2020-08-24T12:48:03.084Z] 12:48:03 INFO - PID 2360 | Loading test 'accessibility/simple.js'
[task 2020-08-24T12:48:03.084Z] 12:48:03 INFO - PID 2360 | Executing test 'accessibility/simple.js'
[task 2020-08-24T12:48:03.316Z] 12:48:03 INFO - PID 2360 | Open toolbox on 'accessibility'
[task 2020-08-24T12:48:03.316Z] 12:48:03 INFO - PID 2360 | Open toolbox - Wait for tab target
[task 2020-08-24T12:48:03.335Z] 12:48:03 INFO - PID 2360 | Open toolbox - Call showToolbox
[task 2020-08-24T12:48:03.335Z] 12:48:03 INFO - PID 2360 | Open toolbox - Wait for "toolbox-created"
[task 2020-08-24T12:48:03.335Z] 12:48:03 INFO - PID 2360 | Open toolbox - Wait for custom onLoad callback
[task 2020-08-24T12:52:33.895Z] 12:52:33 INFO - PID 2360 | 1598273553892 addons.xpi ERROR System addon update list error Error: Failed downloading XML, status: 0, reason: error
[task 2020-08-24T12:53:03.092Z] 12:53:03 INFO - PID 2360 | TEST-UNEXPECTED-FAIL | damp | accessibility/simple.js: Test timed out
[task 2020-08-24T12:53:03.111Z] 12:53:03 INFO - Launcher process psutil.Process(pid=2360L, name='firefox.exe', started='12:40:00') detected. Terminating parent process psutil.Process(pid=2520, name='firefox.exe', started='12:40:00') instead.
[task 2020-08-24T12:53:03.111Z] 12:53:03 INFO - Terminating psutil.Process(pid=2520, name='firefox.exe', started='12:40:00')
[task 2020-08-24T12:53:03.130Z] 12:53:03 INFO - PID 2360 | Exiting due to channel error.
[task 2020-08-24T12:53:03.354Z] 12:53:03 INFO - mozcrash checking c:\users\task_1598269882\appdata\local\temp\tmpqroer4\profile\minidumps for minidumps...
[task 2020-08-24T12:53:03.354Z] 12:53:03 INFO - TEST-UNEXPECTED-ERROR | damp | unexpected error

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

New occurrence:
https://treeherder.mozilla.org/logviewer?job_id=324327847&repo=autoland&lineNumber=1322

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There are 21 total failures in the last 7 days on

[task 2021-08-15T09:44:40.728Z] 09:44:40     INFO -  PID 6808 | Reload page on 'simple.netmonitor'
[task 2021-08-15T09:44:40.728Z] 09:44:40     INFO -  PID 6808 | Wait for a pageshow event for browsing context 104
[task 2021-08-15T09:44:40.750Z] 09:44:40     INFO -  PID 6808 | console.warn: "Already stopped listening to websocket events for this window."
[task 2021-08-15T09:44:40.751Z] 09:44:40     INFO -  PID 6808 | console.warn: "Already stopped listening to server sent events for this window."
[task 2021-08-15T09:44:40.757Z] 09:44:40     INFO -  PID 6808 | Received pageshow event for 104
[task 2021-08-15T09:44:40.757Z] 09:44:40     INFO -  PID 6808 | Wait for pending paints on 'simple.netmonitor.reload'
[task 2021-08-15T09:44:40.786Z] 09:44:40     INFO -  PID 6808 | 'simple.netmonitor.reload.settle.DAMP' took 29.08160496325945ms.
[task 2021-08-15T09:44:40.819Z] 09:44:40     INFO -  PID 6808 | Waiting for 0 requests
[task 2021-08-15T09:44:40.830Z] 09:44:40     INFO -  PID 6808 | Close toolbox on 'simple.netmonitor'
[task 2021-08-15T09:44:40.848Z] 09:44:40     INFO -  PID 6808 | Garbage collect
[task 2021-08-15T09:44:41.448Z] 09:44:41     INFO -  PID 6808 | netmonitor/simple.js took 1561ms.
[task 2021-08-15T09:44:41.449Z] 09:44:41     INFO -  PID 6808 | Loading test 'accessibility/simple.js'
[task 2021-08-15T09:44:41.449Z] 09:44:41     INFO -  PID 6808 | Executing test 'accessibility/simple.js'
[task 2021-08-15T09:44:41.456Z] 09:44:41     INFO -  PID 6808 | Wait for a pageshow event for browsing context 109
[task 2021-08-15T09:44:41.460Z] 09:44:41     INFO -  PID 6808 | [Parent 7064, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2021-08-15T09:44:41.498Z] 09:44:41     INFO -  PID 6808 | Received pageshow event for 109
[task 2021-08-15T09:44:41.599Z] 09:44:41     INFO -  PID 6808 | Open toolbox on 'accessibility'
[task 2021-08-15T09:44:41.599Z] 09:44:41     INFO -  PID 6808 | Open toolbox - Call showToolboxForTab
[task 2021-08-15T09:44:41.599Z] 09:44:41     INFO -  PID 6808 | Open toolbox - Wait for "toolbox-created"
[task 2021-08-15T09:44:41.604Z] 09:44:41     INFO -  PID 6808 | Open toolbox - Wait for showToolbox to resolve
[task 2021-08-15T09:49:41.453Z] 09:49:41     INFO -  PID 6808 | TEST-UNEXPECTED-FAIL | damp | accessibility/simple.js: Test timed out
[task 2021-08-15T09:49:41.457Z] 09:49:41     INFO -  Launcher process psutil.Process(pid=6808, name='firefox.exe', started='09:44:22') detected. Terminating parent process psutil.Process(pid=7064, name='firefox.exe', started='09:44:22') instead.
[task 2021-08-15T09:49:41.458Z] 09:49:41     INFO -  Terminating psutil.Process(pid=7064, name='firefox.exe', started='09:44:22')
[task 2021-08-15T09:49:41.468Z] 09:49:41     INFO -  PID 6808 | Exiting due to channel error.
[task 2021-08-15T09:49:41.468Z] 09:49:41     INFO -  PID 6808 | Exiting due to channel error.
[task 2021-08-15T09:49:41.469Z] 09:49:41     INFO -  PID 6808 | Exiting due to channel error.
[task 2021-08-15T09:49:41.760Z] 09:49:41     INFO -  mozcrash checking C:\Users\task_1628982575\AppData\Local\Temp\tmponnzvsat\profile\minidumps for minidumps...
[task 2021-08-15T09:49:41.760Z] 09:49:41     INFO -  TEST-UNEXPECTED-ERROR | damp | unexpected error
[task 2021-08-15T09:49:41.760Z] 09:49:41    ERROR -  Traceback (most recent call last):
[task 2021-08-15T09:49:41.761Z] 09:49:41     INFO -    File "C:\Users\task_1628982575\build\tests\talos\talos\run_tests.py", line 336, in run_tests
[task 2021-08-15T09:49:41.761Z] 09:49:41     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2021-08-15T09:49:41.761Z] 09:49:41     INFO -    File "C:\Users\task_1628982575\build\tests\talos\talos\ttest.py", line 65, in runTest
[task 2021-08-15T09:49:41.762Z] 09:49:41     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2021-08-15T09:49:41.762Z] 09:49:41     INFO -    File "C:\Users\task_1628982575\build\tests\talos\talos\ttest.py", line 215, in _runTest
[task 2021-08-15T09:49:41.762Z] 09:49:41     INFO -      debugger_args=browser_config["debugger_args"],
[task 2021-08-15T09:49:41.762Z] 09:49:41     INFO -    File "C:\Users\task_1628982575\build\tests\talos\talos\talos_process.py", line 191, in run_browser
[task 2021-08-15T09:49:41.762Z] 09:49:41     INFO -      raise TalosError("unexpected error")
[task 2021-08-15T09:49:41.762Z] 09:49:41     INFO -  talos.utils.TalosError: unexpected error
[task 2021-08-15T09:49:41.763Z] 09:49:41     INFO -  TEST-INFO took 2979117ms
[task 2021-08-15T09:49:41.763Z] 09:49:41     INFO -  SUITE-END | took 2979s
[task 2021-08-15T09:49:42.149Z] 09:49:42     INFO -  Exception ignored in: <bound method ProcessHandlerMixin.Process.__del__ of <mozprocess.processhandler.ProcessHandlerMixin.Process object at 0x0000022517CD4B38>>
[task 2021-08-15T09:49:42.150Z] 09:49:42    ERROR -  Traceback (most recent call last):
[task 2021-08-15T09:49:42.150Z] 09:49:42     INFO -    File "C:\Users\task_1628982575\build\venv\lib\site-packages\mozprocess\processhandler.py", line 192, in __del__
[task 2021-08-15T09:49:42.150Z] 09:49:42     INFO -      self._internal_poll(_deadstate=_maxint)
[task 2021-08-15T09:49:42.151Z] 09:49:42     INFO -    File "c:\mozilla-build\python3\lib\subprocess.py", line 1035, in _internal_poll
[task 2021-08-15T09:49:42.151Z] 09:49:42     INFO -      if _WaitForSingleObject(self._handle, 0) == _WAIT_OBJECT_0:
[task 2021-08-15T09:49:42.152Z] 09:49:42    ERROR -  TypeError: WaitForSingleObject() argument 1 must be int, not AutoHANDLE
[task 2021-08-15T09:49:42.173Z] 09:49:42    ERROR - Return code: 2
[task 2021-08-15T09:49:42.173Z] 09:49:42  WARNING - setting return code to 2

Jamie, can you please assign someone to take a look?

Flags: needinfo?(jteh)
Whiteboard: [stockwell needswork:owner]

In the past week we had 67 occurrences of this bug on:

[task 2021-09-05T04:05:00.784Z] 04:05:00 INFO - PID 7400 | TEST-UNEXPECTED-FAIL | damp | accessibility/simple.js: Test timed out
[task 2021-09-05T04:05:00.788Z] 04:05:00 INFO - Launcher process psutil.Process(pid=7400, name='firefox.exe', started='03:59:39') detected. Terminating parent process psutil.Process(pid=1032, name='firefox.exe', started='03:59:39') instead.
[task 2021-09-05T04:05:00.789Z] 04:05:00 INFO - Terminating psutil.Process(pid=1032, name='firefox.exe', started='03:59:39')
[task 2021-09-05T04:05:00.829Z] 04:05:00 INFO - PID 7400 | Exiting due to channel error.
[task 2021-09-05T04:05:00.952Z] 04:05:00 INFO - mozcrash checking C:\Users\task_1630788708\AppData\Local\Temp\tmpa8h08jib\profile\minidumps for minidumps...
[task 2021-09-05T04:05:00.953Z] 04:05:00 INFO - TEST-UNEXPECTED-ERROR | damp | unexpected error
[task 2021-09-05T04:05:00.953Z] 04:05:00 ERROR - Traceback (most recent call last):
[task 2021-09-05T04:05:00.954Z] 04:05:00 INFO - File "C:\Users\task_1630788708\build\tests\talos\talos\run_tests.py", line 336, in run_tests
[task 2021-09-05T04:05:00.954Z] 04:05:00 INFO - talos_results.add(mytest.runTest(browser_config, test))
[task 2021-09-05T04:05:00.954Z] 04:05:00 INFO - File "C:\Users\task_1630788708\build\tests\talos\talos\ttest.py", line 65, in runTest
[task 2021-09-05T04:05:00.954Z] 04:05:00 INFO - return self._runTest(browser_config, test_config, setup)
[task 2021-09-05T04:05:00.955Z] 04:05:00 INFO - File "C:\Users\task_1630788708\build\tests\talos\talos\ttest.py", line 215, in _runTest
[task 2021-09-05T04:05:00.955Z] 04:05:00 INFO - debugger_args=browser_config["debugger_args"],
[task 2021-09-05T04:05:00.956Z] 04:05:00 INFO - File "C:\Users\task_1630788708\build\tests\talos\talos\talos_process.py", line 191, in run_browser
[task 2021-09-05T04:05:00.956Z] 04:05:00 INFO - raise TalosError("unexpected error")
[task 2021-09-05T04:05:00.956Z] 04:05:00 INFO - talos.utils.TalosError: unexpected error
[task 2021-09-05T04:05:00.956Z] 04:05:00 INFO - TEST-INFO took 321665ms
[task 2021-09-05T04:05:00.957Z] 04:05:00 INFO - SUITE-END | took 321s

Assignee: nobody → apavel
Assignee: apavel → nobody
Assignee: nobody → apavel

It will be interesting to see if skipping this on Windows actually fixes anything.

The failure logs show:

[task 2021-09-07T07:52:54.276Z] 07:52:54     INFO -  PID 8952 | Loading test 'accessibility/simple.js'
[task 2021-09-07T07:52:54.276Z] 07:52:54     INFO -  PID 8952 | Executing test 'accessibility/simple.js'
[task 2021-09-07T07:52:54.284Z] 07:52:54     INFO -  PID 8952 | Wait for a pageshow event for browsing context 109
[task 2021-09-07T07:52:54.289Z] 07:52:54     INFO -  PID 8952 | [Parent 3584, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2021-09-07T07:57:54.283Z] 07:57:54     INFO -  PID 8952 | TEST-UNEXPECTED-FAIL | damp | accessibility/simple.js: Test timed out
[task 2021-09-07T07:57:54.283Z] 07:57:54     INFO -  Launcher process psutil.Process(pid=8952, name='firefox.exe', started='07:52:36') detected. Terminating parent process psutil.Process(pid=3584, name='firefox.exe', started='07:52:36') instead.
[task 2021-09-07T07:57:54.284Z] 07:57:54     INFO -  Terminating psutil.Process(pid=3584, name='firefox.exe', started='07:52:36')
[task 2021-09-07T07:57:54.293Z] 07:57:54     INFO -  PID 8952 | Exiting due to channel error.
[task 2021-09-07T07:57:54.294Z] 07:57:54     INFO -  PID 8952 | Exiting due to channel error.
[task 2021-09-07T07:57:54.566Z] 07:57:54     INFO -  mozcrash checking C:\Users\task_1630963970\AppData\Local\Temp\tmp9rnxp7u3\profile\minidumps for minidumps...

So we never get the pageshow event for our simple test page. It's the exact same page we used for all the other tests running right before this one https://searchfox.org/mozilla-central/source/testing/talos/talos/tests/devtools/addon/content/pages/simple.html
There might be a bug in our logic to wait for the page load, but I don't see why this would affect the accessibility simple test more than any other.

Attachment #9239531 - Attachment description: Bug 1660854 - disable accessibility/simple.js due to frequent failures r?#intermittent-reviewers → Bug 1660854 - disable accessibility/simple.js on Win due to frequent failures r=jdescottes
Assignee: apavel → nobody
Keywords: leave-open
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][stockwell disabled]
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1c89dc72db61
disable accessibility/simple.js on Win due to frequent failures r=perftest-reviewers,jdescottes,AlexandruIonescu DONTBUILD

For info :ochameau is currently working on Bug 1439509, which should significantly reduce the memory leaked by DevTools. This might have a positive impact on intermittents such as this one.

Edit: early try pushes look promising: https://treeherder.mozilla.org/jobs?repo=try&revision=df0a70c6b5b11800a30a312f76160698e4e5674c

See Also: → 1439509
Severity: normal → S3
Flags: needinfo?(jteh)
You need to log in before you can comment on or make changes to this bug.