1960694 - Event listener logpoints can freeze the console

Status: ASSIGNED

(DevTools :: Console, defect, P2)

Description

[Holger Benl [:hbenl]]

Setting an event listener breakpoint with the "Log" checkbox checked can freeze the console, i.e. it eventually stops adding new messages.
This is somewhat intermittent but the following STRs let me reproduce it relatively reliably:

1. Open https://echarts.apache.org/examples/en/
2. Open the debugger, set an event listener breakpoint for "Request Animation Frame" and check the "Log" checkbox
3. Scroll the page and watch the messages from the event listener logpoint appear in the console
4. Reload the page, scroll, reload, etc. until the console freezes

In the browser console I can then see an exception "TypeError: can't access property "_grip", message2Parameter is undefined" from https://searchfox.org/mozilla-central/source/devtools/client/webconsole/utils/messages.js#707.

Comment 1

[Holger Benl [:hbenl]]

Attachment: event log with 0 arguments.png

One issue seems to be that this code assumes that there is always at least one argument in the frame but if there isn't (see the frame.arguments watch expression in the screenshot) then we evaluate the expression [_event] with bindings { _event: undefined } and end up constructing a message with arguments: [undefined].

Comment 2

[Nicolas Chevobbe [:nchevobbe]]

(In reply to Holger Benl from comment #1)

Created attachment 9479340 [details]
event log with 0 arguments.png

One issue seems to be that this code assumes that there is always at least one argument in the frame but if there isn't (see the frame.arguments watch expression in the screenshot) then we evaluate the expression [_event] with bindings { _event: undefined } and end up constructing a message with arguments: [undefined].

In this case, event if we get an undefined evaluation result, this should be transformed into a grip like {type: undefined} in https://searchfox.org/mozilla-central/rev/08b2a1a770688df19a5a43fd89fb63b34bb2d6a6/devtools/server/actors/resources/console-messages.js#227-234 , so the [undefined] array we get in parameters in the console client shouldn't come from there?

I can't reproduce myself unfortunately. Holger, can you add a conditional breakpoint in https://searchfox.org/mozilla-central/source/devtools/client/webconsole/utils/messages.js#707 for when message2Parameter is undefined, and copy message1 and message2 here once you triggered the issue?

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

(I also filed another bug to make sure we log something more meaningful for those events: Bug 1960905)

Comment 4

[Holger Benl [:hbenl]]

Attachment: message2 with undefined argument.png

I couldn't copy the object (stringify fails due to a cycle) so here's a screenshot instead.

Comment 5

[Holger Benl [:hbenl]]

event if we get an undefined evaluation result, this should be transformed into a grip

Yeah, this usually works, I just saw how an undefined argument in a requestAnimationFrame log is transformed to { type: "undefined" } in the message object that is passed to areMessagesParametersSimilar().
So now I'll need to figure out where the messages with an undefined argument are coming from.

Comment 6

[Holger Benl [:hbenl]]

Attachment: undefined argument not transformed.png

As you can see in this screenshot, some undefined arguments do not get transformed to { type: "undefined" } in prepareConsoleMessageForRemote().

Comment 7

[Holger Benl [:hbenl]]

The reason is that arguments is not [undefined] but an array with one empty slot (like new Array(1)) and arguments.map() will not call the callback for empty slots!

Comment 8

[Holger Benl [:hbenl]]

Attachment: Bug 1960694 - [devtools] Handle empty slots when converting console message arguments. r=#devtools-reviewers,nchevobbe

Comment 9

[Holger Benl [:hbenl]]

Attachment: strange arguments array.png

(replying to https://phabricator.services.mozilla.com/D245764#8499647)

By the way, did you manage to find why we're getting these empty slots?

Actually I found that they're not empty slots but something else.
When I took the screenshot, I was paused here. Note the inline preview of message.arguments is [ () ] but message.arguments[0] evaluates to undefined. I have also evaluated new Array(1) and [undefined] for comparison.

Comment 10

[Holger Benl [:hbenl]]

Why are we going through an evaluation anyway? I think this was only done (in D45619) to share some code with regular logpoints (which need to go through an evaluation for the user-supplied log expression).

Comment 11

[Holger Benl [:hbenl]]

Attachment: Bug 1960694 - [devtools] Don't use evaluations for event logpoints. r=#devtools-reviewers

Comment 12

[Holger Benl [:hbenl]]

D245881 logs events without using an evaluation.
That showed me that the strange argument that I noticed in Comment 9 is originally a function.
Then I noticed something else: the arguments that we're looking at here are not the arguments to the requestAnimationFrame() call - they're the arguments for the function that calls requestAnimationFrame(), so we're looking at the wrong frame here. Do we even have frames for calls to built-in functions like requestAnimationFrame()?