Closed Bug 1253794 Opened 4 years ago Closed 3 years ago

Intermittent e10s browser_net_statistics-02.js | Test timed out | Found a tab after previous test timed out: http://example.com/browser/devtools/client/netmonitor/test/html_statistics-test-page.html

Categories

(DevTools :: Netmonitor, defect)

Unspecified
macOS
defect
Not set

Tracking

(e10s+, firefox49+ fixed, firefox50 fixed)

RESOLVED FIXED
Firefox 50
Tracking Status
e10s + ---
firefox49 + fixed
firefox50 --- fixed

People

(Reporter: RyanVM, Assigned: jsnajdr)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

Attached image screenshot
https://treeherder.mozilla.org/logviewer.html#?job_id=23056339&repo=mozilla-inbound

16:17:06     INFO -  209 INFO TEST-START | devtools/client/netmonitor/test/browser_net_statistics-02.js
16:17:06     INFO -  Handler function NetworkEventActorProxy.addResponseContent threw an exception: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js :: NetworkEventActorProxy.methodFactory/< :: line 1386"  data: no]
16:17:06     INFO -  Stack: NetworkEventActorProxy.methodFactory/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:1386:5
16:17:06     INFO -  exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
16:17:06     INFO -  NRL__onComplete@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:402:5
16:17:06     INFO -  NRL_onStreamClose@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:362:7
16:17:06     INFO -  NRL_onInputStreamReady@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:451:7
16:17:06     INFO -  Line: 1386, column: 0
16:17:06     INFO -  console.error:
16:17:06     INFO -    Handler function NetworkEventActorProxy.addResponseContent threw an exception: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js :: NetworkEventActorProxy.methodFactory/< :: line 1386"  data: no]
16:17:06     INFO -  Stack: NetworkEventActorProxy.methodFactory/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:1386:5
16:17:06     INFO -  exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
16:17:06     INFO -  NRL__onComplete@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:402:5
16:17:06     INFO -  NRL_onStreamClose@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:362:7
16:17:06     INFO -  NRL_onInputStreamReady@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:451:7
16:17:06     INFO -  Line: 1386, column: 0
16:17:06     INFO -  Handler function NetworkEventActorProxy.addResponseContent threw an exception: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js :: NetworkEventActorProxy.methodFactory/< :: line 1386"  data: no]
16:17:06     INFO -  Stack: NetworkEventActorProxy.methodFactory/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:1386:5
16:17:06     INFO -  exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
16:17:06     INFO -  NRL__onComplete@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:402:5
16:17:06     INFO -  NRL_onStreamClose@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:362:7
16:17:06     INFO -  NRL_onInputStreamReady@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:451:7
16:17:06     INFO -  Line: 1386, column: 0
16:17:06     INFO -  console.error:
16:17:06     INFO -    Handler function NetworkEventActorProxy.addResponseContent threw an exception: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js :: NetworkEventActorProxy.methodFactory/< :: line 1386"  data: no]
16:17:06     INFO -  Stack: NetworkEventActorProxy.methodFactory/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:1386:5
16:17:06     INFO -  exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
16:17:06     INFO -  NRL__onComplete@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:402:5
16:17:06     INFO -  NRL_onStreamClose@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:362:7
16:17:06     INFO -  NRL_onInputStreamReady@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/webconsole/network-monitor.js:451:7
16:17:06     INFO -  Line: 1386, column: 0
16:17:51     INFO -  TEST-INFO | started process screencapture
16:17:51     INFO -  TEST-INFO | screencapture: exit 0
16:17:51     INFO -  210 INFO checking window state
16:17:51     INFO -  211 INFO Initializing a network monitor pane.
16:17:51     INFO -  212 INFO Adding tab: http://example.com/browser/devtools/client/netmonitor/test/html_statistics-test-page.html
16:17:51     INFO -  213 INFO Net tab added successfully: http://example.com/browser/devtools/client/netmonitor/test/html_statistics-test-page.html
16:17:51     INFO -  214 INFO Target remoted.
16:17:51     INFO -  215 INFO Console message: [JavaScript Error: "no element found" {file: "http://example.com/browser/devtools/client/netmonitor/test/sjs_content-type-test-server.sjs?sts=304&fmt=xml" line: 1}]
16:17:51     INFO -  216 INFO Cache disabled when the current and all future toolboxes are open.
16:17:51     INFO -  217 INFO TEST-PASS | devtools/client/netmonitor/test/browser_net_statistics-02.js | Request to reconfigure the tab was recorded. -
16:17:51     INFO -  218 INFO Console message: [JavaScript Error: "no element found" {file: "http://example.com/browser/devtools/client/netmonitor/test/sjs_content-type-test-server.sjs?sts=304&fmt=xml" line: 1}]
16:17:51     INFO -  219 INFO Netork monitor pane shown successfully.
16:17:51     INFO -  220 INFO Starting test...
16:17:51     INFO -  221 INFO TEST-PASS | devtools/client/netmonitor/test/browser_net_statistics-02.js | The initial frontend mode is correct. -
16:17:51     INFO -  222 INFO Console message: [JavaScript Error: "no element found" {file: "http://example.com/browser/devtools/client/netmonitor/test/sjs_content-type-test-server.sjs?sts=304&fmt=xml" line: 1}]
16:17:51     INFO -  223 INFO TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net_statistics-02.js | Test timed out -
16:17:51     INFO -  224 INFO finish() was called, cleaning up...
16:17:51     INFO -  MEMORY STAT | vsize 3662MB | residentFast 637MB | heapAllocated 134MB
16:17:51     INFO -  225 INFO TEST-OK | devtools/client/netmonitor/test/browser_net_statistics-02.js | took 45043ms
16:17:51     INFO -  Not taking screenshot here: see the one that was previously logged
16:17:51     INFO -  226 INFO TEST-UNEXPECTED-FAIL | devtools/client/netmonitor/test/browser_net_statistics-02.js | Found a tab after previous test timed out: http://example.com/browser/devtools/client/netmonitor/test/html_statistics-test-page.html -
16:17:51     INFO -  227 INFO checking window state
Blocks: e10s-tests
tracking-e10s: --- → +
Not sure it fixed the intermittent since I couldn't reproduce it locally.
Assignee: nobody → ntim.bugs
Status: NEW → ASSIGNED
Attachment #8760012 - Flags: review?(poirot.alex)
Looks like it's still happening:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=7fddea9e513438a8da1f5d08b11d95ef66dde0ff&selectedJob=21993909

