1253794 - 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

Reporter

Description

•

8 years ago

Attached image screenshot — Details

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

Tracy Walker [:tracy]

Updated

•

8 years ago

Blocks: e10s-tests

tracking-e10s: --- → +

Tim Nguyen :ntim

Comment 1

•

8 years ago

Attached patch Refactor browser_net_statistics-02.js test (obsolete) — Details — Splinter Review

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)

Tim Nguyen :ntim

Comment 2

•

8 years ago

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 :/

Tim Nguyen :ntim

Comment 3

•

8 years ago

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.

Tim Nguyen :ntim

Comment 4

•

8 years ago

(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

Tim Nguyen :ntim

Comment 5

•

8 years ago

So the issue here is that we're not waiting for the message manager to initialise.

Comment hidden (Intermittent Failures Robot)

14 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* fx-team: 10
* mozilla-inbound: 3
* try: 1

Platform breakdown:
* linux64: 6
* osx-10-10: 5
* linux32: 2
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1253794&startday=2016-05-30&endday=2016-06-05&tree=all

Jarda Snajdr [:jsnajdr]

Assignee

Comment 7

•

8 years ago

(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.

Alexandre Poirot [:ochameau]

Comment 8

•

8 years ago

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)

Jarda Snajdr [:jsnajdr]

Assignee

Comment 9

•

8 years ago

https://treeherder.mozilla.org/#/jobs?repo=try&revision=65a9fed54751

Jarda Snajdr [:jsnajdr]

Assignee

Comment 10

•

8 years ago

Attached patch Tolerate missing params in sjs_content-type-test-server.sjs, fix intermittent browser_net_statistics failures — Details — Splinter Review

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)

Jarda Snajdr [:jsnajdr]

Assignee

Updated

•

8 years ago

Attachment #8760012 - Attachment is obsolete: true

Alexandre Poirot [:ochameau]

Comment 11

•

8 years ago

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+

Jarda Snajdr [:jsnajdr]

Assignee

Updated

•

8 years ago

Keywords: checkin-needed

Jarda Snajdr [:jsnajdr]

Assignee

Updated

•

8 years ago

Blocks: 1134073

Pulsebot

Comment 12

•

8 years ago

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

Tim Nguyen :ntim

Updated

•

8 years ago

Assignee: ntim.bugs → jsnajdr

Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)

Comment 13

•

8 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/6a6cb441259d

Status: ASSIGNED → RESOLVED

Closed: 8 years ago

status-firefox50: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → Firefox 50

Tim Nguyen :ntim

Comment 14

•

8 years ago

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?

Liz Henry (:lizzard) (relman/hg->git project)

Comment 15

•

8 years ago

Tracking for 49

status-firefox49: --- → affected

tracking-firefox49: --- → +

Liz Henry (:lizzard) (relman/hg->git project)

Comment 16

•

8 years ago

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+

J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)

Comment 17

•

8 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/4f016f425e75

status-firefox49: affected → fixed

BMO Automation

Updated

•

6 years ago

Product: Firefox → DevTools

screenshot 8 years ago Ryan VanderMeulen [:RyanVM] 282.34 KB, image/png		Details
Refactor browser_net_statistics-02.js test 8 years ago Tim Nguyen :ntim 2.93 KB, patch		Details \| Diff \| Splinter Review
Tolerate missing params in sjs_content-type-test-server.sjs, fix intermittent browser_net_statistics failures 8 years ago Jarda Snajdr [:jsnajdr] 2.71 KB, patch	ochameau : review+ lizzard : approval-mozilla-aurora+	Details \| Diff \| Splinter Review