Closed Bug 1683189 Opened 6 months ago Closed 6 months ago

StreamFilter not disconnected after redirect of document requests

Categories

(WebExtensions :: Request Handling, defect, P2)

defect

Tracking

(firefox-esr78 unaffected, firefox83 wontfix, firefox84 wontfix, firefox85 wontfix, firefox86 fixed)

RESOLVED FIXED
86 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox83 --- wontfix
firefox84 --- wontfix
firefox85 --- wontfix
firefox86 --- fixed

People

(Reporter: robwu, Assigned: robwu)

References

(Regression)

Details

(Keywords: regression)

Attachments

(2 files)

I was writing a unit test that checks the behavior of webRequest with a view-source:-URL that was redirected elsewhere, and unexpectedly the test stalled for a while and then filter.onerror got triggered with the error "Invalid request ID" (while I expected "Channel redirected"). Turns out that this isn't specific to view-source:, this happens to any document (main_frame / sub_frame type).

STR:

  1. Load the attached zip file at about:debugging
  2. Inspect the background page.
  3. Click on the extension button, which opens a URL that redirects to example.com.
  4. Look at the console from step 2.
  5. Open the devtools in the tab from step 3, and run: new Image().src = "http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme"
  6. Look at the console from step 2 to see the expected behavior.

Expected:

Actual:

I suspect that this is caused by an incorrect handling of StreamFilters after attaching a DocumentLoadListener in nsHttpChannel::AttachStreamFilter at https://searchfox.org/mozilla-central/rev/8d722de75886d6bffc116772a1db8854e34ee6a7/netwerk/protocol/http/nsHttpChannel.cpp#6945-6955

It is supposedly resolved in nsHttpChannel::CallOnStartRequest at https://searchfox.org/mozilla-central/rev/8d722de75886d6bffc116772a1db8854e34ee6a7/netwerk/protocol/http/nsHttpChannel.cpp#1665-1689

A call to CallOnStartRequest should result in "nsHttpChannel::CallOnStartRequest [this=%p] being logged.

But I am not seeing that. Instead, I see these relevant log lines (copied from a test run of a xpcshell test (in-process extensions) with MOZ_LOG=timestamp,nsHttp:5 MOZ_LOG_FILE=/tmp/log.txt, manually edited to only show the lines related to the request near the point where I would expect CallOnStartRequest):

V/nsHttp sending progress and status notification [this=0x7feba2104000 status=804b000a progress=0/0]
I/nsHttp http response [
E/nsHttp   HTTP/1.1 303 See Other
E/nsHttp   location: http://127.0.0.1:43649/dummy
E/nsHttp   connection: close
E/nsHttp   server: httpd.js
E/nsHttp   date: Thu, 17 Dec 2020 17:22:58 GMT
E/nsHttp   content-length: 0
E/nsHttp     OriginalHeaders
E/nsHttp   location: http://127.0.0.1:43649/dummy
E/nsHttp   connection: close
E/nsHttp   server: httpd.js
E/nsHttp   date: Thu, 17 Dec 2020 17:22:58 GMT
E/nsHttp   content-length: 0
I/nsHttp ]

V/nsHttp nsHttpChannel::OnStartRequest [this=0x7feba2104000 request=0x7feba21d92e0 status=0]
V/nsHttp nsHttpChannel::ProcessResponse [this=0x7feba2104000 httpStatus=303]
V/nsHttp nsHttpChannel::ContinueProcessResponse3 [this=0x7feba2104000, rv=804b0001]
V/nsHttp nsHttpChannel::AsyncProcessRedirection [this=0x7feba2104000 type=303]
V/nsHttp redirecting to: http://127.0.0.1:43649/dummy [redirection-limit=20]
D/nsHttp nsHttpHandler::NewProxiedChannel [proxyInfo=(nil)]
V/nsHttp Creating HttpBaseChannel @0x7feb9c212000
V/nsHttp Creating nsHttpChannel [this=0x7feb9c212000]
E/nsHttp HttpBaseChannel::Init [this=0x7feb9c212000]
E/nsHttp host=127.0.0.1 port=43649
E/nsHttp uri=http://127.0.0.1:43649/dummy
E/nsHttp nsHttpChannel::Init [this=0x7feb9c212000]
V/nsHttp nsHttpChannel::SetupReplacementChannel [this=0x7feba2104000 newChannel=0x7feb9c212050 preserveMethod=0]
V/nsHttp HttpBaseChannel::SetupReplacementChannel [this=0x7feba2104000 newChannel=0x7feb9c212050 preserveMethod=0]
V/nsHttp nsHttpChannel::OnClassOfServiceUpdated this=0x7feb9c212000, cos=64
V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x7feb9c212000 header="Accept" value="text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8" merge=0]
V/nsHttp HttpBaseChannel::SetRequestHeader [this=0x7feb9c212000 header="User-Agent" value="Mozilla/5.0 (X11; Linux x86_64; rv:86.0) Gecko/20100101 /86.0a1" merge=0]
V/nsHttp nsHttpChannel::SetPriority 0x7feb9c212000 p=-20
V/nsHttp HttpBaseChannel::SetApplyConversion [this=0x7feb9c212000 value=1]
V/nsHttp nsHttpChannel::GetNavigationStartTimeStamp [this=0x7feba2104000]
V/nsHttp nsHttpChannel::WaitForRedirectCallback [this=0x7feba2104000]
V/nsHttp nsHttpChannel::OnRedirectVerifyCallback [this=0x7feba2104000] result=0 stack=2 WaitingForRedirectCallback=1
V/nsHttp nsHttpChannel::ContinueProcessRedirection [rv=0,this=0x7feba2104000]