I'm using the only platform where it's not happening :/
Try push with `devtools.dump.emit` --> true: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f1716b4ed77bb105218bf478a1efeb1efb469a5a&selectedJob=21994874

It seems like EVENTS.PRIMED_CACHE_CHART_DISPLAYED and EVENTS.EMPTY_CACHE_CHART_DISPLAYED are never emitted when the test fails, which causes the test to timeout.
(In reply to Tim Nguyen :ntim from comment #3)
> Try push with `devtools.dump.emit` --> true:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=f1716b4ed77bb105218bf478a1efeb1efb469a5a&selectedJob=2
> 1994874
> 
> It seems like EVENTS.PRIMED_CACHE_CHART_DISPLAYED and
> EVENTS.EMPTY_CACHE_CHART_DISPLAYED are never emitted when the test fails,
> which causes the test to timeout.

This is probably caused by errors on NetworkEventActorProxy
So the issue here is that we're not waiting for the message manager to initialise.
(In reply to Tim Nguyen :ntim from comment #5)
> So the issue here is that we're not waiting for the message manager to
> initialise.

These errors mean that network events from parent are coming even after the toolbox was closed and the message manager is closed, too.

I build Firefox on an Ubuntu 16.04 vmware image and all the tests are still passing - I can't reproduce the failure even on linux64.

I'll be investigating this now.
Comment on attachment 8760012 [details] [diff] [review]
Refactor browser_net_statistics-02.js test

Review of attachment 8760012 [details] [diff] [review]:
-----------------------------------------------------------------

::: devtools/client/netmonitor/test/browser_net_statistics-02.js
@@ +20,5 @@
> +    waitFor(panel, EVENTS.EMPTY_CACHE_CHART_DISPLAYED)
> +  ]);
> +
> +  info("Switching to statistics view and waiting for it to display");
> +  NetMonitorView.toggleFrontendMode();

