Closed Bug 1570478 Opened 5 years ago Closed 3 years ago

Intermittent browser/components/extensions/test/browser/browser_ext_devtools_network.js | A promise chain failed to handle a rejection: 'getEventTimings' active request packet to 'server0.conn16.netEvent21' can't be sent as the conne

Categories

(DevTools :: General, defect, P5)

Product:
DevTools
Component:
General
Platform:
Unspecified
All
Type:
defect

Tracking

(Fission Milestone:Future, firefox-esr78 wontfix, firefox90 wontfix, firefox91 wontfix, firefox92 fixed)

Status:
RESOLVED FIXED
Milestone:
92 Branch
Project Flags:
Fission Milestone Future
Tracking Flags:
Tracking Status
firefox-esr78 --- wontfix
firefox90 --- wontfix
firefox91 --- wontfix
firefox92 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: rpl)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell])

Attachments

(3 files)

Bug 1570478 - Disabled browser_ext_devtools_network.js on Windows, Linux and MacOS. r=jmaher
(deleted), text/x-phabricator-request
Details
Bug 1570478 - Prevent browser_ext_devtools_network.js from failing intermittently due to late RDP requests. r?Honza!
(deleted), text/x-phabricator-request
Details
Bug 1570478 - Re-enabled browser_ext_devtools_network.js on all jobs besides fission. r?mixedpuppy!
(deleted), text/x-phabricator-request
Details

