1088861 - Console doesn't respond when debugger is paused at breakpoint that was hit by executing a command in the console

Status: RESOLVED FIXED

(DevTools :: Console, defect, P1)

Description

[James Long (:jlongster)]

The console doesn't respond to me when I set a breakpoint in the simple function on this page: http://jlongster.com/s/console/

Call the function, let the debugger pause. Now try to evaluate anything in the console. It just doesn't respond.

Comment 1

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

Can repro w/ BP on line 4.

Comment 2

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

Suspect that the console is holding off on everything until it gets a response to the eval. But I don't know the console frontend super well.

Comment 3

[Brian Grinstead [:bgrins]]

After the STR are followed, the console seems to be completely broken - commands don't do anything even after unpausing

Comment 4

[Brian Grinstead [:bgrins]]

I see these errors in the browser toolbox after resuming:

error occurred while processing 'autocomplete: Error: Debugger.Frame is not live
Stack: WCA_onAutocomplete@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/webconsole.js:815:9
DSC_onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/main.js:1403:15
LocalDebuggerTransport.prototype.send/<@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:545:11
makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:83:14
makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:83:14
Line: 815, column: 8 main.js:1275:0
onPacket threw an exception: Error: Server did not specify an actor, dropping packet: {"error":"unknownError","message":"error occurred while processing 'autocomplete: Error: Debugger.Frame is not live\nStack: WCA_onAutocomplete@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/webconsole.js:815:9\nDSC_onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/main.js:1403:15\nLocalDebuggerTransport.prototype.send/<@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:545:11\nmakeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:83:14\nmakeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:83:14\nLine: 815, column: 8"}
Stack: DebuggerClient.prototype.onPacket@resource://gre/modules/devtools/dbg-client.jsm:887:1
LocalDebuggerTransport.prototype.send/<@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:545:11
makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:83:14
makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:83:14
Line: 887, column: 0 DevToolsUtils.js:59:0

Comment 5

[Brian Grinstead [:bgrins]]

Then when trying to run a command afterwards I see this spam the log:

A promise chain failed to handle a rejection. Did you forget to '.catch', or did you forget to 'return'?
See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise

Date: Tue Dec 09 2014 14:01:25 GMT-0800 (PST)
Full Message: null
Full Stack: JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: PendingErrors.register :: line 165
JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.completePromise :: line 678
JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_handleException :: line 448
JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 326
JS frame :: resource://gre/modules/Task.jsm :: TaskImpl :: line 275
JS frame :: resource://gre/modules/Task.jsm :: createAsyncFunction/asyncFunction :: line 249
JS frame :: resource://gre/modules/Task.jsm :: Task_spawn :: line 164
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: .linkToInspector :: line 3095
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: ._renderElementNode :: line 3076
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: .render :: line 2941
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Widgets.JSObject.prototype<.render :: line 2286
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Messages.Extended.prototype<._renderObjectActor :: line 1190
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Messages.Extended.prototype<._renderValueGrip :: line 1098
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Messages.Extended.prototype<._renderBodyPiece :: line 1064
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Messages.ConsoleGeneric.prototype<._renderBodyPiece :: line 1404
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Messages.ConsoleGeneric.prototype<._renderBodyPieces :: line 1395
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/console-output.js :: Messages.ConsoleGeneric.prototype<.render :: line 1310
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/webconsole.js :: WCF_logConsoleAPIMessage :: line 1226
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/webconsole.js :: WCF__outputMessageFromQueue :: line 2265
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/webconsole/webconsole.js :: WCF__flushMessageQueue :: line 2153
native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0 <unknown>

Comment 6

[Brian Grinstead [:bgrins]]

This totally screws up the toolbox to where it can't reopen on that same tab after closing - you have to start on a brand new tab before things will work again.

Comment 7

[Brian Grinstead [:bgrins]]

The call to onEvaluateJS doesn't run until after the thread is unpaused because it is waiting for the evaluateJS call to foo() to finish.  Once this runs all the other queued commands (autocomplete, evaluateJS, etc) throw errors and leave things in a bad state.  So really these are two separate problems.

