1413391 - Intermittent Perma test-verify browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | A promise chain failed to handle a rejection: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE)

Status: RESOLVED INCOMPLETE

(Firefox :: Settings UI, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: csabou [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=141200431&repo=mozilla-central

https://queue.taskcluster.net/v1/task/bH-0m_mYR5-7Ym28Rgu8JA/runs/0/artifacts/public/logs/live_backing.log

https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=ae1d655ea7c7101543ac56e88414de4527bd7540&filter-searchStr=tv

[task 2017-11-01T00:42:56.285Z] 00:42:56     INFO - TEST-PASS | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | Non-Privacy element of id=firefoxAccountCategory should be hidden - 
[task 2017-11-01T00:42:56.286Z] 00:42:56     INFO - TEST-PASS | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | Element should not be null, when checking visibility - 
[task 2017-11-01T00:42:56.289Z] 00:42:56     INFO - TEST-PASS | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | Non-Privacy element of id=weavePrefsDeck should be hidden - 
[task 2017-11-01T00:42:56.290Z] 00:42:56     INFO - Buffered messages finished
[task 2017-11-01T00:42:56.291Z] 00:42:56     INFO - TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | A promise chain failed to handle a rejection: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIApplicationCacheService.getGroups] - stack: null
[task 2017-11-01T00:42:56.291Z] 00:42:56     INFO - Rejection date: Wed Nov 01 2017 00:42:55 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 253
[task 2017-11-01T00:42:56.294Z] 00:42:56     INFO - Stack trace:
[task 2017-11-01T00:42:56.296Z] 00:42:56     INFO -     resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:253
[task 2017-11-01T00:42:56.297Z] 00:42:56     INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:449
[task 2017-11-01T00:42:56.298Z] 00:42:56     INFO -     testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1102:11
[task 2017-11-01T00:42:56.299Z] 00:42:56     INFO -     run@chrome://mochikit/content/browser-test.js:1039:9
[task 2017-11-01T00:42:56.299Z] 00:42:56     INFO - GECKO(5729) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2017-11-01T00:42:56.301Z] 00:42:56     INFO - GECKO(5729) | MEMORY STAT | vsize 2250MB | residentFast 289MB | heapAllocated 134MB
[task 2017-11-01T00:42:56.302Z] 00:42:56     INFO - TEST-OK | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | took 964ms
[task 2017-11-01T00:42:56.303Z] 00:42:56     INFO - checking window state

Comment 1

[Tiberius Oros[:tiberius_oros]]

Starting with October 31st, there have been 32 failures. 
It fails mostly on windows10-64 and Windows 7 platforms, but there is a higher number of failures on OS X 10.10 and Linux x64, too.
The failures occur mostly on opt and debug build types and there are also some failures on pgo and asan.

Here is an example of a recent log: 
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=141204925&lineNumber=6554

And a relevant snippet of the log: 

01:06:31     INFO -  100 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | Non-Privacy element of id=firefoxAccountCategory should be hidden -
6551
01:06:31     INFO -  101 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | Element should not be null, when checking visibility -
6552
01:06:31     INFO -  102 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | Non-Privacy element of id=weavePrefsDeck should be hidden -
6553
01:06:31     INFO -  Buffered messages finished
6554
01:06:31    ERROR -  103 INFO TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | A promise chain failed to handle a rejection: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIApplicationCacheService.getGroups] - stack: null
6555
01:06:31     INFO -  Rejection date: Wed Nov 01 2017 01:06:30 GMT+0000 (Coordinated Universal Time) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 253
6556
01:06:31     INFO -  Stack trace:
6557
01:06:31     INFO -      resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:253
6558
01:06:31     INFO -      chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:449
6559
01:06:31     INFO -      testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1102:11
6560
01:06:31     INFO -      run@chrome://mochikit/content/browser-test.js:1039:9
6561
01:06:31     INFO -  GECKO(5480) | MEMORY STAT | vsize 712MB | vsizeMaxContiguous 795MB | residentFast 217MB | heapAllocated 97MB
6562
01:06:31     INFO -  104 INFO TEST-OK | browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js | took 556ms
6563
01:06:31     INFO -  105 INFO checking window state
6564
01:06:31     INFO -  106 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 174}]
6565
01:06:32     INFO -  GECKO(5480) | Completed ShutdownLeaks collections in process 4732
6566
01:06:32     INFO -  GECKO(5480) | Completed ShutdownLeaks collections in process 3372
6567
01:06:32     INFO -  GECKO(5480) | Completed ShutdownLeaks collections in process 5308
6568
01:06:32     INFO -  GECKO(5480) | Completed ShutdownLeaks collections in process 5480
6569
01:06:32     INFO -  107 INFO TEST-START | Shutdown
6570
01:06:32     INFO -  108 INFO Browser Chrome Test Summary
6571
01:06:32     INFO -  109 INFO Passed:  117
6572
01:06:32  WARNING -  110 INFO Failed:  1
6573
01:06:32  WARNING -  One or more unittests failed.

