Closed Bug 1607823 Opened 4 years ago Closed 4 years ago

Intermittent remote/test/browser/network/browser_setCacheDisabled.js | Uncaught exception - [Exception... "(null)" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "<unknown>" data: no]

Categories

(Remote Protocol :: Agent, defect, P1)

defect

Tracking

(firefox74 fixed)

RESOLVED FIXED
Firefox 74
Tracking Status
firefox74 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: ccoroiu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=284020507&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UMl3GBCfS3GLpmwmdKuETQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UMl3GBCfS3GLpmwmdKuETQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


task 2020-01-08T13:07:36.438Z] 13:07:36 INFO - TEST-START | remote/test/browser/network/browser_setCacheDisabled.js
[task 2020-01-08T13:07:36.453Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f10b592d800 == 9 [pid = 1126] [id = {34151ac6-399b-4d69-b782-bf33bfdbae05}]
[task 2020-01-08T13:07:36.454Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 31 (0x7f10b82faf20) [pid = 1126] [serial = 31] [outer = (nil)]
[task 2020-01-08T13:07:36.455Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 32 (0x7f10b997b400) [pid = 1126] [serial = 32] [outer = 0x7f10b82faf20]
[task 2020-01-08T13:07:36.462Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 33 (0x7f10b9988c00) [pid = 1126] [serial = 33] [outer = 0x7f10b82faf20]
[task 2020-01-08T13:07:36.551Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 45
[task 2020-01-08T13:07:36.552Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 57
[task 2020-01-08T13:07:36.553Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 45
[task 2020-01-08T13:07:36.553Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 57
[task 2020-01-08T13:07:36.569Z] 13:07:36 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fd38e0b5000 == 2 [pid = 1291] [id = {bca4a278-c4df-46e3-8b9d-efb20725ab58}]
[task 2020-01-08T13:07:36.571Z] 13:07:36 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (0x7fd38f4af2e0) [pid = 1291] [serial = 5] [outer = (nil)]
[task 2020-01-08T13:07:36.571Z] 13:07:36 INFO - GECKO(1126) | [Child 1291, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 848
[task 2020-01-08T13:07:36.571Z] 13:07:36 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (0x7fd38e071400) [pid = 1291] [serial = 6] [outer = 0x7fd38f4af2e0]
[task 2020-01-08T13:07:36.590Z] 13:07:36 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (0x7fd38f2d1400) [pid = 1291] [serial = 7] [outer = 0x7fd38f4af2e0]
[task 2020-01-08T13:07:36.698Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 32 (0x7f10c03dcc00) [pid = 1126] [serial = 5] [outer = (nil)] [url = about:blank]
[task 2020-01-08T13:07:36.698Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 31 (0x7f10bd328c00) [pid = 1126] [serial = 9] [outer = (nil)] [url = about:blank]
[task 2020-01-08T13:07:36.719Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f10b82d8000 == 8 [pid = 1126] [id = {58c75e51-9294-4c96-8eb5-d38af6ce371e}] [url = about:blank]
[task 2020-01-08T13:07:36.719Z] 13:07:36 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f10b592c800 == 7 [pid = 1126] [id = {a420e06e-5e14-4945-9e1f-49bded9e2356}] [url = about:blank]
[task 2020-01-08T13:07:37.176Z] 13:07:37 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file /builds/worker/workspace/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2020-01-08T13:07:37.218Z] 13:07:37 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file /builds/worker/workspace/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2020-01-08T13:07:37.523Z] 13:07:37 INFO - GECKO(1126) | [Child 1202: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7fd03a375000) [pid = 1202] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2020-01-08T13:07:37.524Z] 13:07:37 INFO - GECKO(1126) | [Child 1202: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7fd039bb7400) [pid = 1202] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2020-01-08T13:07:37.826Z] 13:07:37 INFO - GECKO(1126) | [Child 1181: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (0x7f563fa15800) [pid = 1181] [serial = 15] [outer = (nil)] [url = moz-extension://980c3a99-f8f7-440d-a523-eff7604f2f3f/_generated_background_page.html]
[task 2020-01-08T13:07:37.946Z] 13:07:37 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: we only accept nsIURI interface type, patch welcome: file /builds/worker/workspace/build/src/dom/ipc/PropertyBagUtils.cpp, line 112
[task 2020-01-08T13:07:37.954Z] 13:07:37 INFO - GECKO(1126) | [Child 1291, Main Thread] WARNING: Trying to request nsIHttpChannel from DocumentChannelChild, this is likely broken: file /builds/worker/workspace/build/src/netwerk/ipc/DocumentChannelChild.cpp, line 64
[task 2020-01-08T13:07:37.958Z] 13:07:37 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 8 (0x7fd38f5dc400) [pid = 1291] [serial = 8] [outer = 0x7fd38f4af2e0]
[task 2020-01-08T13:07:38.007Z] 13:07:38 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 7 (0x7fd38e06e400) [pid = 1291] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-01-08T13:07:38.009Z] 13:07:38 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 6 (0x7fd38e076800) [pid = 1291] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2020-01-08T13:07:38.009Z] 13:07:38 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fd38e5ce000 == 1 [pid = 1291] [id = {961e2cf3-d789-496f-9432-089288c889aa}] [url = http://example.com/browser/remote/test/browser/network/doc_empty.html]
[task 2020-01-08T13:07:38.096Z] 13:07:38 INFO - TEST-INFO | started process screentopng
[task 2020-01-08T13:07:38.542Z] 13:07:38 INFO - TEST-INFO | screentopng: exit 0
[task 2020-01-08T13:07:38.542Z] 13:07:38 INFO - Buffered messages logged at 13:07:36
[task 2020-01-08T13:07:38.542Z] 13:07:38 INFO - Entering test bound cacheEnabledAfterDisabled
[task 2020-01-08T13:07:38.542Z] 13:07:38 INFO - CDP server started
[task 2020-01-08T13:07:38.542Z] 13:07:38 INFO - Buffered messages logged at 13:07:37
[task 2020-01-08T13:07:38.543Z] 13:07:38 INFO - CDP client instantiated
[task 2020-01-08T13:07:38.544Z] 13:07:38 INFO - Buffered messages logged at 13:07:38
[task 2020-01-08T13:07:38.545Z] 13:07:38 INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/remote/test/browser/network/doc_empty.html" line: 0}]
[task 2020-01-08T13:07:38.545Z] 13:07:38 INFO - CDP client closed
[task 2020-01-08T13:07:38.546Z] 13:07:38 INFO - CDP server stopped
[task 2020-01-08T13:07:38.547Z] 13:07:38 INFO - Buffered messages finished
[task 2020-01-08T13:07:38.547Z] 13:07:38 INFO - TEST-UNEXPECTED-FAIL | remote/test/browser/network/browser_setCacheDisabled.js | Uncaught exception - [Exception... "(null)" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "<unknown>" data: no]
[task 2020-01-08T13:07:38.548Z] 13:07:38 INFO - Leaving test bound cacheEnabledAfterDisabled
[task 2020-01-08T13:07:38.549Z] 13:07:38 INFO - Entering test bound cacheEnabledByDefault
[task 2020-01-08T13:07:38.550Z] 13:07:38 INFO - CDP server started
[task 2020-01-08T13:07:38.550Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f10b5935000 == 8 [pid = 1126] [id = {d3ace48d-8f85-4ae3-87ce-7f304741c91c}]
[task 2020-01-08T13:07:38.550Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 32 (0x7f10b82fb2e0) [pid = 1126] [serial = 34] [outer = (nil)]
[task 2020-01-08T13:07:38.551Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 33 (0x7f10b7da0400) [pid = 1126] [serial = 35] [outer = 0x7f10b82fb2e0]
[task 2020-01-08T13:07:38.552Z] 13:07:38 INFO - GECKO(1126) | [Child 1291: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 5 (0x7fd38f4aef20) [pid = 1291] [serial = 1] [outer = (nil)] [url = http://example.com/browser/remote/test/browser/network/doc_empty.html]
[task 2020-01-08T13:07:38.552Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 34 (0x7f10b8210000) [pid = 1126] [serial = 36] [outer = 0x7f10b82fb2e0]
[task 2020-01-08T13:07:38.552Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 45
[task 2020-01-08T13:07:38.552Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 57
[task 2020-01-08T13:07:38.552Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 45
[task 2020-01-08T13:07:38.553Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 57
[task 2020-01-08T13:07:38.554Z] 13:07:38 INFO - GECKO(1126) | [Child 1319: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f1e475b1000 == 2 [pid = 1319] [id = {b21cc200-819a-40a0-961b-6028ade15d64}]
[task 2020-01-08T13:07:38.554Z] 13:07:38 INFO - GECKO(1126) | [Child 1319: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (0x7f1e489b02e0) [pid = 1319] [serial = 5] [outer = (nil)]
[task 2020-01-08T13:07:38.555Z] 13:07:38 INFO - GECKO(1126) | [Child 1319, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/workspace/build/src/layout/base/nsPresContext.cpp, line 848
[task 2020-01-08T13:07:38.556Z] 13:07:38 INFO - GECKO(1126) | [Child 1319: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 6 (0x7f1e47571400) [pid = 1319] [serial = 6] [outer = 0x7f1e489b02e0]
[task 2020-01-08T13:07:38.557Z] 13:07:38 INFO - GECKO(1126) | [Child 1319: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 7 (0x7f1e47a73400) [pid = 1319] [serial = 7] [outer = 0x7f1e489b02e0]
[task 2020-01-08T13:07:38.606Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file /builds/worker/workspace/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2020-01-08T13:07:38.642Z] 13:07:38 INFO - GECKO(1126) | [Parent 1126, Main Thread] WARNING: NS_ENSURE_TRUE(aURI) failed: file /builds/worker/workspace/build/src/netwerk/dns/nsEffectiveTLDService.cpp, line 176
[task 2020-01-08T13:07:39.186Z] 13:07:39 INFO - CDP client instantiated

I wish we would have the nserror stack here. Maybe bug 1591161 will help with that in the future.

Flags: needinfo?(hskupin)
Regressed by: 1607461
Summary: Intermittent TV remote/test/browser/network/browser_setCacheDisabled.js | Uncaught exception - [Exception... "(null)" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "<unknown>" data: no] → Intermittent remote/test/browser/network/browser_setCacheDisabled.js | Uncaught exception - [Exception... "(null)" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "<unknown>" data: no]

(In reply to Andreas Tolfsen ❲:ato❳ from comment #1)

I wish we would have the nserror stack here. Maybe bug 1591161 will help with that in the future.

No it won't. That is all what we get for this error. I have seen that already while implementing the test but thought I got it removed. I never was able to see it on my machine. Checking the intermittent failures I can see why... it happens very rarely on MacOS but mostly on Linux and Windows. So I will have to use my older Linux machine to reproduce it.

The underlying problem here is somewhat related to content code this test runs. My speculation is that the test continues even with the await keyword added for checkPromise. And SpecialPowers.spawn or the progress listener, which is still active, somewhat get in trouble returning the Promise. Due to the terrible error details it's far away from being easy to understand. So lets see if I can find out something today.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Flags: needinfo?(hskupin)
Priority: P5 → P1

Something here is really bogus with SpecialPowers.spawn(). Maybe it is related to the internal async behavior:

/* Any copyright is dedicated to the Public Domain.
 * http://creativecommons.org/publicdomain/zero/1.0/ */

"use strict";
  
const TEST_PAGE = "data:text/html,<div>test</div>";

add_plain_task(async function() {
  const finished = SpecialPowers.spawn(
    gBrowser.selectedBrowser,
    [],
    async () => {
      await new Promise(resolve => content.setTimeout(resolve, 4000));
    }
  );

  const browser = gBrowser.selectedTab.linkedBrowser;
  const loaded = BrowserTestUtils.browserLoaded(browser, false, TEST_PAGE);
  BrowserTestUtils.loadURI(browser, TEST_PAGE);
  await loaded;

  await finished;
  ok(true);
});

With this code snippet for a browser chrome test I can always produce this failure. Note that there is nothing related to the remote agent at all.

Kris, any idea what this could be?

Flags: needinfo?(kmaglione+bmo)

The problem is that SpecialPowers.spawn tasks are limited to the lifetime of an inner window, but the test navigates the window the task was spawned in between the time it's launched and the time it completes.

Flags: needinfo?(kmaglione+bmo)

Hm, so I have to setup a webprogress listener on the docshell to observe the load flags:
https://searchfox.org/mozilla-central/source/remote/test/browser/network/browser_setCacheDisabled.js

To catch all of those I have to register it before I load the page. Is there another way in doing that? Do you know? I tried to have the listener in the parent process but I was not able to get it working. Thanks!

Flags: needinfo?(kmaglione+bmo)

What I wonder is that this is basically an intermittent failure and not happening that often. Given your explanation I would assume that it is always failing. Maybe it's just that spawning the task via SpecialPowers takes a bit of time, and due to the async nature of checkLoadFlags we already started the page load so that the task is run on the new inner window?

Olli, maybe you can also help out here? Maybe you could have a look at comment 7? Thanks.

Flags: needinfo?(bugs)

I don't really know. There sure must be some API to load scripts in child process in a way which isn't bound to the inner windows.
But looks like the APIs have changed recently.

Flags: needinfo?(bugs)

The problematic API here is actually SpecialPowers.spawn(). Most of the tests have been converted to use that API instead of ContentTask.spawn(). But not all can be converted right now due to:

(In reply to Kris Maglione [:kmag] from bug 1596918 comment #0)

That said, there are still cases where have ContentTask.spawn calls which can't be converted to SpecialPowers.spawn. The main difference at this point is the lifetime of the task, where ContentTask.spawn is bound to the lifetime of a frameloader, and may persist across same-process navigations, and SpecialPowers.spawn is bound to the lifetime of a window global, and may not. In general, those kinds of tasks should be considered deprecated, and should be rewritten in such a way as to be agnostic to whether a navigation maintains the same docShell/process as the previous document. But that is a nontrivial amount of work.

So to fix this intermittent I will revert back to ContentTask.spawn() for now and figuring out how to convert it to SpecialPowers.spawn() at a later time.

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 74
Regressions: 1610382
See Also: → 1610382
See Also: 1610382
Flags: needinfo?(kmaglione+bmo)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: