1753730 - Early hint preloader responsible for a single preload

Status: RESOLVED FIXED

(Core :: Networking: HTTP, task, P2)

Description

[Manuel Bucher [:manuel]]

+++ This bug was initially created as a clone of Bug #1740689 +++

We need a class that will be responsible for a single preload. The class will:

• create a channel
• and will receive data, (OnStartRequest/OnDataAvaialbe/OnStopRequest)

Creating new bug, because the previous one was closed with a patch, but the Preloader part is still todo.

Comment 1

[Manuel Bucher [:manuel]]

Attachment: Bug 1753730 - Add EarlyHintPreloader to load 103 Early Hint responses into the cache r=#necko

Comment 2

[Manuel Bucher [:manuel]]

Attachment: Bug 1753730 - Test that the cached image from the early hint preload is used r=#necko

Depends on D137885

Comment 3

[Manuel Bucher [:manuel]]

Attachment: Bug 1753730 - Fix early hint not propagating with http proxy r=#necko

Depends on D139740

Comment 4

[Manuel Bucher [:manuel]]

Attachment: Bug 1753730 - Add Referer-Header to early hint preload r=#necko

Depends on D137885

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/47787105e3ad
Fix early hint not propagating with http proxy r=necko-reviewers,dragana
https://hg.mozilla.org/integration/autoland/rev/3c25877d2660
Add EarlyHintPreloader to load 103 Early Hint responses into the cache r=necko-reviewers,ckerschb,dragana,kershaw
https://hg.mozilla.org/integration/autoland/rev/8f27dc8dbbe0
Test that the cached image from the early hint preload is used r=necko-reviewers,ckerschb,dragana,kershaw

Comment 6

[Iulian Moraru]

Backed out for causing bc failures on browser_103_preload.js.

Push with failures

Failure log for TV jobs
Failure log for bc failures
Failure log for bc failures

Backout link

[task 2022-05-03T19:47:00.090Z] 19:47:00     INFO - TEST-PASS | netwerk/test/browser/browser_103_preload.js | test_preload_csp_imgsrc_none: Image dislpayed unexpectedly - true == true - 
[task 2022-05-03T19:47:00.091Z] 19:47:00     INFO - Buffered messages finished
[task 2022-05-03T19:47:00.092Z] 19:47:00     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_preload.js | test_preload_csp_imgsrc_none: Unexpected amount of requests made - {"hinted":0,"normal":0} deepEqual {"hinted":1,"normal":0} - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_preload.js :: test_preload_csp_imgsrc_none :: line 332
[task 2022-05-03T19:47:00.092Z] 19:47:00     INFO - Stack trace:
[task 2022-05-03T19:47:00.092Z] 19:47:00     INFO - chrome://mochitests/content/browser/netwerk/test/browser/browser_103_preload.js:test_preload_csp_imgsrc_none:332
[task 2022-05-03T19:47:00.092Z] 19:47:00     INFO - Leaving test bound test_preload_csp_imgsrc_none
[task 2022-05-03T19:47:00.093Z] 19:47:00     INFO - Entering test bound test_103_error_400
[task 2022-05-03T19:47:00.319Z] 19:47:00     INFO - TEST-PASS | netwerk/test/browser/browser_103_preload.js | test_103_error_400: Unexpected amount of requests made - {"hinted":1,"normal":1} deepEqual {"hinted":1,"normal":1} - 

Comment 7

[Manuel Bucher [:manuel]]

Some thoughts on why some tests are failing: My method of checking if the correct amount of requests were made doesn't seem reliable from the Failure log links above

# Failure log for TV jobs
[task 2022-05-03T20:01:35.927Z] 20:01:35     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_preload.js | test_103_preload: Unexpected amount of requests made - {"hinted":0,"normal":1} deepEqual {"hinted":1,"normal":0} - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_preload.js :: test_hint_preload_internal :: line 73
# Failure log for bc failures - link 1
[task 2022-05-03T20:09:17.580Z] 20:09:17     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_preload.js | test_103_preload: Unexpected amount of requests made - {"hinted":0,"normal":1} deepEqual {"hinted":1,"normal":0} - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_preload.js :: test_hint_preload_internal :: line 73
# Failure log for bc failures - link 2
[task 2022-05-03T19:47:00.092Z] 19:47:00     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_preload.js | test_preload_csp_imgsrc_none: Unexpected amount of requests made - {"hinted":0,"normal":0} deepEqual {"hinted":1,"normal":0} - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_preload.js :: test_preload_csp_imgsrc_none :: line 332
[task 2022-05-03T19:47:04.054Z] 19:47:04     INFO - TEST-UNEXPECTED-FAIL | netwerk/test/browser/browser_103_preload.js | test_103_iframe: Unexpected amount of requests made - {"hinted":0,"normal":0} deepEqual {"hinted":0,"normal":1} - JS frame :: chrome://mochitests/content/browser/netwerk/test/browser/browser_103_preload.js :: test_103_iframe :: line 475

The first three look like the config option network.early-hints.enabled is false or EarlyHintPreloader has an error parsing the early hint response. The forth one can only partially be explained that way, no "normal" load was made. Maybe in addition the iframe doesn't have to load for a page to be considered completely loaded. That could explain the test failures, but I'll now investigate and try to fix them.

Comment 8

[Manuel Bucher [:manuel]]

My current understanding why the tests are failing:

• test_preload_csp_imgsrc_none:
  • The early hint response with the hint to the image resource and the final http response are sent with 0ms delay in-between.
  • The final http response doesn't need to load the image in the html page, because of Content-Security-Policy: img-src 'none'.
  • the page load is completed before the early hint request is sent.
  • Tab gets closed (and the early hint request gets cancelled/or requesting the count is faster than requesting the image in the preloader).
  • No early hint preload is counted.
  • Possible workarounds:
    • allow either one or zero preload requests - might have influence on other test cases if the preload is made when the next test case is started, might be unlikely or impossible
    • add delay in page load to allow the preload to be made within the time frame (10-15ms) - code is still racy, but might avoid the intermittent for now
• Other test failures, where a normal response is made instead of an early hint response:
  • AFAIK the main document is loaded in the child process and requests the image
  • The early hint request is made on the parent process
  • The test failure occurs if the child process is faster in creating the channel to load the resource (here again because it is available instantly after the early hint)
• I've no explanation why the iframe test doesn't fire any loads.

Comment 9

[Manuel Bucher [:manuel]]

test_preload_csp_imgsrc_none and test_103_iframe were failing, because they weren't designed to run multiple times in the same browser session. Clearing the cache at the end of the test case fixed these test cases.
I'm still investigating the reason for the remaining test failures.

The left object contains the observed number of request made, the right object contains the expected number of requests made.

Test verify failures

• https://treeherder.mozilla.org/logviewer?job_id=376696507&repo=autoland&lineNumber=2924

test_103_relative_preload: Unexpected amount of requests made - {"hinted":0,"normal":1} deepEqual {"hinted":1,"normal":0}

• https://treeherder.mozilla.org/logviewer?job_id=376696507&repo=autoland&lineNumber=3301

test_103_error_408: Unexpected amount of requests made - {"hinted":0,"normal":1} deepEqual {"hinted":1,"normal":1}

• https://treeherder.mozilla.org/logviewer?job_id=377114263&repo=autoland&lineNumber=3189

test_103_error_400: Unexpected amount of requests made - {"hinted":0,"normal":1} deepEqual {"hinted":1,"normal":1}

• https://treeherder.mozilla.org/logviewer?job_id=376696871&repo=autoland&lineNumber=3248

test_103_redirect_same_origin: Unexpected amount of requests made - {"hinted":2,"normal":1} deepEqual {"hinted":2,"normal":0}

bc test failures

• https://treeherder.mozilla.org/logviewer?job_id=376697713&repo=autoland&lineNumber=2773
  https://treeherder.mozilla.org/logviewer?job_id=376698656&repo=autoland&lineNumber=2659

test_103_preload_twice_1: Unexpected amount of requests made - {"hinted":0,"normal":1} deepEqual {"hinted":1,"normal":0}

Comment 10

[Manuel Bucher [:manuel]]

My current theory for the failures in the comment above are:

• The channel from the main html can be created before the channel in the EarlyHint code. Leading to only the normal load reaching the server and the EarlyHint code reaching the cache Edit(2022-05-11): This can't be the case, the early hint channel is always created first.
• From the test_103_redirect_same_origin test case I conclude that if two threads call New_Channel to the same resource it is possible that two http requests are made (Instead of always one http request and the other going into the cache)

I am able to reproduce these test failures locally, so I'll investigate with rr, when I got the test failure recorded with it.

Comment 11

[Manuel Bucher [:manuel]]

(In reply to Manuel Bucher from comment #10)

• From the test_103_redirect_same_origin test case I conclude that if two threads call New_Channel to the same resource it is possible that two http requests are made (Instead of always one http request and the other going into the cache)

This and the other test failures seems to be possible when the early hint request takes too long. I've checked that by adding a delay to the early hint response[1]. Then an additional normal channel is created. This seems worth fixing, because in the real world requests aren't responded to instantly, but take a few more milliseconds than in the test case. There are some ways to work around that:

• Maybe it is possible to fix this in the cache to check if a channel with the same parameters has been opened and reuse the response directly? - Not sure if that is possible in general, as not all responses are cacheable and therefore reuseable.
• When creating the channel in the main doc, check if the early hint preloader already has a channel open: Needs redesign on how the preloader works
• Maybe there are better solutions?

Side note: With my test applied, there are also test failures with two preloads. The count is also off because of the lost update problem. This due to changing the response function to be async ([1]), so shouldn't be a problem in the normal test mode.

[1]: apply the following patch to https://phabricator.services.mozilla.com/D139740?id=577137

diff --git a/netwerk/test/browser/early_hint_pixel.sjs b/netwerk/test/browser/early_hint_pixel.sjs
index 2d0d5d70d4f9a..f227083c41e54 100644
--- a/netwerk/test/browser/early_hint_pixel.sjs
+++ b/netwerk/test/browser/early_hint_pixel.sjs
@@ -1,6 +1,8 @@
 "use strict";
 
-function handleRequest(request, response) {
+let { setTimeout } = ChromeUtils.import("resource://gre/modules/Timer.jsm");
+
+async function handleRequest(request, response) {
   response.setHeader("Content-Type", "image/png", false);
   response.setHeader("Cache-Control", "max-age=604800", false);
 
@@ -25,6 +27,20 @@ function handleRequest(request, response) {
         "bAe1SzDY8gAAAABJRU5ErkJggg=="
     );
   }
+  if (
+    request.hasHeader("X-Moz") &&
+    request.getHeader("X-Moz") === "early hint"
+  ) {
+    response.processAsync();
+    setTimeout(() => {
+      response.write(image);
+      response.finish();
+
+      setSharedState("earlyHintCount", JSON.stringify(count));
+    }, 5000); /* wait 5 seconds 10ms seems enough to create reliable test failures */
+    return;
+  }
+
   setSharedState("earlyHintCount", JSON.stringify(count));
   response.write(image);
 }

Comment 12

[Dragana Damjanovic [:dragana]]

This is a good catch and not an easy one to fix :(
Your description sounds good and it is a real problem.

(In reply to Manuel Bucher from comment #11)

(In reply to Manuel Bucher from comment #10)
There are some ways to work around that:

• Maybe it is possible to fix this in the cache to check if a channel with the same parameters has been opened and reuse the response directly? - Not sure if that is possible in general, as not all responses are cacheable and therefore reuseable.
• When creating the channel in the main doc, check if the early hint preloader already has a channel open: Needs redesign on how the preloader works
• Maybe there are better solutions?

The only other option, which is very similar to your second option, is to store preloaded data into a stream and server the "real" request from the stream and never open a HttpChannel. This is the architecture we wanted to work on in the second phase. It looks like we will need to start working on this soon.

Changing the behavior of the cache will be hard. There are some corner cases that will be hacky to resolve, e.g. what to do when a "real" request waits for the preload response, but the preload gets a response that is not cachable.
One option would be:

• for each "real" request create a HttpChannel and check the preload service
• if the preload service has an outstanding request that has not received OnStartRequest yet, suspend the "real" channel
• resume the "real" channel as soon as OnStartRequest is received.

Since this would be an intermittent solution, I suggest landing this as it is (make the test flexible so that they do not fail) and continue working on phase 2.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/720dc7784a4b
Fix early hint not propagating with http proxy r=necko-reviewers,dragana
https://hg.mozilla.org/integration/autoland/rev/88bc7da6b963
Add EarlyHintPreloader to load 103 Early Hint responses into the cache r=necko-reviewers,ckerschb,dragana,kershaw
https://hg.mozilla.org/integration/autoland/rev/a21cc7514210
Test that the cached image from the early hint preload is used r=necko-reviewers,ckerschb,dragana,kershaw

Comment 14

[Cristina Cozmuta (:CrissCozmuta)]

https://hg.mozilla.org/mozilla-central/rev/720dc7784a4b
https://hg.mozilla.org/mozilla-central/rev/88bc7da6b963
https://hg.mozilla.org/mozilla-central/rev/a21cc7514210