1595197 - webRequest.StreamFilter.onstop is being called twice

Status: RESOLVED FIXED

(WebExtensions :: Request Handling, defect, P1)

Description

[particlecore]

Attachment: test.zip

User Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:72.0) Gecko/20100101 Firefox/72.0

Steps to reproduce:

Bug discovered in Nightly 72.0a1 (2019-11-08) (64-bit)

Load attached demo extension

Click "Inspect" and switch to the console

Open www.youtube.com

Actual results:

The console outputs two messages confirming the .onStop function is now being called twice:

19:59:45.916
This message should only show once in the console 0.27884815437952426 background.js:21:21
19:59:45.982
This message should only show once in the console 0.2947613163421413

Expected results:

The console should only output once, the onstop function should only be called once.

This appears to be related to a fix for this (these) issue(s)

1587960
1590898

Comment 1

[kernp25]

onstart also fires 2 times.

Comment 2

[kernp25]

This is what the console gives:
onstart 2 times
ondata 120 times
onstop
ondata
onstop

Comment 3

[particlecore]

(In reply to kernp25 from comment #2)

This is what the console gives:
onstart 2 times
ondata 120 times
onstop
ondata
onstop

ondata looks normal at a glance because it is called repeatedly until there is no more data, however I can't tell if it is being called more times than it should without comparing the behavior with ondata before this problem surfaced.

Comment 4

[kernp25]

Can you confirme this bug?

Comment 5

[Seba S.]

Hi, particlecore,

Thanks for your contribution!

I'm adding product and component on this, I think you are right and it could be related to the fixes for 1587960 / 1590898.

Regards,

Comment 6

[Perry Jiang [:perry] [no longer employee, use ni?]]

I think the problem may be that we're calling WebRequest callbacks for internal redirects (on top of the initial request), leading to these duplicate calls. Internal redirects shouldn't be observable by web pages (they're "internal" by nature).

Comment 7

[Alex Cornestean]

Hello,

I have managed to reproduce the issue based on the provided STR only on the latest Nightly (72.0a1/20191114055112) under Windows 10 Pro 64-bit and MacOS Catalina 10.15.

The latest Beta (71.0b9/20191111170815) and Release (70.0.1/20191030021342) are unaffected by this.

The .onStop function is indeed being called twice and the console outputs 2 messages to confirm that.

Comment 8

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

Bugbug thinks this bug is a regression, but please revert this change in case of error.

Comment 9

[Perry Jiang [:perry] [no longer employee, use ni?]]

Attachment: Bug 1595197 - fix StreamFilter redirect handling

Each subtest (i.e. each call to call{XHR,Fetch}) will ensure that
StreamListener.on{start,stop} is called once and only once. If either are called
more than once before the next subtest, the overall test will fail.

Comment 10

[particlecore]

(In reply to Perry Jiang [:perry] from comment #6)

I think the problem may be that we're calling WebRequest callbacks for internal redirects (on top of the initial request), leading to these duplicate calls. Internal redirects shouldn't be observable by web pages (they're "internal" by nature).

Seems to be something to do with cache. If I open the page fresh (meaning no cache in browser) the issue does not occur. Once I open it again and every next time it finds in cache the issue occurs.

I did this:

• Open the page for the first time (no cache in browser) issue does not occur
• Open the same page after the first time (cache is turned on in the browser by the way) issue occurs all the time
• Press Ctrl + Shift + R on the same page (to force full reload) issue does not occur

This might also be linked with the issue of Firefox leaking cached content/resources directly to the filter as it was reported before, I found these in the following search results for an issue I also faced and ultimately I had to do the same thing the users did (remove the initial content):

• https://bugzilla.mozilla.org/show_bug.cgi?id=1530408
• https://discourse.mozilla.org/t/31417
• https://stackoverflow.com/questions/52128329

Comment 11

[Andrew Sutherland [:asuth] (he/him)]

(In reply to particlecore from comment #10)

I did this:

• Open the page for the first time (no cache in browser) issue does not occur

No cache presumably means all site data cleared which means no ServiceWorkers are present. On first load, a ServiceWorker won't be present for initial navigation. (Although it can start controlling the page via https://developer.mozilla.org/en-US/docs/Web/API/Clients/claim.)

• Open the same page after the first time (cache is turned on in the browser by the way) issue occurs all the time

The ServiceWorker should be present at this time.

• Press Ctrl + Shift + R on the same page (to force full reload) issue does not occur

This bypasses ServiceWorkers as well as the cache.

Comment 12

[Jim Mathies [:jimm]]

Do we need kmag's signoff here? He's busy with fission.

Comment 13

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

The priority flag is not set for this bug.
:jimm, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 14

[Shane Caraveo (:mixedpuppy)]

Perry, what is the status of the work on this?

Comment 15

[Perry Jiang [:perry] [no longer employee, use ni?]]

Sorry, got caught up on some other stuff and was OOO for a few days. I'm working on this right now.

Comment 16

[Liz Henry (:lizzard) (relman/hg->git project)]

This will likely miss 73 but we could still take a patch in 74 next week.

Comment 17

[particlecore]

Still not fixed in 74

Comment 18

[particlecore]

As a result of this bug I've had to implement a workaround because all users of my extension could no longer load YouTube pages since this duplicate event dispatch bug was resulting in out of memory errors.
Details in https://github.com/ParticleCore/Iridium/issues/825

Comment 22

[Mathew Hodson]

A bisect was done in one of the duplicates, so we should mark Regressed by bug 1590898.

(In reply to Rob Wu [:robwu] from comment #1)

I bisected. This was regressed by bug 1590898 (https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=ff0b109afd62c3c2dd396463bb3632228e959ff3&tochange=a4c51f3f0bb1dd51ded827d3049d633f56662a7f)

Comment 23

[Shane Caraveo (:mixedpuppy)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d8967e31aadfcaf824aa78b0e1a63302041721b1

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fca6b4827fc6
fix StreamFilter redirect handling r=zombie,robwu

Comment 25

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/mozilla-central/rev/fca6b4827fc6