Isn't it showNetworkStatisticsView that is failing?
http://mxr.mozilla.org/mozilla-central/source/devtools/client/netmonitor/netmonitor-view.js#282
(it is called by toggleFrontedMode)
It seems to yield on many things before creating primed and empty cache

Could be worth putting debugs there...
Attachment #8760012 - Flags: review?(poirot.alex)
So, the problem seems to be this:

The html_statistics-test-page.html page sends a few requests to sjs_content-type-test-server.sjs, two of them are:

get("sjs_content-type-test-server.sjs?sts=304&fmt=html");
get("sjs_content-type-test-server.sjs?sts=304&fmt=jsonp");

However, the "html" servlet fails when a "content" param is missing, and the "jsonp" servlet fails when a "fun" param is missing. They throw a TypeError and never return any response.

In netmonitor-view.js, there is a function whenDataAvailable that waits until all the responses arrive. If it waits also for the "html" and "jsonp" requests, it will wait forever.

But it doesn't always wait for them. It only waits for the requests that happen to be already in "requestsView.attachments" array when the wait is initiated in showNetworkStatisticsView. And this is quite a random object - immediately after triggering the reload, it's usually empty, or contains only a few requests that were already initiated. Only when it happens to contain also the "html" and "jsonp" requests, which doesn't always happen, does it lead to test timeout and failure.

I fixed this by making sjs_content-type-test-server.sjs tolerate the missing params.

The "right" fix should include fixing the showNetworkStatisticsView function which seems to be broken - it's not well defined how long and for how many network events it should wait before gathering the statistics and displaying the charts. But my main purpose here is to fix the intermittents that are blocking landing of bug 1134073.

Let's see if the try run fixes things.
Attachment #8760180 - Flags: review?(poirot.alex)
Attachment #8760012 - Attachment is obsolete: true
Comment on attachment 8760180 [details] [diff] [review]
Tolerate missing params in sjs_content-type-test-server.sjs, fix intermittent browser_net_statistics failures

Review of attachment 8760180 [details] [diff] [review]:
-----------------------------------------------------------------

::: devtools/client/netmonitor/test/sjs_content-type-test-server.sjs
@@ +77,5 @@
>          response.finish();
>          break;
>        }
>        case "html": {
> +        let content = (params.filter((s) => s.includes("res="))[0] || "").split("=")[1];

Note the existence of URL() constructor:
let url = new URL("htpp://foo.com/?query=string");
url.searchParams.has("query") == true
url.searchParams.get("query") = "string"
url.searchParams.get("not-set") = null
url.searchParams.getAll("query") = ["string"]
...

But I'm not 100% sure it is available within sjs scope.
Attachment #8760180 - Flags: review?(poirot.alex) → review+
Keywords: checkin-needed
Blocks: 1134073
Pushed by pbrosset@mozilla.com:
https://hg.mozilla.org/integration/fx-team/rev/6a6cb441259d
Tolerate missing params in sjs_content-type-test-server.sjs, fix intermittent browser_net_statistics failures r=ochameau
Keywords: checkin-needed
Assignee: ntim.bugs → jsnajdr
https://hg.mozilla.org/mozilla-central/rev/6a6cb441259d
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 50
Comment on attachment 8760180 [details] [diff] [review]
Tolerate missing params in sjs_content-type-test-server.sjs, fix intermittent browser_net_statistics failures

Approval Request Comment
[Feature/regressing bug #]: dependency for bug 1134073
[User impact if declined]: 
[Describe test coverage new/current, TreeHerder]: fixes intermittents
[Risks and why]: low, 3 line change 
[String/UUID change made/needed]: no
Attachment #8760180 - Flags: approval-mozilla-aurora?
Tracking for 49
Comment on attachment 8760180 [details] [diff] [review]
Tolerate missing params in sjs_content-type-test-server.sjs, fix intermittent browser_net_statistics failures

Please uplift to aurora before bug 1134073 uplift
Attachment #8760180 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.