1473718 - A Containered tab opens 2 connections to a server.

Status: RESOLVED FIXED

(Firefox :: Address Bar, defect, P2)

Description

[David Heiberg [:dheiberg]]

When using a container from the Multi-Account Containers (https://addons.mozilla.org/en-GB/firefox/addon/multi-account-containers/), it seems that Firefox opens 2 connections to the server. After some more digging, it seems that one connection is for the  containered tab, and the other connection is for some non containered tab that I suppose is underneath it somehow? I'll try to explain my setup and procedure:

Running a HTTP/2.0 server, Firefox Nightly 63.0a1 (2018-07-05) (64-bit), on Mac OS High Sierra 10.13.5.

Steps:
1) Launch HTTP/2.0 server
2) Open a new Container tab via the toolbar menu.
3) In said container tab, navigate to the local server address
4) Open new, standard, tab and navigate to the same address

Log Breakdown:
Marker 1: This is step 3. Here you can see a http/2.0 connection being established, and assigned UUID starting with 6524786e
Marker 2: This is step 3. Another new H2 connection is made and given UUID e32803e1. 
Marker 3: This is step 3, the containered tab requests the resource, from connection 6524786e.
Marker 4: This is step 4, where the new un-containered tab requests the same resource, on connection e32803e1.

So it seems like a containered tab opens an additional connection, which is to be used for non containered tabs. This seems pre-emptive and not necessarily intended behavior. If I've missed anything, or if any clarification is needed please let me know.