The primary problem is that the server isn't receiving the evaluateJS packet in this case because there is already an evaluateJS request packet active.  This explains why it only happens when the breakpoint is hit by executing a command in the console.  Here is the currently active request:

{"request":{"to":"conn1.consoleActor25","type":"evaluateJS","text":"foo()","frameActor":null,"selectedNodeActor":null},"format":"json"}}

And I'm trying to send a packet like this (when I run 'bar()' in the console while paused):

{"request"{"to":"conn1.consoleActor25","type":"evaluateJS","text":"bar()","frameActor":"conn1.frame129","selectedNodeActor":null},"format":"json"}}

Here is the block where the request is being skipped: http://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/client/dbg-client.jsm#831-833.

Panos, do you know how we could work around this?

Comment 8

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

This is a result of the packet dispatcher's limitation to only have one active request per actor. One way of fixing this is to change that design, but that's a lot of work.

Another option would be to make the evaluateJS request async, or even better (for backwards compatibility) to introduce an evaluateJSAsync. This new request would transmit the expression and return immediately, before evaluation takes place. Then, once the evaluation is completed, the actor would fire an evaluationResult event (unsolicited notification) to the client with the results. We could move the console and scratchpad to this new API and keep the old one around for add-ons (and possibly mark it deprecated).

Here is what the new packets could look like:

{
  "to": "conn0.consoleActor21",
  "type": "evaluateJSAsync",
  "token": UUID-or-timestamp,
  "text": "foo(1,2)",
  "frameActor": null,
  "selectedNodeActor": null
}

{
  "from": "conn0.consoleActor21",
}

And then later:

{
  "from": "conn0.consoleActor21",
  "type": "evaluationResult",
  "token": UUID-or-timestamp,
  "input": "foo(1,2)",
  "result": 3,
  "timestamp": 1418203175598,
  "exception": null,
  "helperResult": null
}

The initial request and async event packets are almost the same as the current evaluateJS request and response ones, with the notable addition of a token. The idea is that the client would send this opaque token that the actor will include in the result to unambiguously associate the response with the request, in the case of multiple pending evaluations. I think a timestamp would suffice for this, since it only needs to be unique per client, but a UUID is an option as well.

Comment 9

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

This will undoubtedly require some changes in the web console and scratchpad frontends, but I don't think those will be too hard.

Comment 10

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

The other thing we could do is actually reject the promises we are waiting on, instead of letting them dangle in the pending state forever and therefore blocking subsequent requests. Right now, if anything goes wrong in the console, it blocks use of the console for the rest of the session because of this. Would be very nice to at least make the console more error tolerant.

I understand this is the same goal as your suggestion about evalJSAsync, Panos, but it sure seems like we could fix this perma-fail behavior without refactoring so much code.

Comment 11

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

Nevermind! Just talked with Panos on irc, and I totally misunderstood this bug. Once I re-read STR and the problem at hand, I am +Infinity to comment 8.

Comment 12

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

