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

Status: VERIFIED FIXED

(DevTools :: Netmonitor, defect, P2)

Description

[Daniel Harding]

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).

Comment 1

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Hi Daniel,
thanks for the report, I can reproduce the issue on my machine.

Changing the target component to: DevTools/Netmonitor

Honza

Comment 2

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 3

[Ian Moody [:Kwan] (UTC+1)]

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.

Comment 4

[Ian Moody [:Kwan] (UTC+1)]

Attachment: empty_onrequestfinished-0.1.zip

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)

Comment 5

[Daniel Harding]

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).

Comment 6

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 7

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Does it work for you in Firefox 62?

Honza

Comment 8

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Honza

Comment 9

[Alexandre Poirot [:ochameau]]

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.

Comment 10

[Alexandre Poirot [:ochameau]]

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?

Comment 11

[Daniel Harding]

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.

Comment 12

[Tony Ross [:antross]]

Attachment: onrequestfinished-bug.zip

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.

Comment 13

[Tony Ross [:antross]]

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.

Comment 14

[Daniel Harding]

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

Comment 15

[Tony Ross [:antross]]

Honza, any thoughts on this?

Comment 16

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(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

Comment 17

[Tony Ross [:antross]]

Attachment: Bug 1472653 - Update event to trigger devtools.network.onRequestFinished. r=honza

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

Comment 18

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 19

[Daniel Harding]

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!

Comment 20

[Jan Honza Odvarko [:Honza] (always need-info? me)]

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

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/248b41426bf2
Update event to trigger devtools.network.onRequestFinished. r=Honza

Comment 22

[Tony Ross [:antross]]

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

Comment 23

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/248b41426bf2

Comment 24

[Cristian Fogel [:cfogel]]

Attachment: 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!

Comment 25

[Tony Ross [: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).

Comment 26

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(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

Comment 27

[Tony Ross [: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

Comment 28

[Ian Moody [:Kwan] (UTC+1)]

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

Comment 29

[Cristian Fogel [:cfogel]]

Closing issue as per comment 25.