Filed by: rgurzau [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=259200493&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/M1O9qKaVQwSRMzAMROHx5A/runs/0/artifacts/public/logs/live_backing.log

[task 2019-07-31T15:40:56.086Z] 15:40:56 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | HAR log should be empty -
[task 2019-07-31T15:40:56.087Z] 15:40:56 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | onNavigated received the expected url. - Expected: http://example.com/, Actual: http://example.com/ -
[task 2019-07-31T15:40:56.087Z] 15:40:56 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | HAR log should not be empty -
[task 2019-07-31T15:40:56.087Z] 15:40:56 INFO - Buffered messages logged at 15:40:53
[task 2019-07-31T15:40:56.087Z] 15:40:56 INFO - Console message: [JavaScript Warning: "Relative positioning of table rows and row groups is now supported. This site may need to be updated because it may depend on this feature having no effect." {file: "resource://devtools/client/netmonitor/src/components/RequestListHeader.js" line: 440}]
[task 2019-07-31T15:40:56.087Z] 15:40:56 INFO - Buffered messages logged at 15:40:54
[task 2019-07-31T15:40:56.087Z] 15:40:56 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | onNavigated received the expected url. - Expected: http://example.com/, Actual: http://example.com/ -
[task 2019-07-31T15:40:56.088Z] 15:40:56 INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | HAR log should not be empty -
[task 2019-07-31T15:40:56.088Z] 15:40:56 INFO - Buffered messages logged at 15:40:55
[task 2019-07-31T15:40:56.088Z] 15:40:56 INFO - Developer toolbox closed for target {}
[task 2019-07-31T15:40:56.088Z] 15:40:56 INFO - Console message: [JavaScript Error: "uncaught exception: Object"]
[task 2019-07-31T15:40:56.088Z] 15:40:56 INFO - Console message: [JavaScript Error: "Error: Error while calling method getEventTimings: 'getEventTimings' active request packet to 'server0.conn16.netEvent21' can't be sent as the connection just closed." {file: "resource://devtools/client/netmonitor/src/connector/firefox-data-provider.js" line: 615}]
[task 2019-07-31T15:40:56.088Z] 15:40:56 INFO - Buffered messages finished
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | A promise chain failed to handle a rejection: 'getEventTimings' active request packet to 'server0.conn16.netEvent21' can't be sent as the connection just closed. - stack: listenerJson@resource://devtools/shared/client/debugger-client.js:342:11
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - emit@resource://devtools/shared/event-emitter.js:190:24
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - emit@resource://devtools/shared/event-emitter.js:271:18
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - reject@resource://devtools/shared/client/debugger-client.js:816:15
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - purgeRequests/<@resource://devtools/shared/client/debugger-client.js:837:47
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - purgeRequests@resource://devtools/shared/client/debugger-client.js:837:28
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - onClosed@resource://devtools/shared/client/debugger-client.js:763:10
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - close@resource://devtools/shared/transport/local-transport.js:171:20
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - close@resource://devtools/shared/transport/local-transport.js:167:13
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - close@resource://devtools/shared/transport/local-transport.js:167:13
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - cleanup@resource://devtools/shared/client/debugger-client.js:216:27
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - close/promise<@resource://devtools/shared/client/debugger-client.js:232:7
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - close@resource://devtools/shared/client/debugger-client.js:209:21
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - TargetMixin/destroy/this._destroyer<@resource://devtools/shared/fronts/targets/target-mixin.js:581:32
[task 2019-07-31T15:40:56.089Z] 15:40:56 INFO - asyncdestroy@resource://devtools/shared/fronts/targets/target-mixin.js:604:9
[task 2019-07-31T15:40:56.090Z] 15:40:56 INFO - destroy@resource://devtools/shared/fronts/targets/browsing-context.js:148:27
[task 2019-07-31T15:40:56.090Z] 15:40:56 INFO - _destroyToolbox/onceDestroyed</<@resource://devtools/client/framework/toolbox.js:3626:27
[task 2019-07-31T15:40:56.090Z] 15:40:56 INFO - async_destroyToolbox/onceDestroyed<@resource://devtools/client/framework/toolbox.js:3585:12
[task 2019-07-31T15:40:56.090Z] 15:40:56 INFO - _destroyToolbox@resource://devtools/client/framework/toolbox.js:3581:27
[task 2019-07-31T15:40:56.090Z] 15:40:56 INFO - destroy@resource://devtools/client/framework/toolbox.js:3457:28

Pushed by rmaries@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7e5d7996aafe
Disabled browser_ext_devtools_network.js on Windows, Linux and MacOS. r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Summary: Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_devtools_network.js | A promise chain failed to handle a rejection: 'getEventTimings' active request packet to 'server0.conn16.netEvent21' can't be sent as the conne → Intermittent browser/components/extensions/test/browser/browser_ext_devtools_network.js | A promise chain failed to handle a rejection: 'getEventTimings' active request packet to 'server0.conn16.netEvent21' can't be sent as the conne
Flags: needinfo?(jmathies)

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Component: Untriaged → General
Product: WebExtensions → DevTools

Honza, can you check if this long living bug can be fixed so the frequent failures will be resolved?

Flags: needinfo?(odvarko)

Luca, could you please take a look at this?
Thanks!

Flags: needinfo?(odvarko) → needinfo?(lgreco)

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #59)

Luca, could you please take a look at this?
Thanks!

I looked to a sample of the failures and it seems that the failure are triggered by a getEventTimings RDP request that we are sending right after we close the toolbox and existing the test.
I would like to check what is triggering that late RDP request, but I've been unable to trigger the failure locally on Linux and macOs :-(, my guess is that we may be logging in the webconsole requests that are triggered internally from chrome privileged code, but I have been unable to double-check that theory locally (and the screenshot associated on try to the failure isn't useful because we are taking it after the toolbox has been closed).