mozregression with STR points to bug 1638422.

Before the regression, filter.onstart was triggered (instead of filter.onerror with filter.error = "Channel redirected"). We intentionally decided to close the StreamFilter, but then filter.onerror had to be triggered, which doesn't happen for document requests.

I have already written unit tests for view-source: in bug 1678734.
The redirect test is included but commented out from the patch.
I also wrote a test that tested cancelation of requests. The test has the expected result, but the test completion is delayed, likely due to this bug.

Here is the test case for cancellation:

diff --git a/toolkit/components/extensions/test/xpcshell/test_ext_webRequest_viewsource_StreamFilter.js b/toolkit/components/extensions/test/xpcshell/test_ext_webRequest_viewsource_StreamFilter.js
index 2562d9d28786..903211d7096a 100644
--- a/toolkit/components/extensions/test/xpcshell/test_ext_webRequest_viewsource_StreamFilter.js
+++ b/toolkit/components/extensions/test/xpcshell/test_ext_webRequest_viewsource_StreamFilter.js
@@ -94,3 +94,49 @@ add_task(async function test_StreamFilter_viewsource() {
 // add_task(async function test_StreamFilter_viewsource_redirect_target() {
 //   await testViewSource(`view-source:${BASE_URL}/redir`);
 // });
+
+// Sanity check: nothing bad happens if the underlying response is aborted.
+add_task(async function test_StreamFilter_viewsource_cancel() {
+  let extension = ExtensionTestUtils.loadExtension({
+    manifest: {
+      permissions: ["webRequest", "webRequestBlocking", "*://*/*"],
+    },
+    background() {
+      browser.webRequest.onBeforeRequest.addListener(
+        details => {
+          let filter = browser.webRequest.filterResponseData(details.requestId);
+          filter.onstart = () => {
+            filter.disconnect();
+            browser.test.fail("Unexpected filter.onstart");
+            browser.test.sendMessage("filter_end");
+          };
+          filter.onerror = function() {
+            browser.test.assertEq("Invalid request ID", filter.error, "Error?");
+            browser.test.sendMessage("filter_end");
+          };
+        },
+        { urls: ["*://*/dummy"] },
+        ["blocking"]
+      );
+      browser.webRequest.onHeadersReceived.addListener(
+        () => {
+          browser.test.log("Intentionally canceling view-source request");
+          return { cancel: true };
+        },
+        { urls: ["*://*/dummy"] },
+        ["blocking"]
+      );
+    },
+  });
+  await extension.startup();
+  let contentPage = await ExtensionTestUtils.loadContentPage(
+    `${BASE_URL}/dummy`
+  );
+  await extension.awaitMessage("filter_end");
+  let contentText = await contentPage.spawn(null, () => {
+    return this.content.document.body.textContent;
+  });
+  equal(contentText, "", "view-source request should have been canceled");
+  await contentPage.close();
+  await extension.unload();
+});
See Also: → 1678734

mStreamFilterRequests is current rejected/resolved from
nsHttpChannel::CallOnStartRequest. But that point may never be reached
for various reasons, including (internal) redirects and cancellations.
Ensure that they are cleaned up via nsHttpChannel::ReleaseListeners.

Tests in test_ext_webRequest_viewsource_StreamFilter.js was already
passing before, but they were non-deterministic due to the reliance on
garbage collection of the HTTP channel. Now it completes soon.

The new test file, test_ext_webRequest_redirect_StreamFilter.js is a
regression test that actually confirms that the filter is closed as soon
as reasonably possible.

Assignee: nobody → rob
Status: NEW → ASSIGNED
Severity: -- → S3
Priority: -- → P2
See Also: → 1683862
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/0e66f49f121d
Release pending StreamFilter requests r=mattwoodrow,mixedpuppy,necko-reviewers,dragana
Status: ASSIGNED → RESOLVED
Closed: 6 months ago
Resolution: --- → FIXED
Target Milestone: --- → 86 Branch

The patch landed in nightly and beta is affected.
:robwu, 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.

Flags: needinfo?(rob)

Regression has been there for a few releases, not important enough to uplift. May be worth trying to fix together with bug 1683862.

You need to log in before you can comment on or make changes to this bug.