Closed Bug 1442406 Opened 2 years ago Closed 2 years ago

Intermittent browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | A promise chain failed to handle a rejection: NetworkError when attempting to fetch resource. - stack: null

Categories

(Firefox :: Site Identity, defect, P5)

defect

Tracking

()

RESOLVED FIXED
Firefox 61
Tracking Status
firefox60 --- fixed
firefox61 --- fixed

People

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

References

Details

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

Attachments

(1 file)

Whiteboard: [stockwell needswork]
Summary: Intermittent browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | A promise chain failed to handle a rejection: NetworkError when attempting to fetch resource. - stack: null

Filed 5 days ago, it already has 34 failures all on linux64-jsdcov / opt. 

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

[task 2018-03-06T10:50:45.085Z] 10:50:45     INFO - Hiding identity popup
[task 2018-03-06T10:50:45.086Z] 10:50:45     INFO - Buffered messages finished
[task 2018-03-06T10:50:45.086Z] 10:50:45     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | A promise chain failed to handle a rejection: NetworkError when attempting to fetch resource. - stack: null
[task 2018-03-06T10:50:45.087Z] 10:50:45     INFO - Rejection date: Tue Mar 06 2018 10:50:44 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 251
Flags: needinfo?(jhofmann)
Georg, I suspect this is from bug 1382359. Can you take a look?
Flags: needinfo?(jhofmann) → needinfo?(gk)
(In reply to Johann Hofmann [:johannh] from comment #4)
> Georg, I suspect this is from bug 1382359. Can you take a look?

Sure. However, it won't happen this week anymore. I'll try to find some time next week but I can't promise anything as I'll be on the week-long Tor dev meeting. I'll get to it the week thereafter, though.
Flags: needinfo?(gk)
(In reply to Georg Koppen from comment #5)
> (In reply to Johann Hofmann [:johannh] from comment #4)
> > Georg, I suspect this is from bug 1382359. Can you take a look?
> 
> Sure. However, it won't happen this week anymore. I'll try to find some time
> next week but I can't promise anything as I'll be on the week-long Tor dev
> meeting. I'll get to it the week thereafter, though.

Okay, thanks. The test might get disabled in the meantime, let's see how it behaves in the next days...
See Also: → 1444674
Duplicate of this bug: 1444674
Alright, I started looking at that. When writing the test I copied and adapted it from `browser_no_mcb_for_loopback.js` taking the test how it originally landed. It turns out that that was causing intermittent NetworkError related failures when unhandled exceptions showed up in browser-chrome tests during work on bug 1242505. The solution for the failure in the loopback test was to whitelist that unhandled exception:

// The following rejections should not be left uncaught. This test has been
// whitelisted until the issue is fixed.
if (!gMultiProcessBrowser) {
  ChromeUtils.import("resource://testing-common/PromiseTestUtils.jsm", this);
  PromiseTestUtils.expectUncaughtRejection(/NetworkError/);
  PromiseTestUtils.expectUncaughtRejection(/NetworkError/);
}

I wonder if the underlying problem is affecting the onion test as well. Is there an easy way to find out from the test log whether `!gMultiProcessBrowser` is `true` for the test when it fails? I tried to look at the different output files available via

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

but am not sure. Would such an exception be acceptable as well? And, how am I supposed to test that a patch I provide is actually fixing those intermittent failures?

Johann, if you are not the right person for the ni? could you find the person who is able to help me with that?
Flags: needinfo?(jhofmann)
Thanks for looking into this!

I think that whitelisting these network errors sounds fine. They're expected to happen because we block those resources, right? But I don't understand why we're only doing it only in non-e10s mode (gMultiProcessBrowser means we have e10s enabled).

Maybe Paolo can help clear that up, since he wrote the original patch :)
Flags: needinfo?(jhofmann) → needinfo?(paolo.mozmail)
Since this issue is intermittent, it is probably distinct from the one in "browser_no_mcb_for_loopback.js", because expectUncaughtRejection requires the error to occur deterministically. You can take a look at the patch in bug 1242505 to get a sense of the different situations we found, but sometimes errors were only reported in non-e10s mode, even though they occurred also in e10s mode.

In fact, most of the tests were whitelisted based purely on automation results. While we fixed the cases for which we knew the cause, we didn't do any further investigations on the cases where the offending code was not obvious. The "browser_no_mcb_for_loopback.js" case might be fixed by terminating a Promise chain with ".catch(Cu.reportError);" somewhere.
Flags: needinfo?(paolo.mozmail)
Attached patch 1442406.patchSplinter Review
Okay, the error message is 

INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “http://123456789abcdef.onion:8/test.js”." {file: "https://example.com/browser/browser/base/content/test/siteIdentity/test_no_mcb_for_onions.html" line: 21}]
INFO - Console message: [JavaScript Error: "TypeError: NetworkError when attempting to fetch resource."]

So it seems something goes wrong while calling `openNewForegroundTab()`. I added a catch-clause to that one and hope that this is fixing the intermittent failures. The test still passes locally for me.
Attachment #8962772 - Flags: review?(ckerschb)
Comment on attachment 8962772 [details] [diff] [review]
1442406.patch

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

worth a try - thanks!
Attachment #8962772 - Flags: review?(ckerschb) → review+
Keywords: checkin-needed
Assignee: nobody → gk
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c8359f8f6142
Fix intermittent test failure of browser_no_mcb_for_onions.js test. r=ckerschb
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/c8359f8f6142
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 61
Whiteboard: [stockwell needswork] → [stockwell fixed:other]
This continues to occur: https://treeherder.mozilla.org/logviewer.html#?job_id=171135299&repo=mozilla-central&lineNumber=2471

[task 2018-03-26T10:22:15.171Z] 10:22:15     INFO - TEST-START | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js
[task 2018-03-26T10:22:15.388Z] 10:22:15     INFO - GECKO(1858) | JavaScript error: , line 0: TypeError: NetworkError when attempting to fetch resource.
[task 2018-03-26T10:22:15.445Z] 10:22:15     INFO - TEST-INFO | started process screentopng
[task 2018-03-26T10:22:15.715Z] 10:22:15     INFO - TEST-INFO | screentopng: exit 0
[task 2018-03-26T10:22:15.715Z] 10:22:15     INFO - Buffered messages logged at 10:22:15
[task 2018-03-26T10:22:15.717Z] 10:22:15     INFO - Entering test bound allowOnionMixedContent
[task 2018-03-26T10:22:15.717Z] 10:22:15     INFO - Console message: [JavaScript Warning: "Loading failed for the <script> with source “http://123456789abcdef.onion:8/test.js”." {file: "https://example.com/browser/browser/base/content/test/siteIdentity/test_no_mcb_for_onions.html" line: 21}]
[task 2018-03-26T10:22:15.717Z] 10:22:15     INFO - Console message: [JavaScript Error: "TypeError: NetworkError when attempting to fetch resource."]
[task 2018-03-26T10:22:15.718Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | hasMixedDisplayContentBlocked not set - false == false - 
[task 2018-03-26T10:22:15.718Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | hasMixedActiveContentBlocked not set - false == false - 
[task 2018-03-26T10:22:15.719Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | Expected state for activeBlocked matches UI state - 
[task 2018-03-26T10:22:15.719Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | Expected state for activeLoaded matches UI state - 
[task 2018-03-26T10:22:15.719Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | Expected state for passiveLoaded matches UI state - 
[task 2018-03-26T10:22:15.720Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identityBox has expected class for activeLoaded - 
[task 2018-03-26T10:22:15.721Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identityBox has expected class for activeBlocked && !passiveLoaded - 
[task 2018-03-26T10:22:15.721Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identityBox has expected class for passiveLoaded && !(activeLoaded || activeBlocked) - 
[task 2018-03-26T10:22:15.722Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identityBox has expected class for passiveLoaded && activeBlocked - 
[task 2018-03-26T10:22:15.722Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | connection icon should be visible - 
[task 2018-03-26T10:22:15.722Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identity-popup has expected attr for activeLoaded - 
[task 2018-03-26T10:22:15.723Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | securityView-body has expected attr for activeLoaded - 
[task 2018-03-26T10:22:15.723Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identity-popup has expected attr for activeBlocked - 
[task 2018-03-26T10:22:15.724Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | securityView-body has expected attr for activeBlocked - 
[task 2018-03-26T10:22:15.724Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | identity-popup has expected attr for passiveLoaded - 
[task 2018-03-26T10:22:15.725Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | securityView-body has expected attr for passiveLoaded - 
[task 2018-03-26T10:22:15.725Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | CC using secure icon - 
[task 2018-03-26T10:22:15.726Z] 10:22:15     INFO - TEST-PASS | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | CC using secure icon - 
[task 2018-03-26T10:22:15.726Z] 10:22:15     INFO - Hiding identity popup
[task 2018-03-26T10:22:15.726Z] 10:22:15     INFO - Buffered messages finished
[task 2018-03-26T10:22:15.727Z] 10:22:15     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | A promise chain failed to handle a rejection: NetworkError when attempting to fetch resource. - stack: (No stack available.)
[task 2018-03-26T10:22:15.727Z] 10:22:15     INFO - Rejection date: Mon Mar 26 2018 10:22:15 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
[task 2018-03-26T10:22:15.727Z] 10:22:15     INFO - Stack trace:
[task 2018-03-26T10:22:15.728Z] 10:22:15     INFO -     resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
[task 2018-03-26T10:22:15.728Z] 10:22:15     INFO -     chrome://mochikit/content/browser-test.js:Tester_execTest/<:1098
[task 2018-03-26T10:22:15.728Z] 10:22:15     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:1067:9
[task 2018-03-26T10:22:15.728Z] 10:22:15     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:967:9
[task 2018-03-26T10:22:15.729Z] 10:22:15     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-03-26T10:22:15.729Z] 10:22:15     INFO - Leaving test bound allowOnionMixedContent
[task 2018-03-26T10:22:15.730Z] 10:22:15     INFO - GECKO(1858) | Collecting coverage for: chrome://mochitests/content/browser/browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js
[task 2018-03-26T10:22:16.784Z] 10:22:16     INFO - GECKO(1858) | Writing coverage to: /builds/worker/workspace/build/blobber_upload_dir/jscov_1522059736781.json
[task 2018-03-26T10:22:16.845Z] 10:22:16     INFO - GECKO(1858) | MEMORY STAT | vsize 2578MB | residentFast 411MB | heapAllocated 142MB
[task 2018-03-26T10:22:16.845Z] 10:22:16     INFO - TEST-OK | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | took 1672ms
[task 2018-03-26T10:22:16.889Z] 10:22:16     INFO - checking window state
[task 2018-03-26T10:22:16.897Z] 10:22:16     INFO - TEST-START | browser/base/content/test/siteIdentity/browser_no_mcb_on_http_site.js
[task 2018-03-26T10:22:17.060Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not load mixed active content!
[task 2018-03-26T10:22:17.060Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not block mixed active content!
[task 2018-03-26T10:22:17.061Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not load mixed display content!
[task 2018-03-26T10:22:17.061Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not block mixed display content!
[task 2018-03-26T10:22:17.259Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not load mixed active content!
[task 2018-03-26T10:22:17.260Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not block mixed active content!
[task 2018-03-26T10:22:17.261Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not load mixed display content!
[task 2018-03-26T10:22:17.261Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not block mixed display content!
[task 2018-03-26T10:22:17.459Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not load mixed active content!
[task 2018-03-26T10:22:17.460Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not block mixed active content!
[task 2018-03-26T10:22:17.461Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not load mixed display content!
[task 2018-03-26T10:22:17.461Z] 10:22:17     INFO - GECKO(1858) | TEST-PASS | unknown test url | OK: Should not block mixed display content!
[task 2018-03-26T10:22:17.623Z] 10:22:17     INFO - GECKO(1858) | Collecting coverage for: chrome://mochitests/content/browser/browser/base/content/test/siteIdentity/browser_no_mcb_on_http_site.js
[task 2018-03-26T10:22:18.783Z] 10:22:18     INFO - GECKO(1858) | Writing coverage to: /builds/worker/workspace/build/blobber_upload_dir/jscov_1522059738780.json
[task 2018-03-26T10:22:18.844Z] 10:22:18     INFO - GECKO(1858) | MEMORY STAT | vsize 2578MB | residentFast 429MB | heapAllocated 162MB
[task 2018-03-26T10:22:18.845Z] 10:22:18     INFO - TEST-OK | browser/base/content/test/siteIdentity/browser_no_mcb_on_http_site.js | took 1948ms
[task 2018-03-26T10:22:18.893Z] 10:22:18     INFO - checking window state
[task 2018-03-26T10:22:21.162Z] 10:22:21     INFO - GECKO(1858) | Completed ShutdownLeaks collections in process 1858
[task 2018-03-26T10:22:21.163Z] 10:22:21     INFO - TEST-START | Shutdown
[task 2018-03-26T10:22:21.164Z] 10:22:21     INFO - Browser Chrome Test Summary
[task 2018-03-26T10:22:21.164Z] 10:22:21     INFO - Passed:  1127
[task 2018-03-26T10:22:21.165Z] 10:22:21     INFO - Failed:  1
[task 2018-03-26T10:22:21.165Z] 10:22:21     INFO - Todo:    0
[task 2018-03-26T10:22:21.165Z] 10:22:21     INFO - Mode:    non-e10s
[task 2018-03-26T10:22:21.166Z] 10:22:21     INFO - *** End BrowserChrome Test Results ***
Flags: needinfo?(gk)
I am not convinced yet. Look at the date of the log: "Rejection date: Mon Mar 26 2018 10:22:15 GMT+0000". So, this is from 3/26 but the fix for this bug did land on 3/28 on m-c.
Flags: needinfo?(gk)
Georg, bellow is a fail from today on m-c.

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

[task 2018-03-30T17:02:11.989Z] 17:02:11     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | A promise chain failed to handle a rejection: NetworkError when attempting to fetch resource. - stack: (No stack available.)
[task 2018-03-30T17:02:11.990Z] 17:02:11     INFO - Rejection date: Fri Mar 30 2018 17:02:11 GMT+0000 (UTC) - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 257
[task 2018-03-30T17:02:11.990Z] 17:02:11     INFO - Stack trace:
[task 2018-03-30T17:02:11.991Z] 17:02:11     INFO -     resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:257
[task 2018-03-30T17:02:11.992Z] 17:02:11     INFO -     chrome://mochikit/content/browser-test.js:Tester_execTest/<:1098
[task 2018-03-30T17:02:11.992Z] 17:02:11     INFO -     Tester_execTest@chrome://mochikit/content/browser-test.js:1067:9
[task 2018-03-30T17:02:11.993Z] 17:02:11     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:967:9
[task 2018-03-30T17:02:11.994Z] 17:02:11     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-03-30T17:02:11.994Z] 17:02:11     INFO - Leaving test bound allowOnionMixedContent
[task 2018-03-30T17:02:11.994Z] 17:02:11     INFO - GECKO(1538) | Collecting coverage for: chrome://mochitests/content/browser/browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js
[task 2018-03-30T17:02:12.964Z] 17:02:12     INFO - GECKO(1538) | Writing coverage to: /builds/worker/workspace/build/blobber_upload_dir/jscov_1522429332961.json
[task 2018-03-30T17:02:13.020Z] 17:02:13     INFO - GECKO(1538) | MEMORY STAT | vsize 2524MB | residentFast 447MB | heapAllocated 177MB
[task 2018-03-30T17:02:13.021Z] 17:02:13     INFO - TEST-OK | browser/base/content/test/siteIdentity/browser_no_mcb_for_onions.js | took 1603ms
Flags: needinfo?(gk)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Blech. So, I wonder what to do, now that the first shot into the dark did not solve this. I can't reproduce this issue locally and it seems try runs are in general fine as well. Christoph: Any ideas, how to move this forward? (Or maybe you know someone who could have an idea)
Flags: needinfo?(gk) → needinfo?(ckerschb)
(In reply to Georg Koppen from comment #23)
> Blech. So, I wonder what to do, now that the first shot into the dark did
> not solve this. I can't reproduce this issue locally and it seems try runs
> are in general fine as well. Christoph: Any ideas, how to move this forward?
> (Or maybe you know someone who could have an idea)

Sorry, I don't have any other ideas at the moment. 16 failures within 718 pushes doesn't seem too bad for now. Obviously it's not great. Once we have the Tor folks back in the seceng team I am pretty sure they can take a closer look at this one again.
Flags: needinfo?(ckerschb)
It seems the failures died down for some reason. Closing this ticket for now then.
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.