Closed Bug 1115779 Opened 5 years ago Closed 3 years ago

Intermittent browser_wa_destroy-node-01.js | Test timed out | Found a tab after previous test timed out: doc_destroy-nodes.html

Categories

(DevTools Graveyard :: Web Audio Editor, defect)

All
Linux
defect
Not set

Tracking

(firefox36 unaffected, firefox37 fixed, firefox47 affected, firefox48 fixed, firefox49 fixed, firefox-esr31 unaffected, firefox50 fixed)

RESOLVED FIXED
Firefox 49
Tracking Status
firefox36 --- unaffected
firefox37 --- fixed
firefox47 --- affected
firefox48 --- fixed
firefox49 --- fixed
firefox-esr31 --- unaffected
firefox50 --- fixed

People

(Reporter: KWierso, Assigned: efaust)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 3 obsolete files)

13:29:40 INFO - 3388 INFO TEST-START | browser/devtools/webaudioeditor/test/browser_wa_destroy-node-01.js
13:29:50 INFO - -*-*- UserCustomizations (child): document created: http://example.com/browser/browser/devtools/webaudioeditor/test/doc_destroy-nodes.html
13:29:50 INFO - -*-*- UserCustomizations (child): _injectInWindow
13:29:50 INFO - -*-*- UserCustomizations (child): principal status: 0
13:29:51 INFO - JavaScript warning: chrome://browser/content/devtools/d3.js, line 479: mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create
13:29:52 INFO - -*-*- UserCustomizations (child): document created: http://example.com/browser/browser/devtools/webaudioeditor/test/doc_destroy-nodes.html
13:29:52 INFO - -*-*- UserCustomizations (child): _injectInWindow
13:29:52 INFO - -*-*- UserCustomizations (child): principal status: 0
13:30:25 INFO - Xlib: extension "RANDR" missing on display ":0".
13:30:27 INFO - TEST-INFO | screentopng: exit 0
13:30:27 INFO - 3389 INFO checking window state
13:30:27 INFO - 3390 INFO Entering test
13:30:27 INFO - 3391 INFO Initializing a web audio editor pane.
13:30:27 INFO - 3392 INFO Adding tab: http://example.com/browser/browser/devtools/webaudioeditor/test/doc_destroy-nodes.html
13:30:27 INFO - 3393 INFO Tab added and finished loading: http://example.com/browser/browser/devtools/webaudioeditor/test/doc_destroy-nodes.html
13:30:27 INFO - 3394 INFO Console message: [JavaScript Warning: "mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create" {file: "chrome://browser/content/devtools/d3.js" line: 479}]
13:30:27 INFO - 3395 INFO Waiting for event: 'start-context' on [Front for webaudio/conn266.child2/webaudioActor7].
13:30:27 INFO - 3396 INFO Waiting for event: 'navigate' on TabTarget:[object XULElement].
13:30:27 INFO - 3397 INFO Console message: [JavaScript Warning: "Unexpected value strokewidth parsing markerUnits attribute." {file: "chrome://browser/content/devtools/d3.js" line: 589}]
13:30:27 INFO - 3398 INFO Waiting for event: 'WebAudioEditor:UIInspectorNodeSet' on [object ChromeWindow].
13:30:27 INFO - 3399 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3400 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3401 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3402 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3403 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3404 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3405 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3406 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3407 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3408 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3409 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3410 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3411 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3412 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3413 INFO Console message: [JavaScript Warning: "Error in parsing value for 'text-anchor'. Declaration dropped." {file: "chrome://browser/content/devtools/webaudioeditor.xul" line: 0 column: 0 source: "left"}]
13:30:27 INFO - 3414 INFO Console message: [JavaScript Warning: "Unexpected value strokewidth parsing markerUnits attribute." {file: "chrome://browser/content/devtools/d3.js" line: 589}]
13:30:27 INFO - 3415 INFO TEST-UNEXPECTED-FAIL | browser/devtools/webaudioeditor/test/browser_wa_destroy-node-01.js | Test timed out - expected PASS
13:30:27 INFO - 3416 INFO TEST-OK | browser/devtools/webaudioeditor/test/browser_wa_destroy-node-01.js | took 46159ms
13:30:27 INFO - 3417 INFO TEST-UNEXPECTED-FAIL | browser/devtools/webaudioeditor/test/browser_wa_destroy-node-01.js | Found a tab after previous test timed out: http://example.com/browser/browser/devtools/webaudioeditor/test/doc_destroy-nodes.html - expected PASS
13:30:27 INFO - *************************
13:30:27 INFO - A coding exception was thrown in a Promise resolution callback.
13:30:27 INFO - See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
13:30:27 INFO - Full message: TypeError: this.docShell is null
13:30:27 INFO - Full stack: get_webNavigation@chrome://global/content/bindings/general.xml:94:1
13:30:27 INFO - get_contentDocument@chrome://global/content/bindings/general.xml:97:1
13:30:27 INFO - Toolbox.prototype.doc@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:241:5
13:30:27 INFO - Toolbox.prototype.destroyHost@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:1582:1
13:30:27 INFO - Toolbox.prototype.destroy/this._destroyer<@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:1661:19
13:30:27 INFO - Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:870:23
13:30:27 INFO - this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:749:7
13:30:27 INFO - this.PromiseWalker.scheduleWalkerLoop/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:691:37
13:30:27 INFO - *************************
13:30:27 INFO - console.error:
13:30:27 INFO - Message: TypeError: this.docShell is null
13:30:27 INFO - Stack:
13:30:27 INFO - get_webNavigation@chrome://global/content/bindings/general.xml:94:1
13:30:27 INFO - get_contentDocument@chrome://global/content/bindings/general.xml:97:1
13:30:27 INFO - Toolbox.prototype.doc@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:241:5
13:30:27 INFO - Toolbox.prototype.destroyHost@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:1582:1
13:30:27 INFO - Toolbox.prototype.destroy/this._destroyer<@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:1661:19
13:30:27 INFO - Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:870:23
13:30:27 INFO - this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:749:7
13:30:27 INFO - this.PromiseWalker.scheduleWalkerLoop/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:691:37
13:30:27 INFO - 3418 INFO TEST-START | browser/devtools/webaudioeditor/test/browser_wa_first-run.js
Assignee: nobody → jsantell
Patch in bug 1115780 should resolve this, as well
No longer blocks: 1106923
Looks like bug 1115780 closed this
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 37
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Jordan, any thoughts?  Seems this started again on May 3 and is spiking quite a bit.

