1716452 - Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/mochitest/test_ext_webrequest_auth.html | application timed out after 370 seconds with no output

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=342754204&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QivaseasQc6rmZ5gni9nSQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-06-14T22:55:32.941Z] 22:55:32     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_webrequest_auth.html | authHandler.onAuthRequired called with 840 http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/authenticate.sjs?realm=auth_nonblocking_forwardAuth&user=auth_nonblocking_forwardAuth&pass=auth_nonblocking_forwardAuth result undefined 
[task 2021-06-14T22:55:32.941Z] 22:55:32     INFO - Buffered messages finished
[task 2021-06-14T22:55:32.942Z] 22:55:32    ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/mochitest/test_ext_webrequest_auth.html | application timed out after 370 seconds with no output
[task 2021-06-14T22:55:32.942Z] 22:55:32    ERROR - Force-terminating active process(es).
[task 2021-06-14T22:55:32.942Z] 22:55:32     INFO - Determining child pids from psutil...
[task 2021-06-14T22:55:32.953Z] 22:55:32     INFO - [5328, 5350, 5415, 5448, 5482, 5512, 5545, 5566, 5598, 5631, 5659, 5696, 5729, 5761, 5787, 5826, 5853, 5875, 5906, 5931, 5956, 5981, 6006, 6031, 6056, 6081, 6106, 6131, 6157, 6182, 6230]
[task 2021-06-14T22:55:32.954Z] 22:55:32     INFO - ==> process 5267 launched child process 5287

Comment 1

[Cosmin Sabou [:CosminS]]

Looks like this has started after Bug 1709838 landed. Retriggers.
Christoph, could you have a look over it? Thank you.

Comment 2

[Intermittent Failures Robot]

27 failures in 2888 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 14
• mozilla-central: 13

Platform and build breakdown:

• linux1804-64: 15
  • debug: 15
• linux1804-64-qr: 6
  • debug: 6
• linux1804-64-asan: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-06-14&endday=2021-06-20&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1709838

Comment 4

[Christoph Kerschbaumer [:ckerschb]]

On it ...

Comment 5

[Christoph Kerschbaumer [:ckerschb]]

Hey Cosmin, I evaluated test test_ext_webrequest_auth.html in detail and I don't think that Bug 1709838 is causing the intermittent.

In more detail:
Within Bug 1709838, we enable https-first in Private Windows which upgrades all connections from http to https in PBM but ...

• only in case the port is the default port - in other words, https-first does not apply to http://mochi.test:8888/ like in the testcase
• only upgrades connections in PBM which is not the case in the testcase.

When running the test I also couldn't find any upgrades or any other indicators that https-first would be messing with it - maybe some other patch that caused this intermittent to appear?

Comment 6

[Cosmin Sabou [:CosminS]]

Hi Christoph, maybe it's something that surfaced along with those changes.
The thing is that before those changes there are 11 green jobs for test_ext_webrequest_auth (log) and after the patch landed there are 8/21 timeouts as you can see from this TH link. Added 20 retriggers more to see if it will fail on the previous push.

Comment 7

[Cosmin Sabou [:CosminS]]

After 20 more retriggers it's still there it fails first.

Comment 8

[Christoph Kerschbaumer [:ckerschb]]

