Closed Bug 1483662 Opened 6 years ago Closed 2 years ago

An error inside an event handler is reported too late

Categories

(DevTools :: Console, defect, P2)

Product:
DevTools
Component:
Console
Version:
61 Branch
Type:
defect

Tracking

(firefox106 verified)

Status:
VERIFIED FIXED
Milestone:
106 Branch
Tracking Flags:
Tracking Status
firefox106 --- verified

People

(Reporter: dan.abramov, Assigned: nchevobbe)

Details

Attachments

(5 files, 1 obsolete file)

index.html
265 bytes, text/html
Details
Bug 1483662 - Add microSecondTimeStamp to nsConsoleMessage, nsScriptError and ConsoleEvent. r=edgar.
48 bytes, text/x-phabricator-request
Details | Review
Bug 1483662 - [devtools] Use microSecondTimeStamp to build timeStamp for console-related resources. r=jdescottes.
48 bytes, text/x-phabricator-request
Details | Review
Bug 1483662 - Add ChromeUtils.dateNow() . r=arai,kmag!
48 bytes, text/x-phabricator-request
Details | Review
Bug 1483662 - [devtools] Use `ChromeUtils.dateNow()` for timestamp of evaluation result packets. r=jdescottes.
48 bytes, text/x-phabricator-request
Details | Review
Attached file index.html — 
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36

Steps to reproduce:

Load this page:

    <body>
      <button>
      </button>
    </body>
    <script>
      const btn = document.getElementsByTagName('button')[0]
      btn.addEventListener('click', function() {
        throw new Error('log 1');
      });
      btn.dispatchEvent(new MouseEvent('click'))
      console.error('log 2')
    </script>




Actual results:

Firefox shows "log 1" and then "log 2". If I refresh the page, it shows "log 2" and "log 1". From now on, on next refreshes the error of the logs is reverse.


Expected results:

In Chrome, Safari, and jsdom, "log 1" exception appears first, and then the "log 2" log appears second. Chrome, Safari, and jsdom consistently print them in the same order, unlike Firefox. I haven't checked other browsers. It would be great if Firefox also consistently showed "log 1" and then "log 2".

The issue is not hypothetical. React is a popular library that relies on the order of these logs. Because they're in the reverse order (or at least are inconsistent), React warnings become confusing: https://github.com/facebook/react/issues/11022
Correction:

>From now on, on next refreshes the error of the logs is reverse.

I meant "From now on, on next refreshes the order of the logs is reverse."
Component: Untriaged → Console
Product: Firefox → DevTools
I can reproduce this. Seems related to console service messages vs console API messages, because if `throw new Error('log 1');` is replaced by `console.error('log 1')` the correct ordering happens in all cases.

I originally thought the problem would just be in the cached message case (i.e. close toolbox and reopen) - the fact that it happens even with the toolbox opened, but only after a refresh, is surprising.
Status: UNCONFIRMED → NEW
Ever confirmed: true
P2 as it affects React and I have seen the confusion in demos gave.

Nicolas, is this something we can solve in Console or do we need help from other teams?
Severity: normal → major
Flags: needinfo?(nchevobbe)
Priority: -- → P2
> I originally thought the problem would just be in the cached message case (i.e. close toolbox and reopen) - the fact that it happens even with the toolbox opened, but only after a refresh, is surprising.

I do think this is a cache vs live thing.
If I do:

1. Go to `data:text/html,<meta charset=utf8><button>Click</button><script>const btn = document.querySelector('button');btn.addEventListener('click', function() {throw new Error('log 1');});btn.dispatchEvent(new MouseEvent('click'));console.error('log 2')</script>`
2. Open the console
3. Refresh
4. Close the console
5. Refresh
6. Open the console

I get :
At 2. `Error: log 1`, then `log 2`
At 3. `log 2` then `Error: log 1`
At 6. `Error: log 1`, then `log 2`

The function to get cached messages, getCachedMessages, takes an array of type of messages to retrieve. And in the console, we set it like this:

```json
  "type": "getCachedMessages",
  "messageTypes": [
    "PageError",
    "ConsoleAPI"
  ]
```
which means PageError are put in the result array first.

But when we're "live", the consoleAPI packet is sent before the pageError one.

From what I see from the packets, the timestamp are often the same for the 2 messages, so we can't really rely on that to do any sorting.

It could have been that we were declaring the listeners in a certain order, which for messages occurring at the same timestamp would explain the issue. But we do create the PageError listener before the ConsoleAPI one: 

```
"startedListeners": [
  "PageError",
  "ConsoleAPI",
  ...
],
```

I can't get any further than ConsoleAPIListener observe function [1] is called before ConsoleServiceListener's one [2]

Maybe baku has more insights on that (he seems to be off this week though) ?

[1] https://searchfox.org/mozilla-central/rev/83562422ecb0f5683da7a9a26ce05ce62bc0c882/devtools/server/actors/webconsole/listeners.js#262
[2] https://searchfox.org/mozilla-central/rev/83562422ecb0f5683da7a9a26ce05ce62bc0c882/devtools/server/actors/webconsole/listeners.js#88
Flags: needinfo?(nchevobbe)
Digging into this more, we found a couple more bugs to related cached messages:

1) Errors and API messages with duplicate timestamps have indeterminate ordering. Since they are in two different stores, and we combine them for display on the client and sort by timestamp (https://searchfox.org/mozilla-central/source/devtools/client/webconsole/webconsole-connection-proxy.js#272-274) sometimes messages that happened at the same time get reversed when loading from cache. I wonder if there's a higher fidelity timestamp we could store, or an alternative way to sort messages to make sure the cached order is always right.
2) I've noticed that sometimes the first API message gets dropped in this test case: `data:text/html,<meta charset=utf8><script>setTimeout(() => { console.log("api 1"); throw new Error("error 1"); },  0); setTimeout(() => {console.log("api 2"); throw new Error("error 2");}, 100); setTimeout(() => {console.log("api 3"); throw new Error("error 3");}, 200)</script>`. One weird thing is that "error 1" has the same timestamp as "api 1", but only the latter seems to get dropped when closing/reopening the toolbox.

I doubt either of these would help the 'live' case with this bug, but fixing (1) should make it so we always get the right ordering at least when loading from cache.
I'd like to ask :baku about Comment 5 when he's back.
Flags: needinfo?(amarchesini)
Hello baku,

Would you have some time to investigate this bug ?
It would be nice if we could fix that in 64.
I created a test demonstrating the issue here: https://phabricator.services.mozilla.com/D7085 
It fails because the messages are not in the same order after a reload, the goal of this bug should be to make this test pass.
Baku, sorry to bother you again, but is there any chance you can have a look at this before the end of the 65 cycle? Thanks!

Is this patch still needed? I don't see it in my review queue. (sorry for the delay)

Flags: needinfo?(amarchesini) → needinfo?(nchevobbe)

No worries. Yes, it would be nice to fix this (basically, the test from https://phabricator.services.mozilla.com/D7085 should pass, if you try it now it fails).

Flags: needinfo?(nchevobbe)
Attachment #9012576 - Attachment description: Bug 1483662 - An error inside an event handler is reported too late; → WIP: Bug 1483662 - An error inside an event handler is reported too late.

Rebased the test from attached patch. We don't have different order between cached and live messages anymore, but we still don't have them in the same order as in Chrome.
We'll take a look in the coming month

Those will be consumed by DevTools webconsole so we can order messages
emitted within the same millisecond more precisely (see next patch in queue)

Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED

We can get a higher precision timestamp from microSecondTimeStamp, which will be consumed
in the console client to re-order messages.
This fixes an issue where different type of resources (console-messages and error-messages)
emitted during the same timestamp would not appear in the order they should be in.
A test is added to make sure the fix is effective.

Depends on D155545

The function returns the current a fractional number
representing the current time (in milliseconds from the Epoch).

This replicates the JSShell dateNow function.

This could be useful in JS land so we can get a more
precise timestamp than Date.now.

For example, it will be used in DevTools code, for the console,
so we can more precisely compare evaluation results
with consoleAPI messages that might have been emitted
as a result of the evaluation.

Depends on D155546

Cu.dateNow() has a higher precision than Date.now(), which is useful for ordering
of messages in the console output.

Depends on D155547

Attachment #9291483 - Attachment description: Bug 1483662 - Add Cu.dateNow() . r=arai,kmag! → Bug 1483662 - Add ChromeUtils.dateNow() . r=arai,kmag!
Attachment #9291484 - Attachment description: Bug 1483662 - [devtools] Use `Cu.dateNow()` for timestamp of evaluation result packets. r=jdescottes. → Bug 1483662 - [devtools] Use `ChromeUtils.dateNow()` for timestamp of evaluation result packets. r=jdescottes.
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/75f0dd69353d
Add microSecondTimeStamp to nsConsoleMessage, nsScriptError and ConsoleEvent. r=edgar.
https://hg.mozilla.org/integration/autoland/rev/8c9df22f12b0
[devtools] Use microSecondTimeStamp to build timeStamp for console-related resources. r=jdescottes.
https://hg.mozilla.org/integration/autoland/rev/9901cd20bbc5
Add ChromeUtils.dateNow() . r=arai,kmag
https://hg.mozilla.org/integration/autoland/rev/087477ea609d
[devtools] Use `ChromeUtils.dateNow()` for timestamp of evaluation result packets. r=jdescottes,devtools-backward-compat-reviewers.
QA Whiteboard: [qa-106b-p2]

Reproduced this issue with an affected build 63.0a1 (20180815100249) on Win 10.
Verified as fixed on Firefox 106.0 (20221010110315) on Win 10, Ubuntu 21.04 and macOS 10.13.

Status: RESOLVED → VERIFIED
QA Whiteboard: [qa-106b-p2]
status-firefox106: fixed → verified
Attachment #9012576 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: