904549 - browser_dbg_cmd.js doesn't always wait for helpers.audit to complete

Status: RESOLVED FIXED

(DevTools :: Debugger, defect)

Description

[Joe Walker [:jwalker]]

I think this is the cause of
https://tbpl.mozilla.org/php/getParsedLog.php?id=26444486&tree=Try&full=1 (search for "Message: TypeError: options.display is undefined")

I think what's happening is that stuff is getting cleaned up before the test has properly finished.



11:56:25     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_cmd.js | setInput("dbg close")
11:56:25     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_cmd.js | html output for dbg close
11:56:25     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_cmd.js | Debugger was closed.
11:56:25     INFO -  console.error:
11:56:25     INFO -    Message: TypeError: options.display is undefined
11:56:25     INFO -    Stack:
11:56:25     INFO -      @chrome://mochitests/content/browser/browser/devtools/commandline/test/helpers.js:776
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:189
11:56:25     INFO -  @resource://gre/modules/devtools/gcli.jsm:9141
11:56:25     INFO -  @resource://gre/modules/devtools/gcli.jsm:8500
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:189
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:189
11:56:25     INFO -  TBOX_destroy/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/toolbox.js:833
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:189
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:189
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/core/promise.js:189
11:56:25     INFO -  onClosed@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/framework/target.js:451
11:56:25     INFO -  @resource://gre/modules/devtools/dbg-client.jsm:380
11:56:25     INFO -  @resource://gre/modules/devtools/dbg-client.jsm:102
11:56:25     INFO -  EV_notify@resource://gre/modules/devtools/dbg-client.jsm:159
11:56:25     INFO -  DC_onClosed@resource://gre/modules/devtools/dbg-client.jsm:705
11:56:25     INFO -  LDT_close@resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/server/transport.js:258
11:56:25     INFO -  LDT_close@resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/server/transport.js:254
11:56:25     INFO -  LDT_close@resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/server/transport.js:254
11:56:25     INFO -  closeTransport@resource://gre/modules/devtools/dbg-client.jsm:418
11:56:25     INFO -  @resource://gre/modules/devtools/dbg-client.jsm:316
11:56:25     INFO -  @resource://gre/modules/devtools/dbg-client.jsm:687
11:56:25     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:122
11:56:25     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:47
11:56:25     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:157
11:56:25     INFO -  DC_onPacket@resource://gre/modules/devtools/dbg-client.jsm:691
11:56:25     INFO -  @resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/server/transport.js:239
11:56:25     INFO -  @resource://gre/modules/devtools/dbg-server.jsm -> resource://gre/modules/devtools/DevToolsUtils.js:61
11:56:25     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_cmd.js | finished in 2027ms

Comment 1

[Joe Walker [:jwalker]]

Perhaps this is a good time to convert it from using callbacks and promises to just promises.

Comment 2

[Joe Walker [:jwalker]]

I re-wrote it to use promises rather than callbacks, but I'm less sure now that we were failing to wait.
There was one instance of dropping an error, but that wouldn't cause the exception above.
Never the less, here's the promise version: http://pastebin.mozilla.org/2846701

Comment 3

[Joe Walker [:jwalker]]

And the same again re-written to use Task.jsm
http://pastebin.mozilla.org/2849618

Comment 4

[Joe Walker [:jwalker]]

Attachment: taskdebug-904549.patch

Comment 5

[Panos Astithas (he/him) [:past] (please ni?)]

Comment on attachment 789856 [details] [diff] [review]
taskdebug-904549.patch

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

Oh yes, Task.jsm fits like a glove in this case!

::: browser/devtools/commandline/test/helpers.js
@@ +115,5 @@
> +  waitForExplicitFinish();
> +
> +  options = options || {};
> +  options.chromeWindow = options.chromeWindow || window;
> +  options.isFirefox = true;

"options" sounds rather confusing, but I don't really have a better suggestion. "metadata" would be equally meaningless and my only other ideas were "tabHandle" and HWND. I can't take credit for the last one.

Naming is hard.

@@ +123,5 @@
> +  tabbrowser.selectedTab = options.tab;
> +  options.browser = tabbrowser.getBrowserForTab(options.tab);
> +  options.target = TargetFactory.forTab(options.tab);
> +
> +  options.browser.contentWindow.location = url;

Adding the "load" event listener before navigation would be more appropriate and less prone to races, wouldn't it?

Comment 6

[Joe Walker [:jwalker]]

Attachment: taskdebug-904549.patch v2

This change does the following:
* Fixes the url ordering point raised by past
* Makes this type of problem a test failure
* Fixes an additional instance of this problem in browser_dbg_cmd_blackbox.js

Asking fitzgen for r? this time because he wrote browser_dbg_cmd_blackbox.js and he's on a better TZ. I think you only need to look at browser_dbg_cmd_blackbox.js, Nick.

The generic problem is that helpers.audit is async so in some cases tests were continuing, and then finishing before the 'post-exec' checks were made. So when the exec finished the test was already done and the post-exec checks failed.

Comment 7

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 790248 [details] [diff] [review]
taskdebug-904549.patch v2

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

r+ browser_dbg_cmd_blackbox.js changes

Comment 8

[Joe Walker [:jwalker]]

Attachment: taskdebug-904549.patch v3

I found the bug (helpers.audit is not synchronous) in the profiler code too.
The fix involved changes to the command too.
Past and Fitzgen have reviewed a lot of this already, so you'll need to take a look at: gclicommands.properties, browser_profiler_cmd.js, and profiler/commands.js

Thanks.

Comment 9

[Joe Walker [:jwalker]]

Try for latest: https://tbpl.mozilla.org/?tree=Try&rev=9896f6574192

Comment 10

[Anton Kovalyov (:anton)]

Comment on attachment 790804 [details] [diff] [review]
taskdebug-904549.patch v3

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

As long as try is successful, changes lgtm.

Comment 11

[Joe Walker [:jwalker]]

https://tbpl.mozilla.org/?tree=Fx-Team&rev=3483a63fd3ca
https://hg.mozilla.org/integration/fx-team/rev/8081dc2924bc

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/8081dc2924bc