Open Bug 1375899 Opened 7 years ago Updated 1 year ago

Console service and DOM console API have different behavior wrt to sync vs async logging, leading to confusion

Categories

(Core :: XPCOM, enhancement, P3)

53 Branch
enhancement

Tracking

()

People

(Reporter: bzbarsky, Unassigned)

References

()

Details

(Keywords: good-first-bug)

Attachments

(1 file, 1 obsolete file)

Say you have code like this:

  window.onerror = function(...args) {
    console.log("onerror", args[4]);
  }
  const target = document.createElement('div');
  target.addEventListener('foo', e => {
    console.log("1");
    throw 1;
  });
  target.addEventListener('foo', e => {
    console.log("2");
    throw 2;
  });
  target.dispatchEvent(new CustomEvent('foo', {cancelable: true}));

What this shows in the console is:

  1
  onerror 1
  2
  onerror 2
  uncaught exception: 1
  uncaught exception: 2

That is, all the exception reports come after all the console.logs.

That's because DOM console looks to me like it synchronously dispatches observer notifications for new messages, while the console service does it off a runnable.  As a result you get this weird "out-of-order" behavior.

Would it be OK to just sync-dispatch notifications when someone logs to the console service from the main thread?  Or to somehow unify the mechanisms the console API and console service use?
Depends on: 988636
No longer depends on: 988636
Attached patch consoleService.patch (obsolete) — Splinter Review
It should be fine to process the console message synchronously, but I'm wanting for a treeherder result.
Assignee: nobody → amarchesini
Attachment #8881441 - Flags: review?(bzbarsky)
Just a note: there was a fair amount of work to make console logging faster in the past, I don't think we want to make console logging calls block on their observers.
Comment on attachment 8881441 [details] [diff] [review]
consoleService.patch

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

::: xpcom/base/nsConsoleService.cpp
@@ +278,5 @@
>      NS_ReleaseOnMainThread(
>        "nsConsoleService::retiredMessage", retiredMessage.forget());
>    }
>  
> +  if (NS_IsMainThread()) {

So this prevents notifying observers about messages that are not from the main thread which is probably a bad thing.
Comment on attachment 8881441 [details] [diff] [review]
consoleService.patch

Yeah, this definitely breaks off-main-thread use of the console service, which is not ok.
Attachment #8881441 - Flags: review?(bzbarsky) → review-
Another approach would be to make the Console API async in the dispatching of messages.
Attachment #8881441 - Attachment is obsolete: true
Attachment #8881557 - Flags: review?(bzbarsky)
Comment on attachment 8881557 [details] [diff] [review]
consoleService.patch

Going to punt to Eric here.  It might be that the right thing is in fact to change the console API, not the console service, if we expect the observer notifications to be slow.
Attachment #8881557 - Flags: review?(bzbarsky) → review?(erahm)
Comment on attachment 8881557 [details] [diff] [review]
consoleService.patch

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

This seems reasonable, we can revisit perf concerns about blocking the main thread if anything shows up in profiles.
Attachment #8881557 - Flags: review?(erahm) → review+
This patch introduces an error in a devtools test:
https://treeherder.mozilla.org/logviewer.html#?job_id=111616124&repo=try&lineNumber=3598

bgrins, can you check why? It seems that the message is not received. Probably it's a timing issue.
Flags: needinfo?(bgrinstead)
(In reply to Andrea Marchesini [:baku] from comment #9)
> This patch introduces an error in a devtools test:
> https://treeherder.mozilla.org/logviewer.
> html#?job_id=111616124&repo=try&lineNumber=3598
> 
> bgrins, can you check why? It seems that the message is not received.
> Probably it's a timing issue.

I need to look closer, but if I just load the test page in a tab [0] I do see the expected "multipart/form-data" error. Also in the test I do see the error in the Browser Console but for whatever reason it's not being observed in the test runner. If I manually re-run the form.submit() call in the console during the test [1] then it is detected.

[0]: data:text/html;charset=utf-8,<form action="?" enctype="multipart/form-data"><p><label>Input <input type="text" value="test value"></label></p></form><script>document.querySelector("form").submit()</script>
[1]: https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/test/browser_webconsole_bug_595934_message_categories.js#31.
Priority: -- → P3

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:baku, could you have a look please?

Flags: needinfo?(amarchesini)
Severity: normal → S3
Flags: needinfo?(bgrinstead)
Flags: needinfo?(amarchesini)

From a short look the patch seems still applicable to the code in  nsConsoleService::LogMessageWithMode. I assume, comment 8 still applies in the sense of being reasonable but someone should do some testing if comment 9 is still an issue (and rebase the patch and transfer it to phabricator).

Assignee: amarchesini → nobody
Severity: S3 → S4
Keywords: good-first-bug
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: