Closed Bug 1472653 Opened Last year Closed 8 months ago

devtools.network.onRequestFinished listener fires before HAR entry is fully populated

Categories

(DevTools :: Netmonitor, defect, P2)

61 Branch
defect

Tracking

(firefox67 fixed)

RESOLVED FIXED
Firefox 67
Tracking Status
firefox67 --- fixed

People

(Reporter: dharding, Assigned: antross)

References

Details

Attachments

(4 files)

I am trying to port a Chrome extension that uses the devtools.network.onRequestFinished API to take action based on the response headers.  However, when the onRequestFinished callback is called, none of the fields in harEntry.response have been initialized.

I was able to reproduce this issue using the HARExportTrigger extension (https://github.com/devtools-html/har-export-trigger) and the associated test page (http://softwareishard.com/test/harexporttrigger/).  To reproduce, install the extension, navigate to the test page, and click the "Add Request Listener" button.  Then clear the browser cache to ensure that the subsequent requests actually traverse the network.  Finally, click any of the four buttons to make a HTTP request.

For each request, the onRequestFinished callback will log the HAR entry to the web console.  If the request actually goes over the network (instead of being satisfied from the cache), the logged response from the HAR entry will be uninitialized:

response: {…}
    bodySize: -1
    content: Object {  }
    cookies: Array []
    headers: Array []
    httpVersion: ""
    redirectURL: ""
    status: 0
    statusText: ""
    <prototype>: Object { … }

If the request is satisfied from the cache, the logged response from the HAR entry will be populated as expected.  This is what I would expect regardless of whether the request had to access the network or not:

response: {…}
    bodySize: null
    content: Object { mimeType: "image/jpeg", size: 1487458, encoding: "base64", … }
    cookies: Array []
    headers: Array(11) [ {…}, {…}, {…}, … ]
    headersSize: 0
    httpVersion: "HTTP/1.1"
    redirectURL: ""
    status: 200
    statusText: "OK"
    <prototype>: Object { … }

Some additional notes:
 - I was able to reproduce this on a new Firefox Profile, with only the HARExportTrigger extension installed.
 - Whether I opened the Developer Tools Network panel or not did not make any difference in the observed behavior.
 - I am on a fairly slow network - total request time was over 400ms (Blocked: 120ms, Connecting: 117ms, Waiting: 168ms).
Flags: needinfo?(odvarko)
Hi Daniel,
thanks for the report, I can reproduce the issue on my machine.

Changing the target component to: DevTools/Netmonitor

Honza
Status: UNCONFIRMED → NEW
Component: Developer Tools → Netmonitor
Ever confirmed: true
Flags: needinfo?(odvarko)
Priority: -- → P2
Product: WebExtensions → DevTools
So, I am puzzled by this. As soon as I started analyzing this, I can't see the issue anymore.

Here is my STR:

1) Install the addon from: https://addons.mozilla.org/cs/firefox/addon/har-export-trigger/
2) Load this page: http://softwareishard.com/test/harexporttrigger/
3) Open the Toolbox
4) Click `Add Request Listener` button on the page
5) Go to `about:preferences#privacy` and click the `Clear History` button (I am picking Everything and only leaving Site preferences and Offline Website Data unchecked.
6) Go back to http://softwareishard.com/test/harexporttrigger/
7) Click the `Text` button
8) Inspect HAR log in the Console panel. The `{...} -> response` it should contain data. E.g. {...} -> response -> bodySize should be set to 380

What am I doing wrong?

Honza
Flags: needinfo?(dharding)
So I seem to be experiencing this as well.  It seems a bit random, though the top level load seems more likely to be empty.
Force-reload (Ctrl+Shift+R) seems to increase the chances of it happening, that seems to boost the rate of empty response.headers (the part my extension is looking at) to about 50% of the (dozen or so) loads on my personal site.

Relatedly onNavigated fires at a very different time (random) to Chrome (before the top level onRequestFinished fires), which seems to make separating out which requests are associated with which navigation very difficult.
STR:
1) Load attached extension
2) Open its panel in devtools (onRequestFinished)
3) Load example.com
4) Reload (Ctrl+R) it a few times
5) Force-reload (Ctrl+Shift+R) it a few times

AR:
Headers are missing about 50% of the time on regular reload, 100% on force-reload (unless you do a second one before the first has finished)
(onNavigated fired randomly)

ER:
Headers always present
(onNavigated fired before first onRequestFinished)

Honza, are you able to repro with this?

(As another note/bug, autoscroll inside a panel is visually interesting)
Flags: needinfo?(odvarko)
Hozna,

It sounds like you are doing exactly the same thing that I am.  I can reproduce 100% of the time by using the "Post Data" button, since that always makes a network connection regardless of the cache state.  This allows skipping the Clear History Step.  Perhaps there is some sort of race condition?  As I noted in my initial report, I am on relatively high-latency network, so for me an actual network request from the test page takes just over 400ms as reported by the Developer Tools.  If the requests complete more quickly for you, that might explain why you are having trouble reproducing it.

I'm happy to provide any other info I can.  I run Gentoo, so it is quite easy (if a bit slow) for me to rebuild Firefox if it would be useful to apply any patches to help instrument the build or otherwise debug it (as long as the patches could be made to apply to Firefox 61).
Flags: needinfo?(dharding)
Do you see any errors in the Browser Console?

I am seeing:
Error: "Error while calling method getEventTimings: No such actor for ID: server2.conn0.netEvent51"
Not entirely sure if it's directly related, but it's at least suspicious.

Honza
Does it work for you in Firefox 62?

Honza
Alex, was there any change recently that could cause the "getEventTimings" error?
See comment #6

Honza
Flags: needinfo?(poirot.alex)
Bug 1444132 may have introduced new races into HAR as it made it significantly faster.
If we were not waiting correctly for an async step, it will make it easier to make it pass as code is now faster.
Then, we may highlight yet another type of race because of that.

By following comment 2, I do reproduce bodySize = -1 without any exception in the browser console.
HAR codebase is most likely not waiting correctly the full request response somewhere.
Flags: needinfo?(poirot.alex)
Oh wait, bodySize set to -1 means that transferredSize isn't set:
  https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/har/har-builder.js#359

It would be interesting to review if the transferredSize is valid from here:
  https://searchfox.org/mozilla-central/source/devtools/shared/webconsole/network-monitor.js#680

It is later received by client in this event:
  https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/har/har-collector.js#244
(is har-collector actually used in this case? I never remember which class is used when)

May be there is a race with networkEventUpdate event here?
Just tested in Firefox 62.0.2 and still see the issue.  Only console output for the POST request besides the uninitialized HAR entry is "Attempt to set a forbidden header was denied: Content-Length" but this isn't related to this issue.
Attaching another repro derived from work on the browser extension for webhint:
https://github.com/webhintio/hint/pull/1438#issuecomment-440013184

As mentioned there, I've had fairly good luck reproducing the issue by running this repro extension against https://webhint.io. Which specific resources end up missing details tends to vary from load to load, but the top-level page and cross-origin resources seem to be the ones which fail most often. On a side-note it looks like the status code almost always returns `0`, even when the other data is populated.

I got some time to look into this and think I've identified where the race condition is. I made a change which I confirmed resolved my repro locally with a custom build of Firefox. Tests still passed, though I could easily be missing some unintended side-effects of the change.

If this sounds good, let me know if you'd prefer to take it from here or if you'd like me to try submitting a patch. I may need some help introducing a reliable test to capture the race condition if that's desired.

Short version:

Trigger onRequestFinished listeners in response to PAYLOAD_RECEIVED instead of REQUEST_ADDED:
https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/api.js#60

Long version:

The onRequestFinished listeners are currently triggered in response to the internal REQUEST_ADDED event. That event is fired when a request is initially added to the netmonitor - so the request may not have a response yet:
https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/connector/firefox-data-provider.js#99

Even though some response data is lazily requested from the backend by HarBuilder (via requestData in FirefoxDataProvider), even that can return from the backend empty if the response hasn't completed yet (and simple items, such as status, are not lazily requested anyway):
https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/har/har-builder.js#326

So REQUEST_ADDED appears to fire too early to reliably include response data in onRequestFinished. Looking at FirefoxDataProvider, various aspects of a request payload get queued and eventually merged. When this is done, PAYLOAD_READY fires (once per request according to the comment in onPayloadDataReceived):
https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/connector/firefox-data-provider.js#427

The onPayloadDataReceived handler that triggers PAYLOAD_READY also includes comments indicating it fires when requestData can be used, further suggesting this is the right event to wait for instead of REQUEST_ADDED.

I'm happy to test once there is a patch available.

Honza, any thoughts on this?

(In reply to Tony Ross from comment #13)

I got some time to look into this and think I've identified where the race condition is. I made a change which I confirmed resolved my repro locally with a custom build of Firefox. Tests still passed, though I could easily be missing some unintended side-effects of the change.

If this sounds good, let me know if you'd prefer to take it from here or if you'd like me to try submitting a patch. I may need some help introducing a reliable test to capture the race condition if that's desired.

Short version:

Trigger onRequestFinished listeners in response to PAYLOAD_RECEIVED instead of REQUEST_ADDED:
https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/api.js#60

This is great help, thanks for the analysis Tony!

Yes, this makes sense and it seems to be the problem. Note that when registering the listener for PAYLOAD_RECEIVED (instead of REQUEST_ADDED) you should also make sure that the right listener is unregistered in the destroy method (in the same api.js file).

Please attach a patch, so people can test this.

Honza

Flags: needinfo?(odvarko)

Fire onRequestFinished after PAYLOAD_RECEIVED instead of REQUEST_ADDED.
Ensures response data is available for a request before dispatching the event.

Thanks Tony!

Push to our Try server (integration tests) looks good:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1d71714f994a3a7383d0faccb2a0aafebd26640d

I'll be yet testing this manually.

Honza

Just tested Tony's patch using Firefox 65. Prior to applying the patch I could still consistently reproduce the issue. After rebuilding with the patch applied I have been unable to reproduce. Looks good to me - thanks Tony!

I just tested the patch as well (with and without) and I can't reproduce the issue if the patch is applied.
Great job here, thanks Tony!

Honza

Pushed by jodvarko@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/248b41426bf2
Update event to trigger devtools.network.onRequestFinished. r=Honza

Great to hear this is working for everyone - I'm glad I could help!

Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 67
Assignee: nobody → antross
Flags: qe-verify+
Attached file addon (1).txt

I've managed to load and use that addon via the about:debugging page.
However, there where still some results that appear to be with zero headings; this is the case for macOS10.13 (beta12)
Is it something of concern? Saw that the message was for the favicons or I might be wrong. Questions would be if it's safe to mark the bug as verified with this?

Attaching the log files for confirmation as well.
Thanks!

Flags: needinfo?(odvarko)
Flags: needinfo?(antross)

@Honza This still looks verified to me.

I confirmed the Network panel of the tools also does not display any response headers for the favicon requests on https://www.mozilla.org/en-US/privacy/firefox/.

My interpretation is this suggests the API is consistent with the Network panel so the fix is still valid. Whether or not response headers should be shown in the Network panel in the first place would be a separate issue (I'm guessing it relates to how favicons are fetched).

Flags: needinfo?(antross)

(In reply to Tony Ross [:antross] from comment #25)

I confirmed the Network panel of the tools also does not display any response headers for the favicon requests on https://www.mozilla.org/en-US/privacy/firefox/.

@antros: Thanks for the update! Can you please file a new bug for this and provide some instructions how to reproduce it? This bug report is already closed.

Honza

Flags: needinfo?(odvarko) → needinfo?(antross)

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #26)

(In reply to Tony Ross [:antross] from comment #25)

I confirmed the Network panel of the tools also does not display any response headers for the favicon requests on https://www.mozilla.org/en-US/privacy/firefox/.

@antros: Thanks for the update! Can you please file a new bug for this and provide some instructions how to reproduce it? This bug report is already closed.

Honza

Looks like I lost the repro after my most recent update unfortunately (or fortunately depending on how you look at it). Not sure if it was tied to a specific version or was state-related, but if I manage to get a repro again I'll open a new bug.

Tony

Flags: needinfo?(antross)
See Also: → 1552686

Thanks a lot for this Tony! I've filed bug 1552686 for the onNavigated behaviour I mentioned in comment 3.

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