(In reply to Panos Astithas [:past] from comment #8)
> Here is what the new packets could look like:
> 
> {
>   "to": "conn0.consoleActor21",
>   "type": "evaluateJSAsync",
>   "token": UUID-or-timestamp,

Please not just a timestamp; it is likely enough that if you programmatically send multiple requests they will all have the same timestamp.

Monotonically incrementing a counter is probably fine, it doesn't seem realistic to send enough requests to hit the max number and overflow to Infinity.

We could always actually generate real UUIDs if we want to be paranoid/thorough.

> And then later:
> 
> {
>   "from": "conn0.consoleActor21",
>   "type": "evaluationResult",
>   "token": UUID-or-timestamp,
>   "input": "foo(1,2)",

Does it make sense to return the input, since we already know which request ID this is an async response to?

Also inputs could get big with scratchpads.

Seems un-needed.

Comment 13

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

(In reply to Nick Fitzgerald [:fitzgen] from comment #12)
> (In reply to Panos Astithas [:past] from comment #8)
> > Here is what the new packets could look like:
> > 
> > {
> >   "to": "conn0.consoleActor21",
> >   "type": "evaluateJSAsync",
> >   "token": UUID-or-timestamp,
> 
> Please not just a timestamp; it is likely enough that if you
> programmatically send multiple requests they will all have the same
> timestamp.
> 
> Monotonically incrementing a counter is probably fine, it doesn't seem
> realistic to send enough requests to hit the max number and overflow to
> Infinity.
> 
> We could always actually generate real UUIDs if we want to be
> paranoid/thorough.

Whatever the choice is, it would awesome for this concept of "token to allow multiple in-flight requests" to be handled at the framework level (some kind of opt-in behavior for a method), instead of just for this one new method, as I can imagine there being other places where that would be a convenient ability.

protocol.js is generally a good place to put such a feature, but I am sure in this case this is an old actor that does not use protocol.js today...

Comment 14

[Brian Grinstead [:bgrins]]

I will look at this

Comment 15

[Brian Grinstead [:bgrins]]

Attachment: console-async.patch

Looking for feedback, I'm working through tests.  I kept all of the ID generation server side since it seemed like this would be easier for clients to work with (and we could change the id generation behind the scenes if needed).  The frontend actually needed no changes except for switching to the new function.  Here is an example packet transfer when executing foo() on https://bgrins.github.io/devtools-demos/debugger/scripts.html:

DBG-SERVER: Packet 38 sent to "conn1.consoleActor25"
DBG-SERVER: Received packet 38: {
  "to": "conn1.consoleActor25",
  "type": "evaluateJSAsync",
  "text": "foo()",
  "frameActor": null,
  "selectedNodeActor": null
}
DBG-SERVER: Packet 39 sent from "conn1.consoleActor25"
DBG-SERVER: Packet 40 sent from "conn1.context120"
DBG-SERVER: Packet 41 sent from "conn1.consoleActor25"
DBG-SERVER: Received packet 39: {
  "from": "conn1.consoleActor25",
  "id": 0
}
DBG-SERVER: Received packet 40: {
  "from": "conn1.context120",
  "type": "newSource",
  "source": {
    "actor": "conn1.source124",
    "url": "debugger eval code",
    "addonID": null,
    "addonPath": null,
    "isBlackBoxed": false,
    "isPrettyPrinted": false,
    "introductionUrl": null,
    "introductionType": "debugger eval"
  }
}
DBG-SERVER: Received packet 41: {
  "from": "conn1.consoleActor25",
  "result": {
    "type": "NaN"
  },
  "timestamp": 1418272370602,
  "exception": null,
  "helperResult": null,
  "type": "evaluationResult",
  "id": 0
}

I do believe that one more change is that jsterm.execute will need to return a promise and the webconsole tests will need to be updated to yield on that.

Comment 16

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

(In reply to Nick Fitzgerald [:fitzgen] from comment #12)
> Please not just a timestamp; it is likely enough that if you
> programmatically send multiple requests they will all have the same
> timestamp.

Since sending multiple requests would have them queued until the responses come back, this would only happen in a badly written client, but I agree it makes sense to guard even against that case.

> Does it make sense to return the input, since we already know which request
> ID this is an async response to?
> 
> Also inputs could get big with scratchpads.
> 
> Seems un-needed.

Note that this argument applies to the existing response packet as well (it is just an expected response packet). My thinking was that we would minimize frontend changes by reusing the same packet format in the async case.

(In reply to J. Ryan Stinnett [:jryans] from comment #13)
> Whatever the choice is, it would awesome for this concept of "token to allow
> multiple in-flight requests" to be handled at the framework level (some kind
> of opt-in behavior for a method), instead of just for this one new method,
> as I can imagine there being other places where that would be a convenient
> ability.
> 
> protocol.js is generally a good place to put such a feature, but I am sure
> in this case this is an old actor that does not use protocol.js today...

The web console actor sure is an old-style actor, but more importantly, using IDs for every request was the more invasive design solution I alluded to in comment 8. It may not require huge code changes, but the potential for subtle errors and races would call for extensive testing and review.

But perhaps I shouldn't be trying to scare folks off that approach. If someone has the time to do it, I'm all for it!

Comment 17

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

Comment on attachment 8534802 [details] [diff] [review]
console-async.patch

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

I'm pleasantly surprised that the frontend didn't require any changes. How does the output pane look when displaying the output of a blocked expression split in two, with an intermediate evaluation between them? Or is it that we don't display anything until the evaluation result arrives?

::: toolkit/devtools/server/actors/webconsole.js
@@ +764,5 @@
> +    // First, send a response packet with the id only
> +    let id = getIncrementedID();
> +    this.conn.send({
> +      from: this.actorID,
> +      id: id

I think resultId would be more descriptive.

@@ +775,5 @@
> +    response.id = id;
> +
> +    // Finally, send an unsolicited evaluationResult packet with
> +    // the normal return value
> +    this.conn.send(response);

You need to add evaluationResult to the UnsolicitedNotifications list in dbg-client.jsm, as this is an old-style actor.

Also, there is now a more descriptive API to use:

this.conn.sendActorEvent(this.actorID, "evaluationResult", response);

::: toolkit/devtools/webconsole/client.js
@@ +133,5 @@
>    /**
> +   * Evaluate a JavaScript expression asynchronously.
> +   * See evaluateJS for parameter and response information.
> +   */
> +  evaluateJSAsync: function WCC_evaluateJS(aString, aOnResponse, aOptions = {})

WCC_evaluateJSAsync if you insist on having it.

@@ +442,5 @@
>    detach: function WCC_detach(aOnResponse)
>    {
> +    // XXX - Two questions:
> +    // 1) Is there a reason this doesn't use DebuggerClient.requester?
> +    // 2) Should this call this._client.unregisterClient(this)?

The answer to both questions is that the web console client predates the DebuggerClient.requester and register/unregisterClient APIs. We could convert it to use those, but I think our time would be better spent doing a wholesale conversion to protocol.js.

Comment 18

[Brian Grinstead [:bgrins]]

(In reply to Panos Astithas [:past] from comment #17)
> Comment on attachment 8534802 [details] [diff] [review]
> console-async.patch
> 
> Review of attachment 8534802 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm pleasantly surprised that the frontend didn't require any changes. How
> does the output pane look when displaying the output of a blocked expression
> split in two, with an intermediate evaluation between them? Or is it that we
> don't display anything until the evaluation result arrives?

We don't display anything until the evaluation result, but when it does come through the frontend already handled it gracefully (IMO) by placing the result alongside the initial call (so it inserts the result above all the intermediate call/results).

Comment 19

[Brian Grinstead [:bgrins]]

(In reply to Panos Astithas [:past] from comment #16)
> (In reply to Nick Fitzgerald [:fitzgen] from comment #12)
> > Please not just a timestamp; it is likely enough that if you
> > programmatically send multiple requests they will all have the same
> > timestamp.
> 
> Since sending multiple requests would have them queued until the responses
> come back, this would only happen in a badly written client, but I agree it
> makes sense to guard even against that case.
> 

With the server side ID generation, maybe it would be safe to just use a timestamp since it's always generating it in the same process.  I don't know about nested event loops when paused though, maybe that breaks this assumption.

Comment 20

[Brian Grinstead [:bgrins]]

The test changes will have to be rebased on top of bug 1042253

Comment 21

[Brian Grinstead [:bgrins]]

(In reply to Panos Astithas [:past] from comment #17)
> ::: toolkit/devtools/server/actors/webconsole.js
> @@ +764,5 @@
> > +    // First, send a response packet with the id only
> > +    let id = getIncrementedID();
> > +    this.conn.send({
> > +      from: this.actorID,
> > +      id: id
> 
> I think resultId would be more descriptive.
> 

Done

> @@ +775,5 @@
> > +    response.id = id;
> > +
> > +    // Finally, send an unsolicited evaluationResult packet with
> > +    // the normal return value
> > +    this.conn.send(response);
> 
> You need to add evaluationResult to the UnsolicitedNotifications list in
> dbg-client.jsm, as this is an old-style actor.
> 
> Also, there is now a more descriptive API to use:
> 
> this.conn.sendActorEvent(this.actorID, "evaluationResult", response);
> 

Done, I just did this for evaluationResult, not sure if I should also use it for the conn.send call earlier in the function

> ::: toolkit/devtools/webconsole/client.js
> @@ +133,5 @@
> >    /**
> > +   * Evaluate a JavaScript expression asynchronously.
> > +   * See evaluateJS for parameter and response information.
> > +   */
> > +  evaluateJSAsync: function WCC_evaluateJS(aString, aOnResponse, aOptions = {})
> 
> WCC_evaluateJSAsync if you insist on having it.
> 

I don't, just copy/pasted that from the other function but I've removed it

> @@ +442,5 @@
> >    detach: function WCC_detach(aOnResponse)
> >    {
> > +    // XXX - Two questions:
> > +    // 1) Is there a reason this doesn't use DebuggerClient.requester?
> > +    // 2) Should this call this._client.unregisterClient(this)?
> 
> The answer to both questions is that the web console client predates the
> DebuggerClient.requester and register/unregisterClient APIs. We could
> convert it to use those, but I think our time would be better spent doing a
> wholesale conversion to protocol.js.

No problem, I've just left it as is

Comment 22

[Brian Grinstead [:bgrins]]

Attachment: console-async-test-fixes.patch

More console tests to review (sorry!).  This is mostly just changing calls from jsterm.execute to yield jsterm.execute, although a couple of the tests needed bigger changes to support this pattern.  I didn't need to make this change in tests where waitForMessages is called after the call to jsterm.execute, since that is async anyway.  This is on top of the latest patch in bug 1042253

Comment 23

[Brian Grinstead [:bgrins]]

Attachment: console-async.patch

Main patch - changes are discussed in comments 18-21, and I also added test coverage for the particular problem stated in this bug

Comment 24

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

Comment on attachment 8535726 [details] [diff] [review]
console-async.patch

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

::: toolkit/devtools/server/actors/webconsole.js
@@ +753,5 @@
> +    });
> +
> +    // Then, execute the script that may pause.
> +    let response = this.onEvaluateJS(aRequest);
> +    response.type = "evaluationResult";

This isn't necessary if you are using sendActorEvent, it will be overwritten anyway.

::: toolkit/devtools/webconsole/client.js
@@ +158,5 @@
> +    // Find the associated callback based on this ID, and fire it.
> +    // In a sync evaluation, this would have already been called in
> +    // direct response to the client.request function.
> +    let onResponse = this.pendingEvaluationResults.get(aPacket.resultID);
> +    if (onResponse) {

It would be a good idea to use DevToolsUtils.reportException() here if there is no response handler in the map.

Comment 25

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

Comment on attachment 8535725 [details] [diff] [review]
console-async-test-fixes.patch

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

::: browser/devtools/webconsole/webconsole.js
@@ +3327,5 @@
> +    let deferred = promise.defer();
> +    let callback = function(msg) {
> +      deferred.resolve(msg);
> +      if (aCallback) {
> +        aCallback.apply(this, arguments);

Why not simply: aCallback(msg)? We were not providing any particular |this| before, and using different arguments for the callback vs. the promise fulfillment value sounds confusing and error-prone.

Comment 26

[Brian Grinstead [:bgrins]]

Attachment: console-async.patch

Updated based on Comment 24

Comment 27

[Brian Grinstead [:bgrins]]

Attachment: console-async-test-fixes.patch

Updated based on Comment 25

Comment 28

[Brian Grinstead [:bgrins]]

Try push with changes from Bug 1042253 included: https://tbpl.mozilla.org/?tree=Try&rev=f51d8acf8287

Comment 29

[Brian Grinstead [:bgrins]]

https://hg.mozilla.org/integration/fx-team/rev/0a8afec4cc9e
https://hg.mozilla.org/integration/fx-team/rev/829f73a127c7

Comment 30

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0a8afec4cc9e
https://hg.mozilla.org/mozilla-central/rev/829f73a127c7