1483319 - Console messages are not shown for todomvc

Status: RESOLVED FIXED

(Core Graveyard :: Web Replay, defect)

Description

[Jason Laster [:jlast]]

STR:
1. open devtools console
2. go to https://firefox-dev.tools/debugger-examples/examples/todomvc/

ER: see a couple "todo created" messages
AR: see an error in the browser console "hud" or "jsterm" is undefined

Comment 1

[Brian Hackett [Laid off!]]

Attachment: patch

The basic problem here is that the console message support in web replay doesn't handle objects that are passed to console.log() calls.  We throw an exception in the web console's server code and then things break.  The attached patch fixes this, and the console messages and associated object previews show up in the web console window.  I'll break it up for review in a minute, as some internal things had to change in order to support this.

There's one aspect of the web console UI that still doesn't work right.  There is a drop down menu on logged objects that allows users to explore their properties, prototype chains, and so forth.  When we are paused at the point where we received a console message, this menu can be accessed, but if we have rewound or run forwards then the drop down menu doesn't work (well, usually doesn't; there is some client side caching of the results going on that sometimes masks this).  This is because the server is using the same Debugger.Object that it got when adding the message, and when replaying Debugger.Objects become unusable after unpausing.  I didn't fix this because I'm not sure what to do about it; the best thing might be to remove the drop down menu when replaying, as users can just warp to the point where the message was logged and inspect the object's original state (and all other state) at that point.

Comment 2

[Brian Hackett [Laid off!]]

Attachment: Part 1 - Transmit console message arguments as debuggee values.

Currently, we convert object arguments to console messages into JSON and pass them up to the middleman process.  The devtools server code running there can't create ReplayDebuggerObjects for these objects, as it can only do so for objects that exist in the replaying process.  This patch changes how console messages are transmitted to the middleman process so that values representing replaying process values are used, which the ReplayDebugger in the server can convert to ReplayDebuggerObjects.  The web console server code can then use these as is when handing grips for them up to the client for processing.

Comment 3

[Brian Hackett [Laid off!]]

Attachment: Part 2 - Treat replayForcedPause as unsolicited.

This isn't really related to the other parts of this bug, but I ran into it while testing.  replayForcedPause pauses need to be treated by the debugger client as unsolicited, or else it might interpret them as responses to messages it has sent and get terminally confused.

Comment 4

[Brian Hackett [Laid off!]]

Attachment: Part 3 - Combine BreakpointPaused and CheckpointPaused phases.

Currently, we have different phases in the navigation code for being paused at a checkpoint or paused at an intra-checkpoint execution point.  These are similar in a lot of ways but the latter allows the debugger a lot more latitude: it can perform queries on the process that might trigger an unhandled recording divergence, which are necessary in order to inspect the contents of objects that are logged by the console.  If the replaying process pauses at a checkpoint and the server code tries to look at the arguments to console messages that have been logged so far, then that server code will not be able to inspect the contents of objects that have been logged.

The best solution here is I think to merge these two phases into a single Paused phase.  This allows debugger queries to be performed anywhere the process might be paused.  This patch makes this change, and also reworks how temporary checkpoints are taken when paused so that they are only saved when dealing with the first request that might trigger an unhandled recording divergence.  This avoids saving (and, later on, restoring) temporary checkpoints whenever a replaying process reaches a checkpoint.

Comment 5

[Brian Hackett [Laid off!]]

Attachment: Part 4 - Give ReplayDebugger control over when the active child should be replaying.

Currently, when pausing at a breakpoint (other than NewScript, via the junky IsUserBreakpoint heuristic method) the middleman process ensures that the debugger is interacting with a replaying process that can perform operations that might trigger unhandled recording divergences.  This strategy doesn't work when such queries might happen at checkpoints, though --- if we did this eagerly we would have to switch to a replaying child whenever the recording child reaches a checkpoint, which would be pretty slow.

The attached patch removes this heuristic from the middleman's code and encodes it as a RecordReplayControl method, so that the ReplayDebugger can ask the middleman process to make sure it is communicating with a replaying process.

Comment 6

[Brian Hackett [Laid off!]]

Attachment: Part 5 - Ensure that the child process is replaying when sending requests that might trigger recording divergence.

This patch uses the API added in part 4 to ensure that the debugger is interacting with a replaying process when necessary: a query is being sent to the child process which might trigger a recording divergence or other side effect.

Comment 7

[Andrew McCreight [:mccr8]]

Comment on attachment 9001819 [details] [diff] [review]
Part 3 - Combine BreakpointPaused and CheckpointPaused phases.

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

