1595610 - webRequest.onHeadersReceived not fired for cached response after script-initiated navigation

Status: REOPENED

(WebExtensions :: Request Handling, defect)

Description

[kernp25]

Attachment: manifest.zip

1. Install test add-on
2. Open Solicitud_beca_Toyota_2019_2020.doc

Actual results:
webRequest is not firing for https://view.officeapps.live.com/op/errorpage.htm?llcc=en-US

Expected results:
webRequest should fire for https://view.officeapps.live.com/op/errorpage.htm?llcc=en-US (so i can use webRequest.filterResponseData)

In Google Chrome it works as expected:
frameId: 0
initiator: "https://view.officeapps.live.com"
method: "GET"
parentFrameId: -1
requestId: "1289"
statusCode: 200
statusLine: "HTTP/1.1 200"
tabId: 23
timeStamp: 1573504743027.031
type: "main_frame"
url: "https://view.officeapps.live.com/op/errorpage.htm?llcc=en-US"

Comment 1

[kernp25]

My nightly version:
72.0a1 (2019-11-11) (64-Bit)

Comment 2

[Miruna Curtean]

Attachment: Firefox versus Chrome console log.PNG

After performing the steps to reproduce provided in both Firefox and Chrome it look like the results are quite similar.
Could you please provide more details or a recording of the expected result?

Comment 3

[kernp25]

Really stange, because now it seems to work (it was not working before).
Tested on 72.0a1 (2019-11-18) (64-Bit).

Comment 4

[kernp25]

Attachment: firefox_XuWlxcsRet.png

Comment 5

[kernp25]

Maybe there was a bug in Nightly?

Comment 6

[Miruna Curtean]

Attachment: Console log results 2019-11-11 builds

I've tested on the Nightly builds that were released on 2019-11-11 (Build ID:20191111215252 and Build ID:20191119043902).
When I input the example link into the browser two requests are fired (see attached) but unless there's an issue with that, I am going to set this bug as Invalid.
If it can be reproduced again then it can be reopened.

Comment 7

[Rob Wu [:robwu]]

Not reproducible. Please provide more details if possible.

Note that if you use location to navigate, and the only change is the reference fragment, then it is possible for the page to not (re)load anew.

And when you try to reproduce, make sure that the location assignment only happens after the webRequest listener has been added.

Comment 8

[kernp25]

Attachment: DFe4oiFFpX.mp4

Comment 9

[kernp25]

Thus bug still exists. Can you look at the video?

Comment 10

[kernp25]

Only at the end of the video you will see that it fires for https://view.officeapps.live.com/op/errorpage.htm?llcc=de-DE

Comment 11

[kernp25]

Attachment: firefox_j6WSyMRNfY.png

Comment 12

[Rob Wu [:robwu]]

I can see the video, but cannot reproduce locally.

Which version of Firefox are you using?

In your video there are lots of add-ons. Does the issue only happen with a certain combination of add-ons?

Can you reproduce the problem when the devtools of the tab is open, and if yes, can you export the contents of the network tab as HAR?

Comment 13

[kernp25]

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

Which version of Firefox are you using?

74.0.1 (64-Bit)

In your video there are lots of add-ons. Does the issue only happen with a certain combination of add-ons?

I don't think so. I will test it again without add-ons.

Can you reproduce the problem when the devtools of the tab is open, and if yes, can you export the contents of the network tab as HAR?

I will try.

Comment 14

[kernp25]

Attachment: manifest.zip

New improved test add-on.

Comment 15

[kernp25]

I did again some testing: If you disable the cache (e.g. Disable cache option in devtools), then the issue does not seem to occur anymore.

Comment 16

[kernp25]

Can you test again using the new test add-on?

Comment 17

[kernp25]

Attachment: view.officeapps.live.com_Archive [20-04-08 00-04-00].har

Note: webRequest.onHeadersReceived was not called

Comment 18

[kernp25]

Attachment: view.officeapps.live.com_Archive [20-04-08 00-08-20].har

Note: webRequest.onHeadersReceived was called

Comment 19

[Rob Wu [:robwu]]

