1628162 - HTTP/2 pipelining causes request selection to include multiple requests (multiselect)

Status: RESOLVED DUPLICATE of bug 1640745

(DevTools :: Netmonitor, defect, P2)

Description

[:Harald Kirschner :digitarald]

Via:

https://superuser.com/questions/1537396/what-is-the-reason-firefox-combines-multiple-requests-in-the-network-monitor

https://discourse.mozilla.org/t/how-can-i-use-the-network-monitor-with-a-http-2-connection/57418

Comment 1

[:Harald Kirschner :digitarald]

Honza, any idea how actor IDs, which seem to be used for handling selection, could be re-used for multiple entries?

Comment 2

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

Some analysis:

1. We have a (redux) selector that returns request ID:
   https://searchfox.org/mozilla-central/rev/a707541ff423ade0d81cef6488e6ecfa09273886/devtools/client/netmonitor/src/selectors/requests.js#143-147

And yes, Request ID is Actor ID.

2. The selectedRequest ID is used here:
   https://searchfox.org/mozilla-central/rev/a707541ff423ade0d81cef6488e6ecfa09273886/devtools/client/netmonitor/src/components/request-list/RequestListContent.js#403

So, it is possibile that multiple requests are selected if they have the same ID.

3. There are two ways to add new requests
   A) New HTTP executed by the page and regularly added to the list of requests:
   https://searchfox.org/mozilla-central/rev/a707541ff423ade0d81cef6488e6ecfa09273886/devtools/client/netmonitor/src/reducers/requests.js#150
   B) The user wants to resend an existing request
   https://searchfox.org/mozilla-central/rev/a707541ff423ade0d81cef6488e6ecfa09273886/devtools/client/netmonitor/src/reducers/requests.js#215

There is no indication that resending a request is involved in this bug. So, let's assume A

4. The entry point for new HTTP requests added on the client is in the Data provider:
   https://searchfox.org/mozilla-central/rev/a707541ff423ade0d81cef6488e6ecfa09273886/devtools/client/netmonitor/src/connector/firefox-data-provider.js#367

We can see that actor ID is used as the first argument i.e. ID
There is no other entry point for handling new HTTP request coming from the server.

So, it looks like we are getting multiple onNetworkEvent for a request with the same actor.
There is no code that would check ID duplicity (the reducer is using an array not a map) so, it looks like a bug in the server.
Perhaps we are emitting networkevent multiple times for the same request?

Of course, having a test case would easily allow us to check that.

Honza

Comment 3

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

One more comment:

You should see the following error in the Browser Console in case of duplicated requests:

Warning: Encountered two children with the same key, `server0.conn1.netEvent*`. Keys should be unique so that components maintain their identity across updates. Non-unique keys may cause children to be duplicated and/or omitted — the behavior is unsupported and could change in a future version.
    in tbody (created by RequestListContent)
    in table (created by RequestListContent)
    in div (created by RequestListContent)
    ...

Honza

Comment 4

[Christian Wolf]

I am the original user that was affected by this issue and that opened the posts in comment #0.

Unfortunately, I am no longer able to reproduce the bug. I can clearly say that I did not try to resend an existing request. I just wanted to debug another issue and therefore look into the various requests (read-only so to call). So your assumption A was correct.

I will for sure keep an eye on things and try to find a test case. I will also look in the console for the named error. But for now, I am sorry I cannot provide more information.

Comment 6

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

Here is why I think the issue happens.

1. All active HTTP requests are tracked in the NetworkObserver. Collected data about requests are stored in a Map where key is the channel object
   https://searchfox.org/mozilla-central/rev/9120151ddb35f2d4c37bfe613a54a4f10a9a3dc5/devtools/server/actors/network-monitor/network-observer.js#216

2. New HTTP request is inserted in the map by createOrGetActivityObject method
   https://searchfox.org/mozilla-central/rev/9120151ddb35f2d4c37bfe613a54a4f10a9a3dc5/devtools/server/actors/network-monitor/network-observer.js#826

This methods is called often when we need to get access to collected data about specific request

3. A request is removed from the Map when ACTIVITY_SUBTYPE_TRANSACTION_CLOSE is fired by nsIActivityDistributor
   https://searchfox.org/mozilla-central/rev/9120151ddb35f2d4c37bfe613a54a4f10a9a3dc5/devtools/server/actors/network-monitor/network-observer.js#1047

4. If some other notifications (for a request) are fired after ACTIVITY_SUBTYPE_TRANSACTION_CLOSE. In such case a NEW entry is created in the map and NETWORK_EVENT event is sent to the client that treats it as a new request => creating duplicity entries in the table

This happened to me today when debugging blocked requests (by an extension) - using patch attached to bug 1555057.
I noticed that "http-on-stop-request" has been sent after ACTIVITY_SUBTYPE_TRANSACTION_CLOSE.

And since the patch adds _createNetworkEvent in the _httpStopRequest (handler for "http-on-stop-request") it sent a NETWORK_EVENT to the client for this request again.

@mayhemer: Can necko ensure that ACTIVITY_SUBTYPE_TRANSACTION_CLOSE is always the last event for particular event? Is it an error if any other event related to closed request is recieved? E.g. "http-on-stop-request"?

• Here is where we fire "http-on-stop-request" https://searchfox.org/mozilla-central/rev/9120151ddb35f2d4c37bfe613a54a4f10a9a3dc5/netwerk/protocol/http/HttpChannelChild.cpp#1521
• Here is where we fire ACTIVITY_SUBTYPE_TRANSACTION_CLOSE https://searchfox.org/mozilla-central/rev/9120151ddb35f2d4c37bfe613a54a4f10a9a3dc5/netwerk/protocol/http/nsHttpTransaction.cpp#1112

In any case as part of fixing this DevTools should probably check incoming request IDs on the client side and avoid duplicates.

Honza

Comment 9

[Hubert Boma Manilla (:bomsy)]

See STR for Bug 1632953. Might be useful.

Comment 12

[Honza Bambas (:mayhemer)]

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

@mayhemer: Can necko ensure that ACTIVITY_SUBTYPE_TRANSACTION_CLOSE is always the last event for particular event? Is it an error if any other event related to closed request is recieved? E.g. "http-on-stop-request"?

Sorry for such a late answer. No, there is no guarantee and cannot be enforced. Those two are originated on different threads (regardless that they both are ending on main thread eventually.)

Comment 13

[Hubert Boma Manilla (:bomsy)]

Got an good STR from Bug 1644275

1. Open https://share.firefox.dev/3h6vl0B
2. Open Network panel
3. Refresh
4. Click on on a couple of the blocked links
5. There should be duplicates

Comment 14

[Simon.Legner]

Attachment: 2020-08-11-085205.png

Also HTTP/1.1 connections are affected.

Mozilla/5.0 (X11; Linux x86_64; rv:79.0) Gecko/20100101 Firefox/79.0

Comment 15

[Simon.Legner]

Attachment: localhost_Archive [20-08-11 08-50-03].har

Exported HAR from Attachment 9169371 [details]

Comment 16

[Hubert Boma Manilla (:bomsy)]

Thanks for the info Simon.
This should be fixed by Bug 1640745 .
Please can you test in nightly to confirm?

Comment 17

[Simon.Legner]

That's great news, thank you! I can confirm that Comment 13 and Comment 14 are no longer reproducible with 81.0a1 (2020-08-10) (64-bit)

Comment 18

[Hubert Boma Manilla (:bomsy)]

Excellent! Thanks simon.