1683189 - StreamFilter not disconnected after redirect of document requests

Status: RESOLVED FIXED

(WebExtensions :: Request Handling, defect, P2)

Description

[Rob Wu [:robwu]]

Attachment: webRequest-filterResponseData-redirected-document.zip

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:

• The following logs should be seen at step 4 (and also at step 6):
• http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme onBeforeRequest
• http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme onBeforeRedirect
• http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme filter.onerror fired: Channel redirected

Actual:

• The following logs are seen at step 4:
• http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme onBeforeRequest
• http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme onBeforeRedirect
• (... wait for a long while ..., or click on "Minimize memory usage" at about:memory)
• http://httpbingo.org/redirect-to?url=http%3A%2F%2Fexample.com%2F&filterme filter.onerror fired: Invalid request ID

Comment 1

[Rob Wu [:robwu]]

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]

Comment 2

[Rob Wu [:robwu]]

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.

Comment 3

[Rob Wu [:robwu]]

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();
+});

Comment 4

[Rob Wu [:robwu]]

Attachment: Bug 1683189 - Release pending StreamFilter requests

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.

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0e66f49f121d
Release pending StreamFilter requests r=mattwoodrow,mixedpuppy,necko-reviewers,dragana

Comment 6

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/0e66f49f121d

Comment 7

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

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.

Comment 8

[Rob Wu [:robwu]]

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