Comment 2

[Geoff Brown [:gbrown]]

This test verification failure was triggered by the changes in bug 1399808. Failures happened on all platforms and repeated on tree merges to produce 30+ failures, but those won't happen again until/unless the test is modified again.

Bug 1399808 only made a small change to the test; it seems unlikely that it introduced this failure. Probably this was a pre-existing condition.

Other than a very low-frequency bug 1258937, this test is normally well behaved.

For these reasons, I'd say taking any action to address this failure is optional. Leaving the ni for :jaws in case he wants to follow up.


Running locally on Ubuntu, I can easily reproduce this failure with

  mach mochitest browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js

but it runs fine if I test the whole directory

  mach mochitest browser/components/preferences/in-content/tests

...suggesting this test relies on state from a previous test in the same directory.

Comment 3

[Fischer [:Fischer]]

(In reply to Geoff Brown [:gbrown] from comment #2)
> Running locally on Ubuntu, I can easily reproduce this failure with
> 
>   mach mochitest
> browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js
> 
I can see the error on a local test too when only testing browser_bug795764_cachedisabled.js

> but it runs fine if I test the whole directory
> 
>   mach mochitest browser/components/preferences/in-content/tests
> 
> ...suggesting this test relies on state from a previous test in the same
> directory.
The same results as the bug 1399808 TRY results...
The bug 1399808 ran 5x TRY runs against the whole dir and the results were good

[1] https://bugzilla.mozilla.org/show_bug.cgi?id=1399808#c7

Comment 4

[Fischer [:Fischer]]

Attachment: 0001-Try-not-to-use-SpecialPowers.pushPrefEnv.patch

Comment 5

[Fischer [:Fischer]]

(In reply to Tiberius Oros[:tiberius_oros] from comment #1)
> Starting with October 31st, there have been 32 failures. 
> It fails mostly on windows10-64 and Windows 7 platforms, but there is a
> higher number of failures on OS X 10.10 and Linux x64, too.
> The failures occur mostly on opt and debug build types and there are also
> some failures on pgo and asan.
> 
> Here is an example of a recent log: 
> https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=141204925&lineNumber=6554
> 
From the logs, it showed all test operations passed and it failed at the point where the test was about to be closed.
This leads me to `SpecialPowers.pushPrefEnv`, which something goes wrong while trying to roll back the prefs at the end of closing the test.

Made a patch[1] which tries not to call `SpecialPowers.pushPrefEnv` and the local test run now passes.

This is weird to me because all the bug 1399808 did is only to remove one pref to manipulate in the test.

[1] attachment 8924398 [details] [diff] [review] [diff] [review]: 0001-Try-not-to-use-SpecialPowers.pushPrefEnv.patch

Comment 6

[Fischer [:Fischer]]

(In reply to Fischer [:Fischer] from comment #3)
> (In reply to Geoff Brown [:gbrown] from comment #2)
> > Running locally on Ubuntu, I can easily reproduce this failure with
> > 
> >   mach mochitest
> > browser/components/preferences/in-content/tests/browser_bug795764_cachedisabled.js
> > 
> I can see the error on a local test too when only testing
> browser_bug795764_cachedisabled.js
> 
> > but it runs fine if I test the whole directory
> > 
> >   mach mochitest browser/components/preferences/in-content/tests
> > 
> > ...suggesting this test relies on state from a previous test in the same
> > directory.
> The same results as the bug 1399808 TRY results...
> The bug 1399808 ran 5x TRY runs against the whole dir and the results were good
Sorry correct myself: 
Not 5x times (this is about another bug. I was lost between bugs...)
But still against the whole test dir and the results were good.
> 
> [1] https://bugzilla.mozilla.org/show_bug.cgi?id=1399808#c7

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

odd about specialpowers.pushPrefEnv, I have recently seen other bugs where it looks like the prefs were not being applied- I did look over it in detail and it looks proper, but possibly there are edge cases or issues as we have moved to multi process where we need to wait for different events or fire different events.

Comment 8

[Intermittent Failures Robot]

34 failures in 857 pushes (0.04 failures/push) were associated with this bug in the last 7 days.   

** 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-inbound: 14
* mozilla-central: 12
* autoland: 8

Platform breakdown:
* windows7-32: 10
* windows10-64: 10
* linux64: 8
* osx-10-10: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1413391&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 9

[Jared Wein [:jaws] (please needinfo? me)]

Comment on attachment 8924398 [details] [diff] [review]
0001-Try-not-to-use-SpecialPowers.pushPrefEnv.patch

Review of attachment 8924398 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the investigation Fischer! That is odd how pushPrefEnv is failing here. Switching to using a setTimeout of 2 seconds will be worse than what's currently there. Let's live with the failures for now and hopefully when someone figures out what's wrong with pushPrefEnv then a lot of intermittents can be closed.

Comment 10

[Firefox Bug Husbandry Bot]

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