1574417 - Perma [tier2][fission] | TEST-UNEXPECTED-FAIL | damp | netmonitor/complicated.js: Test timed out

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=261937082&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/RAs6gUdlRpCLM6eNYGDDBw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-08-16T05:00:53.183Z] 05:00:53 INFO - PID 1236 | Close toolbox on 'complicated.jsdebugger'
[task 2019-08-16T05:00:53.257Z] 05:00:53 INFO - PID 1236 | Garbage collect
[task 2019-08-16T05:00:54.466Z] 05:00:54 INFO - PID 1236 | debugger/complicated.js took 6250ms.
[task 2019-08-16T05:00:54.466Z] 05:00:54 INFO - PID 1236 | Loading test 'styleeditor/complicated.js'
[task 2019-08-16T05:00:54.466Z] 05:00:54 INFO - PID 1236 | Executing test 'styleeditor/complicated.js'
[task 2019-08-16T05:00:54.466Z] 05:00:54 INFO - PID 1236 | [Parent 3588, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1565922974/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-08-16T05:00:54.484Z] 05:00:54 INFO - PID 1236 | [Child 2844, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1565922974/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-08-16T05:00:55.720Z] 05:00:55 INFO - PID 1236 | 'complicated.styleeditor.open.settle.DAMP' took 0.12014939484652132ms.
[task 2019-08-16T05:00:55.720Z] 05:00:55 INFO - PID 1236 | Garbage collect
[task 2019-08-16T05:00:56.974Z] 05:00:56 INFO - PID 1236 | Reload page on 'complicated.styleeditor'
[task 2019-08-16T05:00:58.474Z] 05:00:58 INFO - PID 1236 | Wait for pending paints on 'complicated.styleeditor'
[task 2019-08-16T05:00:58.474Z] 05:00:58 INFO - PID 1236 | 'complicated.styleeditor.reload.settle.DAMP' took 0.20514143840409815ms.
[task 2019-08-16T05:00:58.474Z] 05:00:58 INFO - PID 1236 | Close toolbox on 'complicated.styleeditor'
[task 2019-08-16T05:00:58.514Z] 05:00:58 INFO - PID 1236 | Garbage collect
[task 2019-08-16T05:00:59.792Z] 05:00:59 INFO - PID 1236 | styleeditor/complicated.js took 5325ms.
[task 2019-08-16T05:00:59.792Z] 05:00:59 INFO - PID 1236 | Loading test 'netmonitor/complicated.js'
[task 2019-08-16T05:00:59.792Z] 05:00:59 INFO - PID 1236 | Executing test 'netmonitor/complicated.js'
[task 2019-08-16T05:00:59.792Z] 05:00:59 INFO - PID 1236 | [Parent 3588, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1565922974/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-08-16T05:00:59.812Z] 05:00:59 INFO - PID 1236 | [Child 4020, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1565922974/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
[task 2019-08-16T05:05:59.818Z] 05:05:59 INFO - PID 1236 | TEST-UNEXPECTED-FAIL | damp | netmonitor/complicated.js: Test timed out
[task 2019-08-16T05:05:59.836Z] 05:05:59 INFO - Terminating psutil.Process(pid=1236L, name='firefox.exe', started='04:53:49')
[task 2019-08-16T05:06:07.473Z] 05:06:07 INFO - rmtree() failed for "('c:\users\task_1565917244\appdata\local\temp\tmpzedkgw',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...
[task 2019-08-16T05:06:07.473Z] 05:06:07 INFO - rmtree() failed for "('c:\users\task_1565917244\appdata\local\temp\tmpzedkgw',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...
[task 2019-08-16T05:06:07.473Z] 05:06:07 INFO - rmtree() failed for "('c:\users\task_1565917244\appdata\local\temp\tmpzedkgw',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...
[task 2019-08-16T05:06:07.473Z] 05:06:07 INFO - rmtree() failed for "('c:\users\task_1565917244\appdata\local\temp\tmpzedkgw',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...
[task 2019-08-16T05:06:07.473Z] 05:06:07 INFO - rmtree() failed for "('c:\users\task_1565917244\appdata\local\temp\tmpzedkgw',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...
[task 2019-08-16T05:06:07.473Z] 05:06:07 INFO - Exception while removing profile directory: c:\users\task_1565917244\appdata\local\temp\tmpzedkgw
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - [Error 32] The process cannot access the file because it is being used by another process: 'c:\users\task_1565917244\appdata\local\temp\tmpzedkgw\profile\cert9.db'
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - TEST-UNEXPECTED-ERROR | damp | unexpected error
[task 2019-08-16T05:06:07.474Z] 05:06:07 ERROR - Traceback (most recent call last):
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - File "C:\Users\task_1565917244\build\tests\talos\talos\run_tests.py", line 276, in run_tests
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - talos_results.add(mytest.runTest(browser_config, test))
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - File "C:\Users\task_1565917244\build\tests\talos\talos\ttest.py", line 64, in runTest
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - return self._runTest(browser_config, test_config, setup)
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - File "C:\Users\task_1565917244\build\tests\talos\talos\ttest.py", line 216, in _runTest
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - debugger_args=browser_config['debugger_args']
[task 2019-08-16T05:06:07.474Z] 05:06:07 INFO - File "C:\Users\task_1565917244\build\tests\talos\talos\talos_process.py", line 156, in run_browser
[task 2019-08-16T05:06:07.475Z] 05:06:07 INFO - raise TalosError("unexpected error")
[task 2019-08-16T05:06:07.475Z] 05:06:07 INFO - TalosError: unexpected error

Comment 1

[Intermittent Failures Robot]

1 failures in 4839 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2019-08-12&endday=2019-08-18&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Razvan Maries]

