Content download wrong for cached requests

[paulb-elastic]

It seems that the content download for a network request are incorrect and filling up the duration of the step, for cached network requests.

Specifically, if the script is configured to wait for something to appear on the page, irrespective of the load state (a common use case to wait for and assert that some content exists on the page), the content download is being reported as the duration of that step (i.e. the step duration, not the network download time).

No further investigation has been done to determine if this is an Uptime, or Synthetics Agent issues.

In the following example, a network request is made for blueBox.jpg and greenBox.jpg. Each of these is ~1KB in size, and we can see they are downloading pretty quickly as expected, on step 1:

However, if the page is cached (for example, revisiting exactly the same page), and we are waiting for some content, the content download is reported as being too long:

Steps to reproduce:

Create a monitor with the following script:

step("My Page", async () => {
   await page.goto('https://paulb-elastic.github.io/testPageWithCounter.html');
   await page.waitForSelector('#counter >> text=Seconds since page loaded: 2');
});
step("Cached version of My Page", async () => {
   await page.goto('https://paulb-elastic.github.io/testPageWithCounter.html');
   await page.waitForSelector('#counter >> text=Seconds since page loaded: 2');
});

Note that this script simply visits the same page twice. The page being loaded simply has a counter which increments each second. For each of these (same) steps, it waits for the counter to reach 2 seconds before the step is complete.

You will see in step 1, the content download for blueBox.jpg (and greenBox.jpg) is correct and very quick (even though the step still had to wait for 2 seconds before it could move onto step 2 (see screenshot above).

In step 2, blueBox.jpg and greenBox.jpg are cached as they were already downloaded in step 1. Here, the content download is incorrect and seems to be over 2 seconds, which relates to how long the step was running before it completed (see screenshot above).

[vigneshshanmugam]

Seems like the reported events from Synthetics agent is wrong.

https://paulb-elastic.github.io/blueBox.jpg {
  blocked: 0.2500000118743628,
  queueing: -1,
  proxy: -1,
  dns: -1,
  ssl: -1,
  connect: -1,
  send: 0.12499999138526618,
  wait: 21.37500001117587,
  receive: 2235.8749999839347,
  total: 2257.62499999837
}
https://paulb-elastic.github.io/greenBox.jpg {
  blocked: 0.12499999138526618,
  queueing: -1,
  proxy: -1,
  dns: -1,
  ssl: -1,
  connect: -1,
  send: 0,
  wait: 23.75000002211891,
  receive: 2233.6249999934807,
  total: 2257.500000006985
}

Performance metrics are indeed reported correctly.

{
  perfMetrics: {
    cls: 0.014375325520833333,
    fcp: { us: 40000 },
    lcp: { us: 40000 },
    dcl: { us: 33250 },
    load: { us: 33875 }
  }
}

We are not handling the resources that are loaded from cache on successive runs correctly. However if we are moving to the newer version of PW, we can bring the new logic that works on top of PW events https://github.com/elastic/synthetics/pull/372 and not need to handle these manually.

[vigneshshanmugam]

Timed boxed this issue and confirmed this is an edge case and we can defer it along with updating PW version which would require rewriting the logic around Network timing information along with fixing popups and requests on subsequent pages.

Moving this to backlog.