https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1115779&startday=2016-04-18&endday=2016-05-11&tree=all
Flags: needinfo?(jsantell)
No work has been done on this tool in quite sometime; looks like it might be a general toolbox issue. Joe, know who would be good for this?
Flags: needinfo?(jsantell) → needinfo?(jwalker)
as a related note, this is most common on linux64 debug.  In addition, I am interested in this bug as this is one of the few common devtools tests which fail on windows 7 on a VM (note: this is our solution for scalability)

many retriggers (this is dt5 on the tip of the branches, but was dt6 when it first started having troubles):
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=linux64%20debug%20dt6&tochange=b97e26486559&fromchange=4aacf1d311f1

and what looks to be a root cause from bug 1266676:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ecc70bad825e8702f2ee171ae89392887753c21c

:h4writer, it seems as though your change is the culprit here- can you help us find the root cause or someone to help narrow this down?
Flags: needinfo?(hv1989)
(In reply to Joel Maher (:jmaher) from comment #11)
> as a related note, this is most common on linux64 debug.  In addition, I am
> interested in this bug as this is one of the few common devtools tests which
> fail on windows 7 on a VM (note: this is our solution for scalability)
> 
> many retriggers (this is dt5 on the tip of the branches, but was dt6 when it
> first started having troubles):
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-
> searchStr=linux64%20debug%20dt6&tochange=b97e26486559&fromchange=4aacf1d311f1
> 
> and what looks to be a root cause from bug 1266676:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/
> ecc70bad825e8702f2ee171ae89392887753c21c
> 
> :h4writer, it seems as though your change is the culprit here- can you help
> us find the root cause or someone to help narrow this down?

That bug makes it possible to hammer IonMonkey a little bit faster . This caused us to already find e.g. bug 1270108. Though it seems that this is probably a different issue than the one before. Can you open a new bug for this, instead of re-using the same bug (that actually was fixed?). Gonna investigate starting tomorrow. (On holiday currently)
filed bug 1273233 to track this.
Flags: needinfo?(jwalker)
Flags: needinfo?(hv1989)
Various debug statements to help figure this out:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=213369e236b6

It times out on this call:
  yield Promise.all([destroyed, waitForGraphRendered(panelWin, 3, 2)]);

Locally, this test stop for quite a while on this.
Let's see if that pass with an even longer timeout to ensure that the nodes really get gc-ed,
or, if for some reason they aren't gc-ed at all on some race conditions.
Increasing the timeout doesn't help. So a race prevent nodes from being collected.
Let's see if additional forceCC/forceGC calls help garbage them:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=7ceb38cf2408
Hum. Can't we retrigger mochitests when they are run on taskcluster???
It doesn't work from treeherder (no error message, but nothing happen),
nor does it work for me from the task inspector ("You do not have sufficient scopes.").
:dustin ^ why would this be an issue
Flags: needinfo?(dustin)
Retriggers work through pulse_actions -- maybe something's wrong there?
Flags: needinfo?(dustin) → needinfo?(armenzg)
garndt just fixed that.
Flags: needinfo?(armenzg)
So. To get back to this webaudio test. It looks like calling forceCC a second time after 80s seems to unlock the test. Could it be that we are calling forceCC too early? Or that we need two of them?
Two new try.

One waiting for an additional tick before calling forceCC:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=99f00079d08e

Another doing two forceCC:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=0fb4a6f9e1ea

Hopefully, one of those is going to be enough.
Re-triggers of TaskCluster tasks work through mozilla-taskcluster rather than pulse_actions.
pulse_actions only takes care of sophisticated Buildbot requests. No TaskCluster at the moment.
Doing two forceCC doesn't help.
Waiting for a tick didn't failed on the first try.
Attached patch patch v1 (obsolete) — Splinter Review
Let's see if a simple tick does it:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=3a64330e28f9
Hopefully this try syntax will do what I expect it to do.
taskcluster retrigger are broken again...
Attachment #8754051 - Flags: review?(jryans)
Assignee: jsantell → nobody
Try syntax to run tests multiple times doesn't work on taskcluster.
So it looks like the only way to run tests multiple times is to push multiple times :s
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=4f8c4ac094b0
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=16e247b143e9
Assignee: nobody → poirot.alex
In addition, I see common timeouts in:
devtools/client/webaudioeditor/test/browser_webaudio-actor-destroy-node.js 

earlier this week I filed bug 1273233 and in backing out ecc70bad825e8702f2ee171ae89392887753c21c, I am able to see no failures in browser_webaudio-actor-dstroy-node.js or browser_wa_destroy-node-01.js.

If we are working around the regression from the js landing, please work around it in browser_webaudio-actor-destroy-node.js as well!
Attached patch patch v2 (obsolete) — Splinter Review
Also fix test reported by Joel!
Attachment #8754296 - Flags: review?(jryans)
Attachment #8754051 - Attachment is obsolete: true
Attachment #8754051 - Flags: review?(jryans)
Comment on attachment 8754296 [details] [diff] [review]
patch v2

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

::: devtools/client/webaudioeditor/test/browser_wa_destroy-node-01.js
@@ +39,5 @@
>    yield clickGraphNode(panelWin, actorIDs[5]);
>  
> +  // Wait for a tick before gc to prevent this test from intermittent timeout
> +  // where the node never get collected.
> +  yield new Promise(done => executeSoon(done));

DevToolsUtils is imported by head.js, use DevToolsUtils.waitForTick

::: devtools/client/webaudioeditor/test/browser_webaudio-actor-destroy-node.js
@@ +17,5 @@
>    ]);
>  
> +  // Wait for a tick before gc to prevent this test from intermittent timeout
> +  // where the node never get collected.
> +  yield new Promise(done => executeSoon(done));