New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=307011344&repo=autoland&lineNumber=951

Comment 4

[Intermittent Failures Robot]

2 failures in 4035 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• windows10-64-shippable: 1
• linux64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-06-15&endday=2020-06-21&tree=all

Comment 5

[Razvan Maries]

Started retriggers: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable%2Fopt-talos-damp-e10s%2Ct%28damp%29&tochange=56af0aa5f1169b1b5ba7ab6fe5a7d652285720d4&fromchange=f0e47b29f8c4840d9f9fbe971991f86179b55314&selectedTaskRun=Q8jH-Z5CQ3aQdJSdVym7MA.0

Comment 6

[Noemi Erli[:noemi_erli]]

Continued with the investigation and reached to: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable%2Fopt-talos-damp-e10s%2Ct%28damp%29&tochange=56af0aa5f1169b1b5ba7ab6fe5a7d652285720d4&fromchange=af990b74d334f3146888f4d2aa21a74017e6543d&selectedTaskRun=JBfrAPzWRti7ToDBRBYUBQ.0
Bas Schouten, could this be triggered somehow by the landing of Bug 1606706?

Comment 7

[Intermittent Failures Robot]

22 failures in 4516 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 19
• mozilla-central: 2

Platform breakdown:

• macosx1014-64-shippable: 22

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-06-29&endday=2020-07-05&tree=all

Comment 8

[Bas Schouten (:bas.schouten)]