The http/2.0 server's logs:
>1 - DEBUG:web-platform-tests:Initiating h2 Connection -- UUID: 6524786e-4b6c-40fd-aa1e-14fc4b45929c
>DEBUG:web-platform-tests:(6524786e-4b6c-40fd-aa1e-14fc4b45929c) Events: [<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.HEADER_TABLE_SIZE, original_value=4096, new_value=65536), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=131072), ChangedSetting(setting=SettingCodes.MAX_FRAME_SIZE, original_value=16384, new_value=16384)}>, <WindowUpdated stream_id:0, delta:12517377>, <PriorityUpdated stream_id:3, weight:201, depends_on:0, exclusive:False>, <PriorityUpdated stream_id:5, weight:101, depends_on:0, exclusive:False>, <PriorityUpdated stream_id:7, weight:1, depends_on:0, exclusive:False>, <PriorityUpdated stream_id:9, weight:1, depends_on:7, exclusive:False>, <PriorityUpdated stream_id:11, weight:1, depends_on:3, exclusive:False>, <PriorityUpdated stream_id:13, weight:241, depends_on:0, exclusive:False>]
>DEBUG:web-platform-tests:(6524786e-4b6c-40fd-aa1e-14fc4b45929c) Events: [<SettingsAcknowledged changed_settings:{}>]
>2 - DEBUG:web-platform-tests:Initiating h2 Connection -- UUID: e32803e1-5288-43af-8a56-54765870ccb0
>DEBUG:web-platform-tests:(e32803e1-5288-43af-8a56-54765870ccb0) Events: [<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.HEADER_TABLE_SIZE, original_value=4096, new_value=65536), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=131072), ChangedSetting(setting=SettingCodes.MAX_FRAME_SIZE, original_value=16384, new_value=16384)}>, <WindowUpdated stream_id:0, delta:12517377>, <PriorityUpdated stream_id:3, weight:201, depends_on:0, exclusive:False>, <PriorityUpdated stream_id:5, weight:101, depends_on:0, exclusive:False>, <PriorityUpdated stream_id:7, weight:1, depends_on:0, exclusive:False>, <PriorityUpdated stream_id:9, weight:1, depends_on:7, exclusive:False>, <PriorityUpdated stream_id:11, weight:1, depends_on:3, exclusive:False>, <PriorityUpdated stream_id:13, weight:241, depends_on:0, exclusive:False>]
>DEBUG:web-platform-tests:(e32803e1-5288-43af-8a56-54765870ccb0) Events: [<SettingsAcknowledged changed_settings:{}>]
>3 - DEBUG:web-platform-tests:(6524786e-4b6c-40fd-aa1e-14fc4b45929c) Events: [<RequestReceived stream_id:15, headers:[(':method', 'GET'), (':path', '/'), (':authority', 'localhost:9000'), (':scheme', 'https'), ('user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:63.0) Gecko/20100101 Firefox/63.0'), ('accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'), ('accept-language', 'en-GB,en;q=0.5'), ('accept-encoding', 'gzip, deflate, br'), ('dnt', '1'), ('upgrade-insecure-requests', '1'), ('te', 'trailers')]>, <StreamEnded stream_id:15>, <PriorityUpdated stream_id:15, weight:42, depends_on:13, exclusive:False>, <WindowUpdated stream_id:15, delta:12451840>]
>DEBUG:web-platform-tests:(6524786e-4b6c-40fd-aa1e-14fc4b45929c) Parsing RequestReceived
>DEBUG:web-platform-tests:GET /
>DEBUG:web-platform-tests:Found handler FileHandler
>DEBUG:web-platform-tests:200 GET / (None) 0
>DEBUG:web-platform-tests:(6524786e-4b6c-40fd-aa1e-14fc4b45929c) Events: [<RequestReceived stream_id:17, headers:[(':method', 'GET'), (':path', '/favicon.ico'), (':authority', 'localhost:9000'), (':scheme', 'https'), ('user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:63.0) Gecko/20100101 Firefox/63.0'), ('accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'), ('accept-language', 'en-GB,en;q=0.5'), ('accept-encoding', 'gzip, deflate, br'), ('dnt', '1'), ('te', 'trailers')]>, <StreamEnded stream_id:17>, <PriorityUpdated stream_id:17, weight:22, depends_on:11, exclusive:False>, <WindowUpdated stream_id:17, delta:12451840>]
>DEBUG:web-platform-tests:(6524786e-4b6c-40fd-aa1e-14fc4b45929c) Parsing RequestReceived
>DEBUG:web-platform-tests:GET /favicon.ico
>DEBUG:web-platform-tests:Found handler FileHandler
>DEBUG:web-platform-tests:404 GET /favicon.ico (None) 0
>4 - DEBUG:web-platform-tests:(e32803e1-5288-43af-8a56-54765870ccb0) Events: [<RequestReceived stream_id:15, headers:[(':method', 'GET'), (':path', '/'), (':authority', 'localhost:9000'), (':scheme', 'https'), ('user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:63.0) Gecko/20100101 Firefox/63.0'), ('accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'), ('accept-language', 'en-GB,en;q=0.5'), ('accept-encoding', 'gzip, deflate, br'), ('dnt', '1'), ('upgrade-insecure-requests', '1'), ('te', 'trailers')]>, <StreamEnded stream_id:15>, <PriorityUpdated stream_id:15, weight:42, depends_on:13, exclusive:False>, <WindowUpdated stream_id:15, delta:12451840>]
>DEBUG:web-platform-tests:(e32803e1-5288-43af-8a56-54765870ccb0) Parsing RequestReceived
>DEBUG:web-platform-tests:GET /
>DEBUG:web-platform-tests:Found handler FileHandler
>DEBUG:web-platform-tests:200 GET / (None) 0
>DEBUG:web-platform-tests:(e32803e1-5288-43af-8a56-54765870ccb0) Events: [<RequestReceived stream_id:17, headers:[(':method', 'GET'), (':path', '/favicon.ico'), (':authority', 'localhost:9000'), (':scheme', 'https'), ('user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:63.0) Gecko/20100101 Firefox/63.0'), ('accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'), ('accept-language', 'en-GB,en;q=0.5'), ('accept-encoding', 'gzip, deflate, br'), ('dnt', '1'), ('te', 'trailers')]>, <StreamEnded stream_id:17>, <PriorityUpdated stream_id:17, weight:22, depends_on:7, exclusive:False>, <WindowUpdated stream_id:17, delta:12451840>]
>DEBUG:web-platform-tests:(e32803e1-5288-43af-8a56-54765870ccb0) Parsing RequestReceived
>DEBUG:web-platform-tests:GET /favicon.ico
>DEBUG:web-platform-tests:Found handler FileHandler
>DEBUG:web-platform-tests:404 GET /favicon.ico (None) 0

Comment 1

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

A few questions:
Do you actually have a web-platform-test for this? That would be super helpful in tracking this down.
I wonder if this is an HTTP/2 issue. Can you check if it also happens with HTTP/1.1 ?

Comment 2

[David Heiberg [:dheiberg]]