DevToolsUtils is imported by head.js, use DevToolsUtils.waitForTick
Attachment #8754296 - Flags: review?(jryans) → review+
Attached patch patch v3 (obsolete) — Splinter Review
With waitForTick.
Attachment #8754569 - Flags: review+
Attachment #8754296 - Attachment is obsolete: true
Target Milestone: Firefox 37 → ---
https://hg.mozilla.org/mozilla-central/rev/a917f7712208
Status: REOPENED → RESOLVED
Closed: 5 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 49
This seems to be better but not fully fixed yet :(
Status: RESOLVED → REOPENED
Flags: needinfo?(poirot.alex)
Resolution: FIXED → ---
Duplicate of this bug: 1273233
Attached patch Fix faulty testSplinter Review
With respect, the previous patch was completely incorrect. In the future, I would recommend that we avoid trying random things as potential fixes, without drilling down to the core cause of the failure. Landing a wait in order to maybe perturb test timings, or extending timeouts or trying another forceCC() is not only incorrect, it's irresponsible. In this case, the problem was just a broken test, but it could easily have been a real bug in the platform. Landing band-aids just masks those issues. We'd much rather solve them.

Changing the GC/CC interactions requested, and ensuring that, on e10s, the collections are actually requested in the content process, rather than in the parent process, seems to have quieted the intermittent failure.

Thanks to Brian Grinstead for his help debugging this.
Assignee: poirot.alex → efaustbmo
Attachment #8754569 - Attachment is obsolete: true
Flags: needinfo?(poirot.alex)
Attachment #8760559 - Flags: review?(bgrinstead)
Comment on attachment 8760559 [details] [diff] [review]
Fix faulty test

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

Thanks for fixing this

::: devtools/client/webaudioeditor/test/head.js
@@ +420,5 @@
>  /**
>  * Forces cycle collection and GC, used in AudioNode destruction tests.
>  */
>  function forceCC() {
> +    ContentTask.spawn(gBrowser.selectedBrowser, {}, function*() {

Nit: use 2 space indentation
Attachment #8760559 - Flags: review?(bgrinstead) → review+
Pushed by efaustbmo@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/815b7fb28fdf
Fix buggy devtools test, solving intermittent timeouts. (r=bgrins)
https://hg.mozilla.org/mozilla-central/rev/815b7fb28fdf
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
See Also: → 1279006
Product: Firefox → DevTools
Product: DevTools → DevTools Graveyard
You need to log in before you can comment on or make changes to this bug.