1733420 - browser_net_send-beacon.js fails with https-first (404 from httpd.js in HTTPS treated as 200?)

Status: RESOLVED FIXED

(DevTools :: Netmonitor, task, P2)

Description

[Julian Descottes [:jdescottes]]

From my local tests, it seems that 404 errors in HTTPS created by httpd.js are captured by the platform as "200 Connected"

An easy way to trigger this is to force https-first with any test which asserts a 404 status. For instance:

• run ./mach test devtools/client/netmonitor/test/browser_net_send-beacon.js --setpref dom.security.https_first=true

ER: Test should pass
AR: Test fails with Got "200", expected "404"

This is a browser mochitest which tries to make a request for https://example.com/browser/devtools/client/netmonitor/test/beacon_request

This request is done via navigator.sendBeacon, but this has no importance here, I only picked this test as an example because it is the smallest one which asserts a 404 in the netmonitor test suite.

From what I can see, httpd.js (which is the server used for mochitests) sends a response with the proper headers. However the network activity picked up by DevTools will only receive a 200 response.

I will create a smaller test case with a few additional logs to try to illustrate the issue. But I don't believe this is a DevTools issue, so I am a bit stuck in my investigation as I don't know the Necko codebase at all.

Comment 1

[Julian Descottes [:jdescottes]]

This might actually be an issue in DevTools' network observer. In _httpResponseExaminer (searchfox), I receive a 404 response status for the HTTPS URL, but somehow it gets lost.

Comment 2

[Julian Descottes [:jdescottes]]

Attachment: Bug 1733420 - Test case

Comment 3

[Julian Descottes [:jdescottes]]

Hi Bomsy, could you take a look at the test case attached here?

This test performs 2 requests which should lead to a 404 error, one in HTTPS, one in HTTP.
The one made with HTTPS is logged as a 200 Connected in DevTools, whereas the HTTP one is logged as a 404.

I initially suspected a platform issue, but I am not so sure anymore. I enabled platform events logging in network-observer.js, and we can see that we get a http-on-examine-response notification for both requests which has a responseStatus of 404. So I'm not sure why we still display it as a 200 in DevTools. I'll keep looking at this, but it might be easier for you to figure out where the mixup comes from.

Comment 4

[Julian Descottes [:jdescottes]]

(Bomsy: see question above)

Comment 5

[Julian Descottes [:jdescottes]]

It seems that we get different headers though.

Still in network-observer.js, in _onResponseHeader, we get the following arrays:

• for the HTTPS request: ["HTTP/1.1 200 Connected", "Connection: keep-alive", "", ""]
• for the HTTP request: ["HTTP/1.1 404 Not Found", "content-type: text/html;charset=utf-8", "connection: close", "server: httpd.js", "date: Thu, 30 Sep 2021 17:01:36 GMT", "content-length: 735", "", ""]

Comment 6

[Julian Descottes [:jdescottes]]

Attachment: http_logs.txt

:whimboo suggested looking at http logs. This is an extract of the logs generated by running the test uploaded on Phabricator with MOZ_LOG=timestamp,rotate:200,nsHttp:5,nsSocketTransport:5,nsHostResolver:5. This is only the part which relates to the HTTPS request.

We can see 2 Http Have status line logs, one with [version=11 status=200 statusText=Connected], the other with [version=11 status=404 statusText=Not Found]. Not sure how to parse this in more details, maybe it will make more sense to others.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Valentin could you maybe help out with Julian's question? Looks like that httpd.js returns a 200 instead of a 404 response for a non-existing path. See the last comment for a HTTP log. Thanks!

Comment 8

[Hubert Boma Manilla (:bomsy)]

Just to add, i had a look from the netmonitor devtools end, observeActivity https://searchfox.org/mozilla-central/rev/eecd2dd4ba630bea4ce103623a4bfb398065b64b/devtools/server/actors/network-monitor/network-observer.js#678 receives (from the platform) both the "HTTP/1.1 200 Connected" and the "HTTP/1.1 404 Not Found" sometime later.

We listen for the gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_HEADER here https://searchfox.org/mozilla-central/rev/eecd2dd4ba630bea4ce103623a4bfb398065b64b/devtools/server/actors/network-monitor/network-observer.js#634-635. The extraStringData is

HTTP/1.1 200 Connected
Connection: keep-alive

but ideally it rather should be

HTTP/1.1 404 Not Found
content-type: text/html;charset=utf-8
connection: close
server: httpd.js
date: Fri, 01 Oct 2021 00:04:42 GMT
content-length: 735

Interestingly we still get the 404 notification sometime later.
So It is not clear were the 200 response is fired from.
Also we seem to be getting a correct 404 notification from http-on-examine-response as mentioned by Julian in Comment 3.

Note: This does not seem to an issue with real websites.

Comment 9

[Valentin Gosu [:valentin] (he/him)]

The 200 Connected is the response from the proxy connection. The 404 is tunneled through that.
Only the 404 is generated by httpd.js AFAIK, the 200 is from the proxy server.
Not entirely sure where this mismatch is happening. I'll take a more careful look later tomorrow if this isn't much help.

Comment 10

[Valentin Gosu [:valentin] (he/him)]

Right, so the issue is that mChannelId we pass to mActivityDistributor->ObserveActivityWithArgs is the same for the initial CONNECT and the actual tunneled request. I assume we should report things differently when mConnection->IsProxyConnectInProgress()
Kershaw, do you have a better suggestion?

Comment 11

[Kershaw Chang [:kershaw]]

(In reply to Valentin Gosu [:valentin] (he/him) from comment #10)

Right, so the issue is that mChannelId we pass to mActivityDistributor->ObserveActivityWithArgs is the same for the initial CONNECT and the actual tunneled request. I assume we should report things differently when mConnection->IsProxyConnectInProgress()
Kershaw, do you have a better suggestion?

I can't think other better suggestion here. So, when mConnection->IsProxyConnectInProgress() is true, I think we should not report HTTP/1.1 200 Connected.

:bomsy, could you check if netmonitor wants to inspect the header of proxy response? If yes, we might need to add a new activity subtype.
Thanks.

Comment 12

[Hubert Boma Manilla (:bomsy)]

:bomsy, could you check if netmonitor wants to inspect the header of proxy response? If yes, we might need to add a new activity subtype.
Thanks.

ATM the netmonitor does do anything with the proxy response header. But it might be useful to have as a new activity subtype (if it is not much more effort), as there have been requests for viewing proxy information e.g Bug 1707192, Bug 252142.

Thanks

Comment 13

[Kershaw Chang [:kershaw]]

(In reply to Hubert Boma Manilla (:bomsy) from comment #12)

:bomsy, could you check if netmonitor wants to inspect the header of proxy response? If yes, we might need to add a new activity subtype.
Thanks.

ATM the netmonitor does do anything with the proxy response header. But it might be useful to have as a new activity subtype (if it is not much more effort), as there have been requests for viewing proxy information e.g Bug 1707192, Bug 252142.

I'll file a big to do this. Thanks!

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Given that the dependency has been fixed now shall we continue to get it fixed? It's still marked as a P2.

Comment 15

[Julian Descottes [:jdescottes]]

It would be nice to get this fixed. I'll defer to Bomsy: do you have a rough idea of what is left on DevTools side to address this?

Comment 16

[Hubert Boma Manilla (:bomsy)]

Attachment: Bug 1733420 - [devtools] Migrate the remaining tests to http-first r=jdescottes

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/fb65575ef4e3
[devtools] Migrate the remaining tests to http-first r=jdescottes

Comment 18

[Cristian Tuns]

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