::: toolkit/recordreplay/ipc/ChildNavigation.cpp
@@ +633,3 @@
>  
> +  if (!mResumeForward && !mRecoveringFromDivergence) {
> +    // We processed this request normally, remember the response and send it to

nit: I think this should be "normally. Remember".

@@ +699,5 @@
>    }
> +
> +  if (!EnsureTemporaryCheckpoint()) {
> +    // One of the premature exit cases was hit in EnsureTemporaryCheckpoint,
> +    // don't allow any operations that can diverge from the recording.

Nit: split this into two sentences or use a colon instead of the comma.

Comment 8

[Andrew McCreight [:mccr8]]

Comment on attachment 9001820 [details] [diff] [review]
Part 4 - Give ReplayDebugger control over when the active child should be replaying.

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

::: toolkit/recordreplay/ipc/ParentIPC.cpp
@@ +821,5 @@
>  
> +void
> +EnsureActiveChildIsReplaying()
> +{
> +  if (gActiveChild->IsRecording() && CanRewind()) {

Why does this just do nothing if we're recording but we can't rewind? I would have expected an assert or a JS exception or something.

Comment 9

[Brian Hackett [Laid off!]]

(In reply to Andrew McCreight [:mccr8] from comment #8)
> Comment on attachment 9001820 [details] [diff] [review]
> Part 4 - Give ReplayDebugger control over when the active child should be
> replaying.
> 
> Review of attachment 9001820 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/recordreplay/ipc/ParentIPC.cpp
> @@ +821,5 @@
> >  
> > +void
> > +EnsureActiveChildIsReplaying()
> > +{
> > +  if (gActiveChild->IsRecording() && CanRewind()) {
> 
> Why does this just do nothing if we're recording but we can't rewind? I
> would have expected an assert or a JS exception or something.

This situation is possible if the devtools.recordreplay.enableRewinding pref is unset.  In that case, when the ReplayDebugger sends a request to the child process that might trigger a recording divergence, the recording process return a response that indicates the request could not be processed --- the same response that is sent when an unhandled recording divergence actually occurred (e.g. trying to eval 'window.alert("foo")').  When the ReplayDebugger receives this response it could throw if it wanted to, but doing that will usually break the debugger.  Leaving things as a no-op here gives other code more latitude in how to deal with this situation, and the methods for doing so are the same as for the more common case of a request that triggered an unhandled recording divergence.

This method is pretty badly named, though.  I'll change it to MaybeSwitchToReplayingChild.

Comment 10

[Andrew McCreight [:mccr8]]

That makes sense. Yeah, renaming the function is a good idea.

Comment 11

[Jim Blandy :jimb]

Comment on attachment 9001816 [details] [diff] [review]
Part 1 - Transmit console message arguments as debuggee values.

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

::: devtools/server/actors/replay/replay.js
@@ +674,5 @@
>      return gPopFrameResult ? convertCompletionValue(gPopFrameResult) : {};
>    },
>  
>    findConsoleMessages(request) {
> +    return gConsoleMessages.map(convertConsoleMessage);

Would it make sense to convert the messages once when they are placed in gConsoleMessages, rather than converting them each time they're extracted?

Comment 12

[Brian Hackett [Laid off!]]

(In reply to Jim Blandy :jimb from comment #11)
> Comment on attachment 9001816 [details] [diff] [review]
> Part 1 - Transmit console message arguments as debuggee values.
> 
> Review of attachment 9001816 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: devtools/server/actors/replay/replay.js
> @@ +674,5 @@
> >      return gPopFrameResult ? convertCompletionValue(gPopFrameResult) : {};
> >    },
> >  
> >    findConsoleMessages(request) {
> > +    return gConsoleMessages.map(convertConsoleMessage);
> 
> Would it make sense to convert the messages once when they are placed in
> gConsoleMessages, rather than converting them each time they're extracted?

Unfortunately, because the converted messages can contain references to debugger objects, which are invalidated when unpausing, we have to do the conversion at same point in execution where the debugger request occurs.

Comment 13

[Jim Blandy :jimb]

Okay, that makes sense.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fd6f1b574cbb
Part 1 - Transmit console message arguments as debuggee values, r=jimb.
https://hg.mozilla.org/integration/mozilla-inbound/rev/ed84aae6166c
Part 2 - Treat replayForcedPause as unsolicited, r=jimb.
https://hg.mozilla.org/integration/mozilla-inbound/rev/2ddf1cb297c5
Part 3 - Combine BreakpointPaused and CheckpointPaused phases, r=mccr8.
https://hg.mozilla.org/integration/mozilla-inbound/rev/4eb666e572f9
Part 4 - Give ReplayDebugger control over when the active child should be replaying, r=mccr8.
https://hg.mozilla.org/integration/mozilla-inbound/rev/8b832de5ad1d
Part 5 - Ensure that the child process is replaying when sending requests that might trigger recording divergence, r=jimb.

Comment 15

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/fd6f1b574cbb
https://hg.mozilla.org/mozilla-central/rev/ed84aae6166c
https://hg.mozilla.org/mozilla-central/rev/2ddf1cb297c5
https://hg.mozilla.org/mozilla-central/rev/4eb666e572f9
https://hg.mozilla.org/mozilla-central/rev/8b832de5ad1d