(In reply to Cosmin Sabou [:CosminS] from comment #7)

After 20 more retriggers it's still there it fails first.

Hey Shane, I don't know how to move forward with this intermittent test failure. I left some analysis in comment 5, but I can't reproduce the error. I was wondering, since you wrote the test, if you could take a look and maybe with joint forces we get the problem resolved - thank you!

Comment 9

[Intermittent Failures Robot]

53 failures in 3115 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #26 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:

• autoland: 38
• mozilla-central: 12
• try: 3

Platform and build breakdown:

• linux1804-64-qr: 9
  • debug: 9
• linux1804-64-asan: 9
  • opt: 9
• linux1804-64: 35
  • debug: 35

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-06-21&endday=2021-06-27&tree=all

Comment 10

[Shane Caraveo (:mixedpuppy)]

There is probably some minor timing change that affects this test on linux. The log shows that onAuthRequired is called, but otherwise there is not much logging in this test.

I would add some logging between each await and figure out which promise is failing, that might tell us something. Then maybe consider doing a Promise.all on these promises: https://searchfox.org/mozilla-central/rev/683046a2d37e1e2a4fd68e7749c1effd1aee2d38/toolkit/components/extensions/test/mochitest/test_ext_webrequest_auth.html#109-117

Failing that, I'd disable the test for linux+debug since that seems to be the bulk of the timeouts.

Comment 11

[Atila Butkovits]

Attachment: Bug 1716452 - disable test_ext_webrequest_auth.html on Linux_debug for frequent failures. r=#intermittent-reviewers

Comment 12

[Intermittent Failures Robot]

39 failures in 723 pushes (0.054 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:

• try: 5
• mozilla-central: 17
• autoland: 17

Platform and build breakdown:

• linux1804-64: 31
  • debug: 31
• linux1804-64-qr: 6
  • debug: 6
• linux1804-64-asan: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-06-28&endday=2021-07-04&tree=all

Comment 13

[Intermittent Failures Robot]

61 failures in 2387 pushes (0.026 failures/push) were associated with this bug in the last 7 days.

This is the #14 most frequent failure this week.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 25
• mozilla-central: 25
• try: 11

Platform and build breakdown:

• linux1804-64: 45
  • debug: 45
• linux1804-64-qr: 13
  • debug: 13
• linux1804-64-asan: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-07-05&endday=2021-07-11&tree=all

Comment 15

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hey Shane,
have you even been able to trigger it locally? I even tried to add some debugging logging and trigger it in a push to try with a TV job but unfortunately I've been unable to trigger it in that TV job, despite the TV job did run 10 times).
This makes me suspect there may be some interaction with a test case running before this one, and without both the test does not fail even if executed multiple times and in chaos mode (as the TV job does).

Follows some more context related to a couple of details I did notice while looking to this intermittent failure logs.

---

Looking to a bunch of the intermittent failures tracked in this bug, I did notice that all screenshot captured when the failure is triggered show the authentication dialog open, while the test is expected to be intercepting requests to open the authentication dialog and replace it with a mock object to test the behaviors expected by this test.

I'm unable to trigger this locally and so I didn't dig more into it, but looking to what class AuthRequestor (defined and used internally in WebRequest.jsm) I did notice that AuthRequestor's _getForwardPrompt does have a try..catch with an empty catch block as part of its own fallback mechanism, and so there is a chance that the test is somehow triggering an exception when the test fails and the fallback mechanism is calling the authentication dialog as a side effect of that, but the empty catch block is preventing us to see an error log when that happens.

If we could trigger the failure with some additional debugging logs in those two _getForwardPrompt's try...catch blocks may help to shade some lights about this intermittent.

To be fair, it may be reasonable to still report the error using (Cu.reportError) if we are running on a debug build, that may help us to get some more details to work with if this kind of unexpected issue will keep happening in the future.

Comment 16

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1716452 - Ensure WebRequest.jsm AuthRequestor _getForwardPrompt does report errors in debug builds. r?mixedpuppy!

Comment 17

[Luca Greco [:rpl] [:luca] [:lgreco]]

Adding leave-open to prevent this issue from being closed once D119644, the purpose of that patch it to provide us some more details from the failure happening while the test runs on the build infrastructure along with the other tests in the same chunk, but it wouldn't fix the intermittent failure yet.

(Also clearing the needinfo assigned to Shane, we have already discussed about this and agreed to proceed with the proposed approach described in comment 15).

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d5e14c4d6f96
Ensure WebRequest.jsm AuthRequestor _getForwardPrompt does report errors in debug builds. r=mixedpuppy

Comment 19

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/d5e14c4d6f96

Comment 20

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1716452 - Fix test_ext_webrequest_auth.html intermittent failures. r?mixedpuppy!

This patch fixes the intermittent failures being triggered by test_ext_webrequest_auth.html by making sure that
the "http-on-modify-request" observer added by the test tasks part of this test file are going to ignore any http
request that isn't related to the mochi.test url that is expected to trigger the authentication dialog.

With the previous version of the chrome script executed by these two test tasks, there was a chance that the observer
would be setting the mocked nsIAuthPromptProvider/nsIauthPromp2 notification callback on the wrong channel, if
the http channel was also related to the mochi.test host. After that the observer was removed and it would not be
setting the notificationCallbacks on the channel that was meant to set it on (and that would make it the test to
trigger the actual authentication prompt that can be seen in the failure screenshots).

As part of this patch we are also reventing the additional debugging logs added in a previous patch attached to
this issue.

Comment 21

[Luca Greco [:rpl] [:luca] [:lgreco]]

Removing leave-open keyword, we are pushing to autoland the fix attached to this issue as D119880, and I'm pretty confident it should prevent these intermittent failures from now on.

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9078c74116cd
Fix test_ext_webrequest_auth.html intermittent failures. r=mixedpuppy

Comment 23

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/9078c74116cd

Comment 24

[Intermittent Failures Robot]

32 failures in 2224 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #43 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:

• autoland: 16
• mozilla-beta: 7
• mozilla-central: 6
• try: 2
• mozilla-esr91: 1

Platform and build breakdown:

• linux1804-64-qr: 4
  • debug: 4
• linux1804-64: 27
  • debug: 27
• linux1804-64-asan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-07-12&endday=2021-07-18&tree=all

Comment 25

[Luca Greco [:rpl] [:luca] [:lgreco]]

The trend of the intermittent failures tracked by this bug seems to also confirm the last patch we landed (comment 23) is preventing the unexpected timeout failures.

Removing disable-recommended from the whiteboard to reflect that.

Comment 26

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:rpl, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Comment 27

[Andreea Pavel [:apavel]]

mozilla-beta failure https://treeherder.mozilla.org/logviewer?job_id=345632569&repo=mozilla-beta&lineNumber=10340

Comment 28

[Luca Greco [:rpl] [:luca] [:lgreco]]

(In reply to Release mgmt bot [:sylvestre / :calixte / :marco for bugbug] from comment #26)

The patch landed in nightly and beta is affected.
:rpl, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

The patch with the fix would not graft cleanly on beta as is without landing both D119644 and D119880 (because the fix from D119880 does also revert the additional debugging logging added in D119644).

It may not be worth it If the intermittency rate in beta isn't that high, but if the intermittency rate on beta is high enough to be annoying then I'll be more than happy to attach a separate test-only patch that does only apply the fix to the test (which wouldn't also require an explicit uplift request).

Andreaa, wdyt?

Comment 29

[Andreea Pavel [:apavel]]

(In reply to Luca Greco [:rpl] [:luca] [:lgreco] from comment #28)

(In reply to Release mgmt bot [:sylvestre / :calixte / :marco for bugbug] from comment #26)

The patch landed in nightly and beta is affected.
:rpl, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

The patch with the fix would not graft cleanly on beta as is without landing both D119644 and D119880 (because the fix from D119880 does also revert the additional debugging logging added in D119644).

It may not be worth it If the intermittency rate in beta isn't that high, but if the intermittency rate on beta is high enough to be annoying then I'll be more than happy to attach a separate test-only patch that does only apply the fix to the test (which wouldn't also require an explicit uplift request).

Andreaa, wdyt?

Failure rate is not high at the moment https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-07-12&endday=2021-07-19&tree=mozilla-beta&bug=1716452.
We'll keep an eye on it and add a ni if it gets high frequency.

Thank you!

Comment 30

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 13
• mozilla-esr91: 3

Platform and build breakdown:

• linux1804-64: 14
  • debug: 14
• linux1804-64-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-07-19&endday=2021-07-25&tree=all

Comment 31

[Ryan VanderMeulen [:RyanVM]]

IMO, we should go ahead with the test-only uplift patch as we'll be living with these failures on ESR91 for the next year otherwise.

Comment 32

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: beta91-folded-and-rebased--Bug_1716452___Fix_test_ext_webrequest_auth_html_intermittent_failures__r_mixedpuppy.patch

This attachment contains the fix landed on Nightly, turned into a single test-only patch that can be applied cleanly on 91 beta as is (got by just folding both D119644 and D119880 into a single patch and then double-checking that it does apply without conflicts on 91 beta as expected).

Comment 33

[Luca Greco [:rpl] [:luca] [:lgreco]]

(In reply to Ryan VanderMeulen [:RyanVM] from comment #31)

IMO, we should go ahead with the test-only uplift patch as we'll be living with these failures on ESR91 for the next year otherwise.

+1 That's definitely a good point.

I've just attached in comment 32 the test-only patch which can be grafted on 91 beta.

Comment 34

[Pascal Chevrel:pascalc (PTO until Sept 2)]

https://hg.mozilla.org/releases/mozilla-beta/rev/bbc5de09297c

Comment 35

[Intermittent Failures Robot]

6 failures in 3131 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 6

Platform and build breakdown:

• linux1804-64: 6
  • debug: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1716452&startday=2021-07-26&endday=2021-08-01&tree=all