(In reply to Noemi Erli[:noemi_erli] from comment #6)

Continued with the investigation and reached to: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable%2Fopt-talos-damp-e10s%2Ct%28damp%29&tochange=56af0aa5f1169b1b5ba7ab6fe5a7d652285720d4&fromchange=af990b74d334f3146888f4d2aa21a74017e6543d&selectedTaskRun=JBfrAPzWRti7ToDBRBYUBQ.0
Bas Schouten, could this be triggered somehow by the landing of Bug 1606706?

That patch changed 'timings' in general, in subtle ways, it won't affect this directly, but it definitely can make some intermittents become rarer and some intermittents become more common. If a test has timing issues, it may affect when and how often those issues occur.

Comment 9

[Intermittent Failures Robot]

16 failures in 5265 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 13
• mozilla-central: 2
• try: 1

Platform breakdown:

• macosx1014-64-shippable: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-07-06&endday=2020-07-12&tree=all

Comment 10

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 11

[Alexandru Michis [:malexandru]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=313006599&repo=mozilla-central&lineNumber=15182

Comment 12

[Intermittent Failures Robot]

1 failures in 3601 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-08-10&endday=2020-08-16&tree=all

Comment 13

[Intermittent Failures Robot]

2 failures in 4100 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform breakdown:

• linux64-shippable-qr: 1
• macosx1014-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-08-17&endday=2020-08-23&tree=all

Comment 14

[Intermittent Failures Robot]

3 failures in 4046 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• linux64-shippable-qr: 2
• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-08-24&endday=2020-08-30&tree=all

Comment 15

[Intermittent Failures Robot]

2 failures in 2984 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• windows10-64-shippable-qr: 1
• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-08-31&endday=2020-09-06&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 3410 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-09-07&endday=2020-09-13&tree=all

Comment 17

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 18

[Intermittent Failures Robot]

2 failures in 4130 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux64-shippable-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-10-05&endday=2020-10-11&tree=all

Comment 19

[Sandor Molnar[:smolnar]]

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=318472272&repo=mozilla-central&lineNumber=1893

Comment 20

[Intermittent Failures Robot]

2 failures in 3694 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux64-shippable-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-10-12&endday=2020-10-18&tree=all

Comment 21

[Intermittent Failures Robot]

3 failures in 4230 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• macosx1014-64-shippable: 1
• windows10-64-shippable-qr: 1
• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-10-19&endday=2020-10-25&tree=all

Comment 22

[Intermittent Failures Robot]

2 failures in 4275 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux64-shippable-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-10-26&endday=2020-11-01&tree=all

Comment 23

[Intermittent Failures Robot]

1 failures in 4128 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1574417&startday=2020-11-02&endday=2020-11-08&tree=all

Comment 24

[Intermittent Failures Robot]

2 failures in 4040 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• linux64-shippable-qr: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1574417&startday=2020-11-09&endday=2020-11-15&tree=all

Comment 26

[Julian Descottes [:jdescottes]]

Interesting to see that netmonitor/complicated.js is now a permafail on Fission platforms. I suspect that something landed after my try pushes for Bug 1677587 (no failure on fission at https://treeherder.mozilla.org/jobs?repo=try&revision=ec00fbb804088a67a8e429604c0606a3920df4c9&selectedTaskRun=a1anu85mQo6DRc6fdLb_6g.0) that make the test fail.

We can disable it on fission, but it would be nice to first understand what made this permafail.

Comment 27

[Julian Descottes [:jdescottes]]

We seem to be missing 2 GET requests when Fission is enabled. I compared the HAR export before and after the regression, and the 2 missing requests were:

• http://www.facebook.com-talos/fis/tp5n/bild.de/www.facebook.com/connect/B4K_BWwP7P5.png
• http://www.facebook.com-talos/fis/tp5n/bild.de/www.facebook.com/connect/nZW4C56WJb6.png

They are referenced in css files which are found in both HAR exports:
http://www.facebook.com-talos/fis/tp5n/bild.de/static.ak.fbcdn.net/rsrc.php/v1/yT/r/0wnSWdIMunu.css
http://www.facebook.com-talos/fis/tp5n/bild.de/static.ak.fbcdn.net/rsrc.php/v1/yZ/r/iWHQrTjA1HD.css

Either we are no longer requesting the images, or the netmonitor is not capturing the requests. Bisecting didn't really help so far.
We could temporarily lower the expected number of requests by 2 when Fission is enabled. This would be better than skipping the test.

Comment 28

[Julian Descottes [:jdescottes]]

Attachment: Bug 1574417 - [devtools] Expect 2 requests less in DAMP netmonitor test when Fission is enabled

Comment 29

[Julian Descottes [:jdescottes]]

I got confused by the difference with the requests number, but the root cause of the timeout is that our helper awaitBrowserLoaded https://searchfox.org/mozilla-central/rev/1d34bd022de0b55c81d9db6026f69bda1d4a86d2/testing/talos/talos/tests/devtools/addon/content/damp.js#54 never resolves when Fission is enabled.

It's a very old-style helper, using framescript and message manager. It should be converted to use JS Window Actors (doing a prototype right now). But it feels like the top level page never actually finishes loading for complicated tests when Fission is enabled. I will check if I get the same issue with actors, and if I do it means there is a bigger issue here.

Other "complicated" tests use a custom way to check the "reload" of the page and don't rely on this helper.

Comment 30

[Julian Descottes [:jdescottes]]

Using JSWindowActors doesn't help, the page still never finishes loading. Something in the following pushlog: https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=0463e97f6980f55f1016009263052e86c5513802&tochange=89a7ce645009272cd0a3e3765cb2fa5312f34a25

Since I wrote a prototype to remove the framescript, I'll push that on https://bugzilla.mozilla.org/show_bug.cgi?id=1678379

Comment 31

[Julian Descottes [:jdescottes]]

Attachment: Bug 1574417 - [devtools] Use a specific reload check in DAMP netmonitor complicated test

Comment 32

[Julian Descottes [:jdescottes]]

Attachment: Bug 1574417 - [devtools] Disable netmonitor/compicated DAMP test on Fission platform

Comment 33

[Intermittent Failures Robot]

36 failures in 4810 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

This is the #33 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 36

Platform breakdown:

• linux64-shippable-qr: 19
• windows10-64-shippable-qr: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1574417&startday=2020-11-16&endday=2020-11-22&tree=all

Comment 34

[Intermittent Failures Robot]

31 failures in 1479 pushes (0.021 failures/push) were associated with this bug in the last 7 days.

This is the #13 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 31

Platform breakdown:

• linux64-shippable-qr: 18
• windows10-64-shippable-qr: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1574417&startday=2020-11-23&endday=2020-11-29&tree=all

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/66f906af343d
[devtools] Disable netmonitor/compicated DAMP test on Fission platform r=bomsy,perftest-reviewers

Comment 36

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/66f906af343d

Comment 37

[Intermittent Failures Robot]

3 failures in 3712 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2
• try: 1

Platform breakdown:

• linux64-shippable-qr: 2
• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1574417&startday=2020-11-30&endday=2020-12-06&tree=all

Comment 38

[Alexandre Poirot [:ochameau]]

It looks like this test times out because of some other reason now.
I've not been able to understand why, but I see the test timeout on this line:
https://searchfox.org/mozilla-central/rev/625c3d0c8ae46502aed83f33bd530cb93e926e9f/testing/talos/talos/tests/devtools/addon/content/tests/netmonitor/netmonitor-helpers.js#199

  const waitForEditor = waitForDOMElement(
    monitor,
    "#response-panel .CodeMirror.cm-s-mozilla",
    win
  );
  mouseDownElement(request, win);
  await waitForEditor; // <=== here

I suspect that we end up selecting a request that has no response content available.
The code before that ensures selecting the biggest request, but it might be subject to various race conditions as it is quite asynchronous and not so simple.