(In reply to kernp25 from comment #14)

Created attachment 9138989 [details]
manifest.zip

New improved test add-on.

This is basically the same as the original add-on, except it uses the webRequest.filterResponseData / StreamFilter API to modify the response upon onHeadersReceived instead of console.log. This is not relevant (because the bug is about onHeadersReceived not firing at all), so unless a good reason is given, I would use the reproduction steps from the first comment.

(In reply to kernp25 from comment #15)

I did again some testing: If you disable the cache (e.g. Disable cache option in devtools), then the issue does not seem to occur anymore.

Thanks for this bit of information. While I am still unable to reproduce, you clearly can, so I'll reopen the bug. There is at least one other cache-related bug report (bug 1543018, again not easily reproducible..), so perhaps your report may help there as well.

Comment 20

[kernp25]

In view.officeapps.live.com_Archive [20-04-08 00-04-00].har:
"status": 0, "statusText": "", "httpVersion": "", "headers": [], "cookies": [],

And in view.officeapps.live.com_Archive [20-04-08 00-08-20].har:
"status": 200, "statusText": "OK", "httpVersion": "HTTP/2.0",

Comment 21

[kernp25]

Maybe this is the reason why onHeadersReceived is not called?
Because of response status 0?

Comment 22

[Rob Wu [:robwu]]

I think that status 0 is just one of the symptoms. In the good case, almost every field except for content is populated. In the broken case, it is not:

Bad ( [20-04-08 00-04-00].har ):

        "response": {
          "status": 0,
          "statusText": "",
          "httpVersion": "",
          "headers": [], 
          "cookies": [], 
          "content": {
            "mimeType": "text/html",
            "size": 6275,
            "text": "<!DOCTYPE html ...(cut)..."
          },
          "redirectURL": "",
          "bodySize": 2202
        },

Good ( [20-04-08 00-08-20].har ):

        "response": {
          "status": 200,
          "statusText": "OK",
          "httpVersion": "HTTP/2.0",
          "headers": [
            { 
              "name": "cache-control",
              "value": "public,max-age=31536000"
            },
            { 
              "name": "content-length",
              "value": "2202"
            },
            ..... cut ....
          ],
          "cookies": [
            {
              "name": "",
              "value": ""
            }
          ],
          "content": {
            "mimeType": "text/html",
            "size": 6275,
            "text": "<!DOCTYPE html ...(cut)..."
          },
          "redirectURL": "",
          "headersSize": 0,
          "bodySize": 2202
        },
        "cache": {},
        "timings": {
          "blocked": 0,
          "dns": 0,
          "ssl": 0,
          "connect": 0,
          "send": 0,
          "wait": 0,
          "receive": 0
        },
        "time": 0,
        "_securityState": "secure"
      },

Comment 23

[kernp25]

Attachment: bf3BGHX5QL.png

Output of the devtools tab from the failed request.

Comment 24

[kernp25]

Again: The issue does not seem to occur, if you disable the cache.
So it must have something to do with the cache?

Comment 25

[kernp25]

Attachment: gc7lWXphN9.png

This is the output from the devtools network tab after i reloaded the tab.

Comment 26

[kernp25]

After i reloaded the tab, it has the status 304.

Comment 27

[Shane Caraveo (:mixedpuppy)]

You might consider testing on top of D53187, or waiting for those patches to land then test.

Comment 28

[kernp25]

And onHeadersReceived was called after i reloaded the tab.

Comment 29

[kernp25]

Can you link the bug?

Comment 30

[kernp25]

Attachment: kdR4bJ7m7Z.png

This is the output from the devtools tab after webRequest.onHeadersReceived was called

Comment 31

[kernp25]

But it seems that it works also for cached requests (look at picture).

Comment 32

[kernp25]

It seems that if the response status is 0, then webRequest.onHeadersReceived is not called.

Comment 33

[kernp25]

When i use webRequest.onBeforeRequest then it always works.
But webRequest.onHeadersReceived does not fire for response status 0.

Comment 34

[kernp25]

So, this is the bug because of the response status 0?

Comment 35

[kernp25]

When i use webRequest.onErrorOccurred then it shows this error: NS_ERROR_NET_ON_WAITING_FOR

Comment 36

[kernp25]

Attachment: firefox_2SfCYLQWEi.png

webRequest.onErrorOccurred output

Comment 37

[kernp25]

This is the real error.

Comment 38

[kernp25]

Why it fires the error NS_ERROR_NET_ON_WAITING_FOR?
Is this a bug in Firefox then?

Comment 39

[kernp25]

Attachment: manifest.zip

Test add-on to show the NS_ERROR_NET_ON_WAITING_FOR bug.

Comment 40

[kernp25]

Can you confirm the NS_ERROR_NET_ON_WAITING_FOR error?

Comment 41

[kernp25]

Attachment: manifest(4).zip

Improved test add-on.

Comment 42

[kernp25]

(In reply to Shane Caraveo (:mixedpuppy) from comment #27)

You might consider testing on top of D53187, or waiting for those patches to land then test.

I don't think it has something to do with https://phabricator.services.mozilla.com/D53187

Comment 43

[Rob Wu [:robwu]]

(In reply to Shane Caraveo (:mixedpuppy) from comment #27)

You might consider testing on top of D53187, or waiting for those patches to land then test.

https://phabricator.services.mozilla.com/D53187 seems to be about StreamFilters, whereas this bug is independent of that (see comment 19).

(In reply to kernp25 from comment #35)

When i use webRequest.onErrorOccurred then it shows this error: NS_ERROR_NET_ON_WAITING_FOR

Interesting. This is already a good start at narrowing the causes, since there are very few sources of this status.
Could you create a network log (https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging) and share the results of a good case and a bad case, with as little noise as possible? (preferably start with a blank profile with no add-ons besides yours).

(In reply to kernp25 from comment #40)

Can you confirm the NS_ERROR_NET_ON_WAITING_FOR error?

I cannot, and I doubt whether verification by QA makes any difference here, so I'll remove the flag.
Since you are quite responsive here, I think that your input can be more useful during the investigation.

Comment 44

[kernp25]

Attachment: view.officeapps.live.com_Archive [20-04-08 20-24-41].har

This log is from 77.0a1 (2020-04-08) (64-Bit)

Comment 45

[kernp25]

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

I cannot, and I doubt whether verification by QA makes any difference here, so I'll remove the flag.
Since you are quite responsive here, I think that your input can be more useful during the investigation.

Can you test again but this time install https://addons.mozilla.org/firefox/addon/ublock-origin/

Comment 46

[kernp25]

Attachment: GKLTq3rdS0.mp4

Bug that happens without uBlock Origin installed.
webRequest.onErrorOccurred is also not called.

Comment 47

[kernp25]

Can you also reproduce the above bug?
Without uBlock Origin?

Comment 48

[kernp25]

With the above bug webRequest.onBeforeRequest is also not called.

Comment 49

[kernp25]

It seems that if you have fission.autostart set to true in about:config then this bug seems to occur.
If fission.autostart is false then the bug does not occur.

Can you confirm?

Comment 50

[Rob Wu [:robwu]]

I tried with the latest extension from comment 41, with and without uBlock Origin, with and without fission.autostart=true on Nightly 76.0a1 buildID 20200325093457 on Linux, and cannot reproduce this problem.

In comment 44 you provided another HAR even though I requested the log from about:networking. Could you visit about:networking, go to the Logging tab and follow the instructions to create a log file? This log is much more detailed than the HAR, because it records internal implementation details as well. See https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging

PS. Could you try to put your comments in one comment before posting a new comment? Every comment generates a bunch of e-mails to people who are (in)directly subscribed to this bug. Thanks for your help!

Comment 51

[kernp25]

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

I tried with the latest extension from comment 41, with and without uBlock Origin, with and without fission.autostart=true on Nightly 76.0a1 buildID 20200325093457 on Linux, and cannot reproduce this problem.

Maybe the bug does not happen on linux? I have tested it on Windows 10.

Comment 52

[gwarser]

Ublock Origin is overriding Cache-Control (https://github.com/gorhill/uBlock/wiki/Advanced-settings#cachecontrolforfirefox1376932) because of https://bugzilla.mozilla.org/show_bug.cgi?id=1376932

Comment 53

[gwarser]

Attachment: Screenshot_20200413_220340.png

I also modified your addon to check it on github page (this was my test page in comment to bug above), and for some reason both listeners are always called

Comment 54

[kernp25]

Attachment: bad_case.moz_log

webRequest.onErrorOccurred was called.

Comment 55

[kernp25]

Attachment: good_case.moz_log

webRequest.onHeadersReceived was called.

Comment 56

[kernp25]

Maybe this will help you?

Comment 57

[kernp25]

Attachment: without_uBlock.moz_log

Tested without uBlock enabled (the bug did not occur).

Comment 58

[kernp25]

Attachment: log.txt-main.16392.moz_log

Bug also occured without uBlock enabled log.