One way to prevent the failure (especially if the late RDP request is unrelated to the tested scenario at it seems) could be to add something like PromiseTestUtils.allowMatchingRejectionsGlobally(/can't be sent as the connection just closed/); to prevent the late RDP request to trigger a failure when we have closed the toolbox and exiting the test.

I'm going to give another try to reproduce the issue locally (e.g. I think that I'm going to try to "force" the conditions that I think may trigger this), otherwise I think the best option to double-check the proposed workaround is to run a couple of push to try and see if I can reproduce it often enough without the patch (and then I can't reproduce it anymore with the workaround applied to it).

Flags: needinfo?(lgreco)

Re-assign a needinfo to me (to give it another try locally or with a push to try and check if the workaround proposed in comment 60 would prevent the failure as expected).

Flags: needinfo?(lgreco)

A late getEventTimings RDP request is being cancelled while we are exiting the test case and we have already closed the devtools toolbox.

The related network request is very likely unrelated to the scenario being tested (I suspect it may be an HTTP request triggered by some
privileged code and being automatically added to the webconsole panel, it is not unlikely that we are not explicitly checking if the http
requests logged in the webconsole are actually related to the extension that the devtools toolbox is targeting).

In the meantime, the attached patch is adding to the PromiseTestUtils's "global allow list" the rejections for any late RDP request
that may still be pending while the test is exiting.

Assignee: nobody → lgreco
Status: NEW → ASSIGNED

The following two "push to try" seems to confirm that the attached patch is going to prevent the intermittent failure:

There is a good chance that we may also re-enable this test to run on linux and win/macos debug builds (based on the push to try linked above, where I temporarily re-enabled it on all builds, and only skipped it on fission), but I think that it would be better to do it separately (after we verified that the test isn't failing intermittently anymore after we landed the attached patch).

Flags: needinfo?(lgreco)

Thanks for working on this Luca, I appreciate it!

Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/4d1264a76227
Prevent browser_ext_devtools_network.js from failing intermittently due to late RDP requests. r=Honza
Whiteboard: [stockwell disabled] → [stockwell disabled] [not-a-fission-bug]

Even though this test is skipped for Fission, this test failure is unlikely a Fission bug because this test is also disabled for e10s on many platforms: all Linux, debug macOS, and debug Win64:

[browser_ext_devtools_network.js]
skip-if = fission || os == 'linux' || (os == 'mac' && debug) || (debug && os == 'win' && bits == 64) # Bug1570478

https://searchfox.org/mozilla-central/rev/74f3c420ee54001059e1850bef3be876749ff873/browser/components/extensions/test/browser/browser.ini#109-110

(In reply to Chris Peterson [:cpeterson] from comment #73)

Even though this test is skipped for Fission, this test failure is unlikely a Fission bug because this test is also disabled for e10s on many platforms: all Linux, debug macOS, and debug Win64:

[browser_ext_devtools_network.js]
skip-if = fission || os == 'linux' || (os == 'mac' && debug) || (debug && os == 'win' && bits == 64) # Bug1570478

Even though this is not a new bug caused by Fission, once Fission is enabled by default, this browser_ext_devtools_network.js test will effectively be disabled on all platforms by the skip-if = fission.

Fission Milestone: --- → Future
OS: Unspecified → All
Whiteboard: [stockwell disabled] [not-a-fission-bug] → [stockwell disabled]

I just took a look if (as I did mention in comment 63) the test as tweaked with the last patch landed (linked in comment 66) was still failing intermittently on the builds where it is currently skipped and:

  • it didn't fail locally using --verify (on linux64 opt)
  • it didn't fail in this push to try neither: https://treeherder.mozilla.org/jobs?repo=try&revision=fac5e0aeba3ffa34fc6a1148453a70ffbe6aef89 (it didn't include any macos job though, the try syntax I used may not be valid anymore for some reason,and it doesn't include any job running TV with fission enabled)
  • it did fail for me locally (on linux64 opt) when using --verify and --enable-fission, while running in chaos mode, but the underlying issue doesn't seem to be the same that was originally tracked by this bugzilla issue

I think that it would be reasonable to start by landing a patch that removes all other skip-if that do not seem to be necessary anymore, and in the meantime look more closely to the failure happening when the test does run with fission enabled.

I'll collect some details from the failures I was able to trigger locally when I run it with --verify --enable-fission and I'll add those details in a new comment here.

I looked into this again today, but I did also recall that fixing and re-enabling this test on fission is actually already tracked by Bug 1691575 and so I'll comment there about the fission-related failure.

In the meantime I think that as part of this bug we should re-enable this test on the other builds where it is currently skipped and confirm that they do not fail intermittently anymore (as the last push to try linked in comment 75 seems to suggest), I'll attach a patch.

See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=1691575
Keywords: leave-open
Pushed by luca.greco@alcacoop.it:
https://hg.mozilla.org/integration/autoland/rev/6a86f7c7c8a2
Re-enabled browser_ext_devtools_network.js on all jobs besides fission. r=mixedpuppy

https://hg.mozilla.org/mozilla-central/rev/6a86f7c7c8a2

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox92: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 92 Branch
Whiteboard: [stockwell disabled] → [stockwell]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: