1429803 - Response header columns are only populated after opening the request sidebar

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P1)

Description

[Tim Nguyen :ntim]

STR:
- Enable some response header columns from the header context menu

Those column cells are empty until the request is actually selected.

Comment 1

[Marius Coman [:mcoman], Ecosystem QA]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:59.0) Gecko/20100101 Firefox/59.0
Firefox: 59.0a1, Build ID 20180111220102

I have managed to reproduce the issue on Windows 10 x64, Ubuntu 14.04 x64 and Mac 10.12 with the latest Nightly (59.0a1) build installed.
Haven't managed to reproduce it with the lastest Firefox Release (57.0.4) and Firefox Beta/Dev edition 58.0b15.
Considering this, using the Mozregression tool, I have found the regression window:

Last good revision: db713228c8e317cbc8e549edce7019b97ebd1b0b
First bad revision: 6111cfdd4f938c15e8f8e165b40e31bcac5c849c
Pushlog:
https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=db713228c8e317cbc8e549edce7019b97ebd1b0b&tochange=6111cfdd4f938c15e8f8e165b40e31bcac5c849c

From the pushlog it seems that the Bug 1418927 has caused the regression. However, after reading the comments it seems that the behavior could be somehow intended. I don't know exactly what "lazily" exactly means in this case.

Ricky, could you please give us your opinion regarding this? Is it intended or it is really a regression caused by your change?

Comment 2

[Ricky Chien [:rickychien] (inactive)]

Lazily is the way we refactor internal architecture in order to mitigate performance issue. Therefore, the behavior is supposed to be the same. I can confirm this bug report is right, this is a new regression from bug 1418927. Thanks

Comment 3

[Patrick Brosset <:pbro>]

Hi Ricky: how confident are we in getting a fix on time for this for FF59? Also, how bad is it?
Honza: same question?

Comment 4

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

Attachment: Bug 1429803 - Properly populate response header columns;

Review commit: https://reviewboard.mozilla.org/r/213632/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/213632/

Comment 5

[Ricky Chien [:rickychien] (inactive)]

Comment on attachment 8943318 [details]
Bug 1429803 - Properly populate response header columns;

https://reviewboard.mozilla.org/r/213632/#review219552

LGTM for this patch. It works for me. Thank you Honza for the quick fix :)

::: devtools/client/netmonitor/src/components/RequestListColumnResponseHeader.js:11
(Diff revision 1)
>  
>  const { Component } = require("devtools/client/shared/vendor/react");
>  const dom = require("devtools/client/shared/vendor/react-dom-factories");
>  const PropTypes = require("devtools/client/shared/vendor/react-prop-types");
>  const { getResponseHeader } = require("../utils/request-utils");
> +const { fetchNetworkUpdatePacket } = require("../utils/request-utils");

nit: we're importing two "../utils/request-utils" here. Please merge them into one.

::: devtools/client/netmonitor/src/components/RequestListItem.js:255
(Diff revision 1)
>          columns.responseTime &&
>            RequestListColumnResponseTime({ item, firstRequestStartedMillis }),
>          columns.duration && RequestListColumnDuration({ item }),
>          columns.latency && RequestListColumnLatency({ item }),
>          ...RESPONSE_HEADERS.filter(header => columns[header]).map(
> -          header => RequestListColumnResponseHeader({ item, header }),
> +          header => RequestListColumnResponseHeader({ connector, item, header }),

nit: format these properties into multi-lines.

Comment 6

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

Comment on attachment 8943318 [details]
Bug 1429803 - Properly populate response header columns;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/213632/diff/1-2/

Comment 7

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

(In reply to Ricky Chien [:rickychien] from comment #5)
> Comment on attachment 8943318 [details]
> Bug 1429803 - Properly populate response header columns;
> 
> https://reviewboard.mozilla.org/r/213632/#review219552
> 
> LGTM for this patch. It works for me. Thank you Honza for the quick fix :)

Thanks for the review Ricky!
All review comments resolved.

Honza

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a4a6b952ba39
Properly populate response header columns; r=rickychien

Comment 9

[Dorel Luca [:dluca]]

Backed out changeset a4a6b952ba39 (bug 1429803) for devtools failure on devtools/client/netmonitor/test/browser_net_columns_showhide.js

https://treeherder.mozilla.org/logviewer.html#?job_id=157161364&repo=autoland&lineNumber=9407

https://hg.mozilla.org/integration/autoland/rev/677af3c4c901b9b7e3b2ae1054cfcc6bed1b3aa8

https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=a4a6b952ba39cb2ecf9bf3de217f61b1b1b143cd&selectedJob=157161364

Comment 10

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

(In reply to Dorel Luca [:dluca] from comment #9)
> Backed out changeset a4a6b952ba39 (bug 1429803) for devtools failure on
> devtools/client/netmonitor/test/browser_net_columns_showhide.js
> 
> https://treeherder.mozilla.org/logviewer.
> html#?job_id=157161364&repo=autoland&lineNumber=9407
The failure indicates that RDP packet is received after the test finishes.

--

My patch appends lazy loading of response headers when RequestListColumnResponseHeader columns is rendered.
I tried to fix this by displaying the `Connection` column (one of those that lazy loads response headers) by default in all tests, so it lazy-loads response headers by default - just like it does e.g. for cookies.

Here is the array that defines the default columns for tests:
https://searchfox.org/mozilla-central/rev/2031c0f517185b2bd0e8f6f92f9491b3410c1f7f/devtools/client/netmonitor/test/head.js#98

It fixes the problem for response-headers but, now I am seeing that event-timings packet is received after the tests finishes.

Alex, could this be related to the work in Bug 1425273?
Or could this indicate that `waitForNetworkEvents` (heads.js) doesn't wait for all events? Perhaps for those that has been initiated lazily?

Honza

Here is the test failures


  TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net_columns_showhide.js | A promise chain failed to handle a rejection: 'getEventTimings' active request packet to 'server1.conn0.child1/netEvent28' can't be sent as the connection just closed. - stack: null
Rejection date: Fri Jan 19 2018 11:48:37 GMT+0100 - false == true - JS frame :: resource://testing-common/PromiseTestUtils.jsm :: assertNoUncaughtRejections :: line 253
Stack trace:
    resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:253
    chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:703
    testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1361:11
    run@chrome://mochikit/content/browser-test.js:1298:9

Comment 11

[Alexandre Poirot [:ochameau]]

(In reply to Jan Honza Odvarko [:Honza] from comment #10)
> (In reply to Dorel Luca [:dluca] from comment #9)
> > Backed out changeset a4a6b952ba39 (bug 1429803) for devtools failure on
> > devtools/client/netmonitor/test/browser_net_columns_showhide.js
> > 
> > https://treeherder.mozilla.org/logviewer.
> > html#?job_id=157161364&repo=autoland&lineNumber=9407
> The failure indicates that RDP packet is received after the test finishes.
> 
> --
> 
> My patch appends lazy loading of response headers when
> RequestListColumnResponseHeader columns is rendered.
> I tried to fix this by displaying the `Connection` column (one of those that
> lazy loads response headers) by default in all tests, so it lazy-loads
> response headers by default - just like it does e.g. for cookies.
> 
> Here is the array that defines the default columns for tests:
> https://searchfox.org/mozilla-central/rev/
> 2031c0f517185b2bd0e8f6f92f9491b3410c1f7f/devtools/client/netmonitor/test/
> head.js#98

This list looks quite arbitrary?
 * Why not use default columns?
 * Why not use all possible columns?
Is there any basic theory on what column should and should not be in this list?
It looks like the full list of all columns are here:
  https://searchfox.org/mozilla-central/source/devtools/client/netmonitor/src/reducers/ui.js#25-51
Whereas the default list is set here:
  https://searchfox.org/mozilla-central/source/devtools/client/preferences/devtools.js#167-169
Is it all columns but the lazy one?

I think it is important to figure this out before modifying the default list of columns used in tests.
Without any background history on this I would only display default columns, or all of them.

> It fixes the problem for response-headers but, now I am seeing that
> event-timings packet is received after the tests finishes.

Surprising. It may highlight a race condition.
We were not waiting for event-timings correctly somewhere and the additional response-headers requests make their lazy fetching visible.

> Alex, could this be related to the work in Bug 1425273?
> Or could this indicate that `waitForNetworkEvents` (heads.js) doesn't wait
> for all events? Perhaps for those that has been initiated lazily?

Exactly, waitForNetworkEvents only waits for EVENTS.NETWORK_EVENT and EVENTS.PAYLOAD_READY.
So, it looks for any new request (EVENTS.NETWORK_EVENT) and for each new request, wait for the related EVENTS.PAYLOAD_READY event which is sent when all non-lazy fields are retrieved.
Because of that, it won't wait for the lazy fetching of response headers, nor any lazy fetched field.

>   TEST-UNEXPECTED-FAIL |
> devtools/client/netmonitor/test/browser_net_columns_showhide.js | A promise
> chain failed to handle a rejection: 'getEventTimings' active request packet
> to 'server1.conn0.child1/netEvent28' can't be sent as the connection just
> closed. - stack: null
> Rejection date: Fri Jan 19 2018 11:48:37 GMT+0100 - false == true - JS frame
> :: resource://testing-common/PromiseTestUtils.jsm ::
> assertNoUncaughtRejections :: line 253
> Stack trace:
>    
> resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:253
>     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:703
>     testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1361:11
>     run@chrome://mochikit/content/browser-test.js:1298:9

I'm not reproducing this exception, I still get the response header one with this patch:

diff --git a/devtools/client/netmonitor/test/head.js b/devtools/client/netmonitor/test/head.js
index 64cdd6b4d282..584317806bb9 100644
--- a/devtools/client/netmonitor/test/head.js
+++ b/devtools/client/netmonitor/test/head.js
@@ -101,7 +101,9 @@ Services.prefs.setCharPref(
   "[\"cause\",\"contentSize\",\"cookies\",\"domain\",\"duration\"," +
   "\"endTime\",\"file\",\"latency\",\"method\",\"protocol\"," +
   "\"remoteip\",\"responseTime\",\"scheme\",\"setCookies\"," +
-  "\"startTime\",\"status\",\"transferred\",\"type\",\"waterfall\"]"
+  "\"startTime\",\"status\",\"transferred\",\"type\"," +
+  "\"Cache-Control\",\"Connection\",\"Content-Encoding\",\"Content-Length\"," +
+  "\"ETag\",\"Keep-Alive\",\"Last-Modified\",\"Server\",\"Vary\",\"waterfall\"]"
 );


Otherwise, to fix the original test failure without modifying the default column,
you may tweak this test to wait for lazy requests with something like this:
  let onDataReceived = waitFor(monitor.panelWin, EVENTS.RECEIVED_EVENT_TIMINGS);
  let onDataReceived = waitFor(monitor.panelWin, EVENTS.RECEIVED_RESPONSE_HEADERS);
or, use waitFor against each column to wait for the content to be loaded.
This test seems to only assert the header line, with column title,
but it doesn't verify that requests lines gets the data correctly displayed.
And more importantly, it doesn't wait for the table cells to be updated with the new column data.

Finally, I don't know if you looked at what actually happens during this test?
It basically freeze from the beginning up to the end of it.
The whole test seems synchronous and freeze firefox.
It would be sane to add some executeSoon call between each action to let a chance to firefox to render some frames!

Comment 12

[Andrew Overholt [:overholt]]

As an outside observer, it looks like maybe a needinfo for comment 11 is in order here :)

Comment 13

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

Attachment: Bug 1429803 - Fix test;

Review commit: https://reviewboard.mozilla.org/r/220238/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/220238/

Comment 14

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

Comment on attachment 8943318 [details]
Bug 1429803 - Properly populate response header columns;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/213632/diff/2-3/

Comment 15

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

(In reply to Andrew Overholt [:overholt] from comment #12)
> As an outside observer, it looks like maybe a needinfo for comment 11 is in
> order here :)
Thanks, this is on top of my list, but I was off Monday+Tuesday.


(In reply to Alexandre Poirot [:ochameau] from comment #11)
Thanks for tips!

I am attaching a patch:
- not modifying the default set of cols
- using waitForTick() to do stuff async and force repaint.

Honza

Comment 16

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

Try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bb9fa4dba3e6dd8fdef898acc2bbc18ccc346c11

Honza

Comment 17

[Alexandre Poirot [:ochameau]]

Comment on attachment 8950980 [details]
Bug 1429803 - Fix test;

https://reviewboard.mozilla.org/r/220238/#review226116

Looks good, but please address the possible races I commented about.

::: devtools/client/netmonitor/test/browser_net_columns_showhide.js:27
(Diff revision 1)
>  
> +  let item = getSortedRequests(store.getState()).get(0);
> +  ok(item.responseHeadersAvailable, "headers are available for lazily fetching");
> +
> +  if (item.responseHeadersAvailable && !item.responseHeaders) {
> +    requestData(item.id, "responseHeaders");

You may call use await here to wait for its full processing. If you fix the other comments, it should work fine.

::: devtools/client/netmonitor/test/browser_net_columns_showhide.js:30
(Diff revision 1)
> +
> +  if (item.responseHeadersAvailable && !item.responseHeaders) {
> +    requestData(item.id, "responseHeaders");
> +  }
> +
> +  await waitFor(monitor.panelWin, EVENTS.RECEIVED_RESPONSE_HEADERS);

This code is subject to races.

* You are waiting for `EVENTS.RECEIVED_RESPONSE_HEADERS` *after* the action that is meant to dispatch this event (i.e. `requestData(item.id, "responseHeaders");`)
* You are waiting for `EVENTS.RECEIVED_RESPONSE_HEADERS` even if you don't call `requestData(item.id, "responseHeaders");`, (i.e. when item.responseHeadersAvailable is false or item.responseHeaders is true)

::: devtools/client/netmonitor/test/browser_net_columns_showhide.js:68
(Diff revision 1)
>  
>    info(`Right clicking on white-space in the header to get the context menu`);
>    EventUtils.sendMouseEvent({ type: "contextmenu" },
>      document.querySelector(".devtools-toolbar.requests-list-headers"));
>  
> +  await waitForTick();

Could you add a comment explaining why we call waitForTick. At least for the first one.

Comment 18

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

Comment on attachment 8950980 [details]
Bug 1429803 - Fix test;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/220238/diff/1-2/

Comment 19

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

(In reply to Alexandre Poirot [:ochameau] from comment #17)
> You may call use await here to wait for its full processing. If you fix the
> other comments, it should work fine.
True

> This code is subject to races.
Removed

> Could you add a comment explaining why we call waitForTick. At least for the
> first one.
Done 

Thanks,
Honza


Try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5b7e6a5a647fc049a02ed60ad774dbb5ea1904ef

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/83a578a1c62d
Properly populate response header columns; r=rickychien
https://hg.mozilla.org/integration/autoland/rev/8592fd84fc79
Fix test; r=ochameau

Comment 21

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/83a578a1c62d
https://hg.mozilla.org/mozilla-central/rev/8592fd84fc79

Comment 22

[Ryan VanderMeulen [:RyanVM]]

Is this something you were intending to request uplift on still? it's getting late in the 59 cycle if the answer is yes :)

Comment 23

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

Comment on attachment 8943318 [details]
Bug 1429803 - Properly populate response header columns;

Approval Request Comment
[Feature/Bug causing the regression]: bug 1418927
[User impact if declined]: Missing data in Network panel (DevTools) in some cases.
[Is this code covered by automated tests?]: yes
[Has the fix been verified in Nightly?]: yes
[Needs manual test from QE? If yes, steps to reproduce]: no
[List of other uplifts needed for the feature/fix]: n/a
[Is the change risky?]: rather low risk
[Why is the change risky/not risky?]: only related to developers, rather small patch and already tested
[String changes made/needed]: n/a

Comment 24

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

Comment on attachment 8950980 [details]
Bug 1429803 - Fix test;

Approval Request Comment
[Feature/Bug causing the regression]: bug 1418927
[User impact if declined]: Missing data in Network panel (DevTools) in some cases.
[Is this code covered by automated tests?]: yes
[Has the fix been verified in Nightly?]: yes
[Needs manual test from QE? If yes, steps to reproduce]: no
[List of other uplifts needed for the feature/fix]: n/a
[Is the change risky?]: rather low risk
[Why is the change risky/not risky?]: only related to developers, rather small patch and already tested
[String changes made/needed]: n/a

Comment 25

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8943318 [details]
Bug 1429803 - Properly populate response header columns;

Fix for a new devtools regression in 59. Taking for 59b12 so we don't ship it.

Comment 26

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/releases/mozilla-beta/rev/0c6c5ed366a6
https://hg.mozilla.org/releases/mozilla-beta/rev/b7844162c4fa