(In reply to Valentin Gosu [:valentin] from comment #1)
> A few questions:
> Do you actually have a web-platform-test for this? That would be super
> helpful in tracking this down.
> I wonder if this is an HTTP/2 issue. Can you check if it also happens with
> HTTP/1.1 ?

There is not web-platform-test for this. I came across this because I am currently developing the HTTP/2.0 server for the wpt project, and noticed that when using containers my server would receive 2 connections. I just checked, and a similar behavior happens with HTTP/1.1, where 2 connections are made to the server and then the request is made, so this does not seem to be HTTP/2.0 specific. 

My guess is that when the tab makes a request, it creates a connection specifically for the container, but then returns and continues running the normal tab code, which also opens a connection to the server. Not too sure on what is happening behind the scenes, but it seems like this is a likely scenario

Comment 3

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

I tried to reproduce this locally with a test case, and I wasn't able to.
Do you have a way we could reproduce this?
Otherwise, would you be able to gather some HTTP logs for us? https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
I am very curious as to why we open that second connection. I've looked at the code a bit, but nothing stands out. It might not even be a bug, but we should definitely investigate it.

Comment 4

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

see comment 3

Comment 5

[David Heiberg [:dheiberg]]

(In reply to Valentin Gosu [:valentin] from comment #3)
> I tried to reproduce this locally with a test case, and I wasn't able to.
> Do you have a way we could reproduce this?
> Otherwise, would you be able to gather some HTTP logs for us?
> https://developer.mozilla.org/en-US/docs/Mozilla/Debugging/HTTP_logging
> I am very curious as to why we open that second connection. I've looked at
> the code a bit, but nothing stands out. It might not even be a bug, but we
> should definitely investigate it.

Hi, I have created a simple server for you so that hopefully you are able to reproduce the error on your end: https://github.com/dhdavvie/SimpleH2Server. Setup and run instructions included, please note the Python 2.7.15 requirement. I used an HTTP/2.0 server as an example as I believe it works really well to showcase the potential bug/feature.

Please feel free to reach out here or on irc (:dheiberg) if the provided server doesn't work or you would like me to expand it somehow :)

Comment 6

[David Heiberg [:dheiberg]]

Attachment: Firefox Network Logs

These are firefox network logs of requesting the resource from the server in a containered tab, then requesting the resource again from a non containered tab. Both tabs were open, but unconnected to the server, at the start of logging.

Comment 7

[David Heiberg [:dheiberg]]

See comments 5 and 6

Comment 8

[u408661]

I wonder if this is related to the thumbnail service? That would conceivably load the page to take a screenshot for the thumbnail using a different container (and therefore originattributes), which would indeed cause a new connection.

I don't see anything about the thumbnail service in the logs, but that makes sense, since those are network-only logs. I don't even know how we would get the thumbnail service to log stuff in the first place to find out. Seems worth checking into, though.

Comment 9

[David Heiberg [:dheiberg]]

(In reply to Nicholas Hurley [:nwgh][:hurley] from comment #8)
> I wonder if this is related to the thumbnail service? That would conceivably
> load the page to take a screenshot for the thumbnail using a different
> container (and therefore originattributes), which would indeed cause a new
> connection.
> 
> I don't see anything about the thumbnail service in the logs, but that makes
> sense, since those are network-only logs. I don't even know how we would get
> the thumbnail service to log stuff in the first place to find out. Seems
> worth checking into, though.

I am not familiar with the workings of the Thumbnail service, but the second connection does not actually make a GET request to the server (unless you go into an uncontainered tab and request the page), it simply establishes a connection. For your theory to be the case, would it not have to perform a GET request in order to load the page?

Comment 10

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

So, the callpath goes through nsHttpHandler::SpeculativeConnect2. If I put an early return in SpeculativeConnectInternal the issue goes away.
The principal it gets is not null, but it doesn't seem to have the correct originAttributes.
Currently looking into where the principal is coming from.

Comment 11

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

Through the magic of RR I was able to trace the issue to:
https://searchfox.org/mozilla-central/rev/28daa2806c89684b3dfa4f0b551db1d099dda7c2/toolkit/components/remotebrowserutils/RemoteWebNavigation.js#92

Commenting that line fixes the issue, but I assume that would regress bug 1383299 :)
Also, for containers, the optimization in 1383299 doesn't really help, as it speculatively creates a connection with no originAttributes (system principal), whereas the tab will later create another connection with the appropriate userContextId.

Comment 12

[Mike Conley (:mconley) (:⚙️)]

Good detective work tracking that down, valentin!

I think I'm a little confused here... re-reading bug 1383299, it looks like we paid attention to origin attributes when working on that patch... hey ckerschb, do you know how we're falling over here?

Comment 13

[Christoph Kerschbaumer [:ckerschb]]

(In reply to Mike Conley (:mconley) (:⚙️) (PTO Jul 24th-Aug 6th)) from comment #12)
> Good detective work tracking that down, valentin!
> 
> I think I'm a little confused here... re-reading bug 1383299, it looks like
> we paid attention to origin attributes when working on that patch... hey
> ckerschb, do you know how we're falling over here?

Unfortunately I don't, but baku knows pretty much everything about Origin Attributes and might be able to help us out here.

Baku, Valentin identified that speculativeConnect2() [1] and the actual channel use different Origin Attributes which probably is not what we want. Is [1] querying the correct origin attributes or are we messing something up here?

[1] https://searchfox.org/mozilla-central/rev/28daa2806c89684b3dfa4f0b551db1d099dda7c2/toolkit/components/remotebrowserutils/RemoteWebNavigation.js#92

Comment 14

[Andrea Marchesini [:baku]]

Attachment: oa.patch

The problem here is that the triggering principal is SystemPrincipal. We want to use a ContentPrincipal instead.

Comment 15

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 8991928 [details] [diff] [review]
oa.patch

Ah hah, thanks baku!

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c1cf5d73a4e2
Speculative connection should start using the correct OriginAttributes values, r=mconley

Comment 17

[Noemi Erli[:noemi_erli]]

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