611032 - Errors from before the Web Console is opened do not show

Status: RESOLVED FIXED

(DevTools :: General, defect, P1)

Description

[David Dahl :ddahl]

After bug 587734 lands, we will need to break out the HUDConsoleObserver so we can observe errors independently of the HUDService running. We will have to change it slightly so that it does not assume that the HUDService is running - instead it will cache all messages to be displayed if the web console is opened.

We will also need a pref that can be set by developers so that this observer and the ConsoelStorageService are started on final-ui-startup. Otherwise, we want this observer and service to be off.

Comment 1

[Kevin Dangoor]

How does this intersect with bug 601260?

Comment 2

[David Dahl :ddahl]

(In reply to comment #1)
> How does this intersect with bug 601260?

I think bug 601260 depends on this one. They are complimentary.

Comment 3

[David Dahl :ddahl]

Looks like we should do our initialization right in here:

http://mxr.mozilla.org/mozilla-central/source/browser/components/nsBrowserGlue.js#351

Comment 4

[Rob Campbell [:rc] (:robcee)]

acceptable.

Comment 5

[Rob Campbell [:rc] (:robcee)]

there is also a number of early startup and delayed startup locations in browser.js itself:

http://mxr.mozilla.org/mozilla-central/source/browser/base/content/browser.js#1370

Depending on when we need these things initialized to start observation, you may want to experiment with putting your hooks in different places.

Comment 6

[David Dahl :ddahl]

Attachment: crash bt and DumpJSStack

hmmm. crash while working on this patch, perhaps is unrelated as it seems to be inside of the createSandbox function. need to pull and build again.

Comment 7

[David Dahl :ddahl]

Attachment: another crash, saving here

Comment 8

[David Dahl :ddahl]

Attachment: v 0.1 Break out ErrorObserver

WIP patch. caches all exceptions, but not strict errors or css errors.

Comment 9

[Kevin Dangoor]

mass change: filter on PRIORITYSETTING

Comment 10

[David Dahl :ddahl]

Attachment: v 0.3 Break out HUDConsoleObserver

I think the crashes are not-related now, did some tweaking of the HUDService.jsm - changed the way it initializes in the browser. Not sure if this approach is going to work. As far as getting css errors properly, bug 606498 should address the window ID issue there. debugging cruft in this patch needs to be removed and a test or two needs to be written.

Comment 11

[David Dahl :ddahl]

Attachment: v 0.3.1 WIP Patch

Trimmed off bits of the patch that unintentionally affected browser.js

Comment 13

[Rob Campbell [:rc] (:robcee)]

Comment on attachment 493042 [details] [diff] [review]
v 0.3.1 WIP Patch

-var EXPORTED_SYMBOLS = ["HUDService", "ConsoleUtils"];
+var EXPORTED_SYMBOLS = ["HUDService",
+                        "ConsoleUtils",
+                        "HeadsUpDisplayUICommands",
+                        "WebConsoleErrorObserver",];

don't really need this trailing comma             ^

presumably the log()s and pprint() send and definition will be removed when ready.

-    if (!(aSubject instanceof Ci.nsIScriptError))
+    if (!(aSubject instanceof Ci.nsIScriptError) || !(aSubject instanceof Ci.nsIScriptError2))
       return;

I think we can check for instanceof Ci.nsIConsoleMessage if you want to combine these.

+        if (hudIds.length) {
+          for (let i = 0; i < hudIds.length; i++) {
+            HUDService.logActivity("console-listener", hudIds[i], aSubject);
+          }
+        }

do we need the brackets in the for loop? I guess it's consistent with this file, but it always makes me go "hmm".

And that's about the worst I can come up with. Looks good!

Comment 14

[David Dahl :ddahl]

(In reply to comment #13)
> Comment on attachment 493042 [details] [diff] [review]
> v 0.3.1 WIP Patch
> 
> -var EXPORTED_SYMBOLS = ["HUDService", "ConsoleUtils"];
> +var EXPORTED_SYMBOLS = ["HUDService",
> +                        "ConsoleUtils",
> +                        "HeadsUpDisplayUICommands",
> +                        "WebConsoleErrorObserver",];
> 
> don't really need this trailing comma             ^
ok

> 
> presumably the log()s and pprint() send and definition will be removed when
> ready.
> 
they will.

> -    if (!(aSubject instanceof Ci.nsIScriptError))
> +    if (!(aSubject instanceof Ci.nsIScriptError) || !(aSubject instanceof
> Ci.nsIScriptError2))
>        return;
> 
> I think we can check for instanceof Ci.nsIConsoleMessage if you want to combine
> these.

ah cool. wasn't sure.
> 
> +        if (hudIds.length) {
> +          for (let i = 0; i < hudIds.length; i++) {
> +            HUDService.logActivity("console-listener", hudIds[i], aSubject);
> +          }
> +        }
> 
> do we need the brackets in the for loop? I guess it's consistent with this
> file, but it always makes me go "hmm".
I always use them. it makes perfectly clear what is happening with a cursory glance of the code.

> 
> And that's about the worst I can come up with. Looks good!

danke

Comment 15

[David Dahl :ddahl]

Attachment: v 0.4 Tests included

Tests included all tests pass

Comment 16

[David Dahl :ddahl]

Attachment: v 0.4.1 Updated patch

This patch requires the console storage service patches in bug 612658 and bug 609890

Gavin: Dietrich said he would review this one if you were slammed for time. Let me know if I should pass it off.

Comment 17

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 499154 [details] [diff] [review]
v 0.4.1 Updated patch

>diff --git a/toolkit/components/console/hudservice/HUDService.jsm b/toolkit/components/console/hudservice/HUDService.jsm

>+                        "HeadsUpDisplayUICommands",

This doesn't appear to be used?

>     switch (aMessage.origin) {
>       case "network":
>       case "WebConsole":
>       case "console-listener":
>         this.logHUDMessage(aMessage, aConsoleNode, aMessageNode);
>+        // TODO: We want to record this event see bug 616318
>+        // something like:
>+        // gConsoleStorage.recordEvent(aMessage.activity.outerWindowID, aMessage.message);

I don't think you actually want to record this event if you're logging it?

>     for (let i = 0; i < len; i++) {
>-      HUDService.logConsoleAPIMessage(this.hudId,
>-                                      messages[i].level,
>-                                      messages[i].arguments);
>+      if (messages[i].nsIScriptError) {
>+        HUDService.logConsoleActivity(this.hudId, messages[i].nsIScriptError);
>+      }
>+      else {
>+        HUDService.logConsoleAPIMessage(this.hudId,
>+        messages[i].level,
>+        messages[i].arguments);
>+      }

Not sure where .nsIScriptError would come from, I don't see it in this patch?

>+WebConsoleErrorObserver = {

>+  observe: function WCEO_observe(aSubject, aTopic, aData)

>+          if (aSubject.flags in this.scriptErrorFlags) {
>+            logLevel = this.scriptErrorFlags[aSubject.flags];
>+          }

This should re-use the HUDService scriptErrorFlags rather than duplicating that mapping (and then you'll benefit from the fix for bug 613364).

>diff --git a/toolkit/components/console/hudservice/tests/browser/browser_WebConsoleErrorObserverTests.js b/toolkit/components/console/hudservice/tests/browser/browser_WebConsoleErrorObserverTests.js

>+function testErrors()

>+  testLogEntry(hud, "foo",
>+               { success: "Found error message",
>+                 err: "Error msg not found"});

This doesn't match testLogEntry's new signature (post http://hg.mozilla.org/mozilla-central/rev/5928e59882b6 )

>+  // TODO: after bug 606498 lands, these CSS error checks should also work

That bug's landed.

Comment 18

[:Gavin Sharp [email: [e-mail]]]

I wonder whether we can actually avoid doing this and just rely on the console service's cache. It caches the last 250 messages already, so rather than having the observer always active and caching things separately, we could just go through nsIConsoleService::getMessageArray() (like the error console does) on web console open and process those messages then. That would eliminate the need for most of these changes - what do you think?

Comment 19

[David Dahl :ddahl]

(In reply to comment #18)
> I wonder whether we can actually avoid doing this and just rely on the console
> service's cache. It caches the last 250 messages already, so rather than having
> the observer always active and caching things separately, we could just go
> through nsIConsoleService::getMessageArray() (like the error console does) on
> web console open and process those messages then. That would eliminate the need
> for most of these changes - what do you think?

hmm. might be a big win. I wonder what the overhead of the on-the-fly processing would bring to the console opening time.

Comment 20

[David Dahl :ddahl]

Also, with a default value of of 250 cached messages, is it possible we may not catch truncated messages before we can process or display them? (edge case - I know)

Comment 21

[David Dahl :ddahl]

I wrote a patch - will attach it here - This approach sounds great (oh man i wish it worked) - but the perf is horrific on an error-heavy site like yahoo.com, which just locked up the browser with an "unresponsive script"

Comment 22

[David Dahl :ddahl]

Attachment: v 0.1 get cached messages via nsIConsoleSvc

A "college try" - very slow on cnn, locks up on yahoo

Comment 23

[David Dahl :ddahl]

(In reply to comment #22)
> Created attachment 500967 [details] [diff] [review]
> v 0.1 get cached messages via nsIConsoleSvc
> 
> A "college try" - very slow on cnn, locks up on yahoo

On further reflection, this is a bit simplistic - in that we are probably pushing this message through the HUDConsoleObserver 2X - although - at a later time. There seems to be no avoiding that.

Comment 24

[:Gavin Sharp [email: [e-mail]]]

Hmm, that patch should only have an impact on console open, right? Not sure how it could affect just browsing to error-heavy sites...

Comment 25

[David Dahl :ddahl]

(In reply to comment #24)
> Hmm, that patch should only have an impact on console open, right? Not sure how
> it could affect just browsing to error-heavy sites...

It does only affect perf on open - i will try using a generator to yield every x messages

Comment 26

[David Dahl :ddahl]

Attachment: v 0.2 get cached messages via nsIConsoleSvc

Comment 27

[David Dahl :ddahl]

(In reply to comment #26)
> Created attachment 501210 [details] [diff] [review]
> v 0.2 get cached messages via nsIConsoleSvc

gavin:

latest patch does not have the perf issues of its predecessor. using a generator that is called by setInterval. What do you think?

Comment 28

[David Dahl :ddahl]

gavin: I can see an issue where new errors are written to the console in the wrong order, as the pre-existing erros are being written, a new error could be written before a previous error. Maybe this is a corner case. 

also: Looks like we may have access to the nsIConsoleService in a  ChromeWorker soon, according to bug 618484

Comment 29

[David Dahl :ddahl]

Attachment: v 0.2.1 get cached messages via nsIConsoleSvc

tweaked a few parameters to try to make it appear faster

Comment 30

[David Dahl :ddahl]

Attachment: v 0.3 get cached messages via nsIConsoleSvc

Thinking about abandoning this route as we do not have the currentInnerWindowID via the consoleSvc.

Comment 31

[David Dahl :ddahl]

Attachment: 0.4.2 comments addressed - original patch updated

One check failed where we turn off the cssparser toggle and still see a css warning - if the jswarn toggle is turned off, it passes. so - the same exact warning comes through the first time as a css warning and the second time as a js warning. will file a bug after I play with it for a bit.

Comment 32

[Mihai Sucan [:msucan]]

Comment on attachment 501881 [details] [diff] [review]
0.4.2 comments addressed - original patch updated

In displayCachedConsoleMessages():

+        if (messages[i].category in ["CSS Parser", "CSS Loader"]) {

Will always return false. Might explain the test failure.

In browser_WebConsoleErrorObserverTests.js:
+  // TODO: after bug 606498 lands, these CSS error checks should also work

Bug 606498 landed. I think you can enable the two tests.

In browser_webconsole_bug_589162_css_filter.js:

-  browser.removeEventListener("load", arguments.callee, true);
+  browser.removeEventListener("DOMContentLoaded", arguments.callee, true);

This change is not needed.


This patch does not apply cleanly. Does it require another patch from some other bug?

Comment 33

[Mihai Sucan [:msucan]]

Comment on attachment 501496 [details] [diff] [review]
v 0.3 get cached messages via nsIConsoleSvc

Why is the following change needed?

   outputMessageNode: function ConsoleUtils_outputMessageNode(aNode, aHUDId) {
-    ConsoleUtils.filterMessageNode(aNode, aHUDId);
+    // ConsoleUtils.filterMessageNode(aNode, aHUDId);

Comment 34

[Mihai Sucan [:msucan]]

Comment on attachment 501881 [details] [diff] [review]
0.4.2 comments addressed - original patch updated

In displayCachedConsoleMessages():

+        if (messages[i].category in ["CSS Parser", "CSS Loader"]) {
+          HUDService.reportPageError(CATEGORY_CSS, aSubject);
+        }
+        else {
+          HUDService.reportPageError(CATEGORY_JS, messages[i]);
+        }

The conditional check always fails because the in keyword doesn't work with arrays.

Additionally you have aSubject, which is undefined. That needs to be changed to messages[i].

After the two changes, all tests pass here.

Comment 35

[David Dahl :ddahl]

(In reply to comment #34)
> Comment on attachment 501881 [details] [diff] [review]
> 
> After the two changes, all tests pass here.

thanks! dumb cut n paste mistake on my part

Comment 36

[David Dahl :ddahl]

Attachment: v 0.4.3 Fixed tests, comments addressed

Comment 37

[(no longer active)]

Is there a good reason that this blocks betaN?  If not, it should be moved over to final+.

Comment 38

[David Dahl :ddahl]

(In reply to comment #37)
> Is there a good reason that this blocks betaN?  If not, it should be moved over
> to final+.

perhaps because it starts a new observer at delayed startup. that is all i can think of.

Comment 39

[David Dahl :ddahl]

Attachment: 0.5 unbitrotted

Gavin: I really hope this bug and bug 612658 and bug 609890 (r+'d) can make Final. Any chance of that?

Comment 40

[David Dahl :ddahl]

This bug and its dependencies bug 609890 and bug 612658 will really 'finish' the web console making it possible to cache and log any errors and console api calls made before the UI is displayed.

Comment 41

[Dietrich Ayala (:dietrich)]

I think this blocks. I can picture this scenario (I've lived it!):

1. load page you're working on
2. wtf?
3. open console

console is blank. web developer is frustrated. reload.

Comment 42

[Johnathan Nightingale [:johnath]]

This lost it's softblocker status and shouldn't have

Comment 43

[David Dahl :ddahl]

(In reply to comment #42)
> This lost it's softblocker status and shouldn't have

I thought the instructions were to remove [softblocker] and re-nominate. my bad.

Comment 44

[Mike Beltzner [:beltzner, not reading bugmail]]

** PRODUCT DRIVERS PLEASE NOTE **

This bug is one of 7 automatically changed from blocking2.0:final+ to blocking2.0:.x during the endgame of Firefox 4 for the following reasons:

 - it was marked as a soft blocking issue without a requirement for beta coverage

Comment 45

[David Dahl :ddahl]

Attachment: 0.5.1 unbitrot

Comment 46

[Rob Campbell [:rc] (:robcee)]

Comment on attachment 522513 [details] [diff] [review]
0.5.1 unbitrot

might want to generate this with hg -w to ignore the whitespace changes, though I'm happy to see the fixes.

+var EXPORTED_SYMBOLS = ["HUDService",
+                        "ConsoleUtils",
+                        "HeadsUpDisplayUICommands",

are the UICommands required by this patch?

-    HUDConsoleObserver.init();
+    // NOTE: the WebConsoleErrorObserver is started on delayed startup

I'd like to see a try run with some green talos lines on it. Curious if any of this affects startup time, though if things are happening in delayed startup, it shouldn't.

...

+  uninit: function WCEO_uninit()
   {
     Services.console.unregisterListener(this);
-    Services.obs.removeObserver(this, "xpcom-shutdown");
-  },
-
-  observe: function HCO_observe(aSubject, aTopic, aData)
+    Services.obs.removeObserver(this, "quit-application-granted");
+  },
+
+  observe: function WCEO_observe(aSubject, aTopic, aData)
   {
-    if (aTopic == "xpcom-shutdown") {
+    if (aTopic == "quit-application-granted") {

wondering if we shouldn't move the removeObserver call to the beginning of uninit or if we even need the uninit method at all.

-catch (ex) {
-  Cu.reportError("HUDService failed initialization.\n" + ex);
-  // TODO: kill anything that may have started up
-  // see bug 568665
-}
+XPCOMUtils.defineLazyGetter(this, "HUDService", function () {
+  try {
+    return new HUD_SERVICE();
+  }
+  catch (ex) {
+    Components.utils.reportError(ex);
+  }

Not using Cu.reportError anymore? No biggie, if you prefer being non-abbreviatey (yes, that's totally a word).

tentative r+. Nothing jumps out and screams at me from this. I do want to try another build to check on performance, but with the scrolling tweak, it might be acceptable.

Comment 47

[Rob Campbell [:rc] (:robcee)]

from a run of the hudtests with all three patches installed:


INFO TEST-START | Shutdown
Browser Chrome Test Summary
	Passed: 839
	Failed: 4
	Todo: 0

*** End BrowserChrome Test Results ***
INFO | automation.py | Application ran for: 0:01:08.825477
INFO | automation.py | Reading PID log: /var/folders/P-/P-wKrM3d2RapjE+F75BYvU+++TI/-Tmp-/tmp31VDD4pidlog
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

INFO | runtests.py | Running tests: end.
mochitest-browser-chrome failed:
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_bug_611795.js | The unknown CSS property warning is displayed only once - Got 4, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_bug_618311_private_browsing.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_bug_618311_private_browsing.js | correct number of popups shown - Got 0, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_notifications.js | We have a hud reference
make: *** [mochitest-browser-chrome] Error 1

Comment 48

[Rob Campbell [:rc] (:robcee)]

we should also remember to scroll to the end after the console is fully-populated.

Comment 49

[Rob Campbell [:rc] (:robcee)]

lastly, the WebConsoleObserver isn't bothering to track network events, is it? We still need the console opened for those to work.

Comment 50

[David Dahl :ddahl]

(In reply to comment #49)
> lastly, the WebConsoleObserver isn't bothering to track network events, is it?
> We still need the console opened for those to work.

I figured it would be best to take this one step at a time - network observer is a bit heavy in resources.

Comment 51

[Rob Campbell [:rc] (:robcee)]

(In reply to comment #50)
> (In reply to comment #49)
> > lastly, the WebConsoleObserver isn't bothering to track network events, is it?
> > We still need the console opened for those to work.
> 
> I figured it would be best to take this one step at a time - network observer
> is a bit heavy in resources.

yeah, acceptable.

Fixing the unittests should get this to the finish line, imo.

Comment 52

[David Dahl :ddahl]

Attachment: 0.5.2 unbitrot again

Still have about 4 failing checks 

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_bug_611795.js | The unknown CSS property warning is displayed only once - Got 4, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_bug_618311_private_browsing.js | Test timed out
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_bug_618311_private_browsing.js | correct number of popups shown - Got 0, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/console/hudservice/tests/browser/browser_webconsole_notifications.js | Test timed out
make: *** [mochitest-browser-chrome] Error 1

Comment 53

[Mihai Sucan [:msucan]]

Updating the title to reflect what the patch fixes.

Comment 54

[Mihai Sucan [:msucan]]

Attachment: v 0.6 rebase, fixes

Rebased the patch, made it work as intended, fixed the tests and did some patch cleanups.

Comment 55

[Mihai Sucan [:msucan]]

Attachment: v 0.7 rebase

Updated the patch, to rebase it on top of the changes from bug 609890. Also made a change to address the same contentWindow.top == contentWindow comment you had there.

Comment 56

[Mihai Sucan [:msucan]]

Attachment: v 0.8 rebase

This patch needed a rebase on top of the latest changes from bug 592469 which just landed.

Comment 57

[Mihai Sucan [:msucan]]

Attachment: v 0.9 revert for window.top

Align the patch with the change in bug 612658. Do not call recordEvent() with the inner ID of window.top.

Comment 58

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 544852 [details] [diff] [review]
v 0.9 revert for window.top

>diff --git a/browser/base/content/browser.js b/browser/base/content/browser.js

>+  // Enable WebConsoleErrorObserver
>+  WebConsoleErrorObserver.init();

This doesn't really belong in browser.js (once-per-window), it's more of a once-per-session thing.

What happened to the strategy of using nsIConsoleService from comment 18, though? Seems like there was a patch that went with that strategy, and I can't see why or where we decided to go back to this approach. ConsoleAPIStorage wasn't really intended for this use, so if we do end up going this way we'd probably want to at least rename it...

Comment 59

[:Gavin Sharp [email: [e-mail]]]

Oh, I see - comment 30. Can we just fix that instead?

Comment 60

[Mihai Sucan [:msucan]]

Thanks for your review!

(In reply to comment #59)
> Oh, I see - comment 30. Can we just fix that instead?

That can be fixed if we update the Gecko code to add the innerWindowId as well to nsIScriptError2 messages, or we have to rely on outer window IDs - meaning that messages from multiple pages that share the same outer window ID will show in the Web Console.

Also, if we do this, we are required to fix bug 669861 as well. Otherwise we'll have all of the Console API messages dumped before (or after) the error messages. We need to mix the two, by sorting them by timestamp.

Fixing bug 669861 requires two changes: we add a timestamp to all of the ConsoleAPIStorage events recorded, and finally we add a timestamp to all of the nsIScriptError2 messages in Gecko.

Shall we go for this?

Comment 61

[Mihai Sucan [:msucan]]

Attachment: v 0.10 back to nsIConsoleService

Changes:

- rebased on top of bug 670896.
- switched back to using the nsIConsoleService cache.
- added a timeStamp property to the ConsoleAPI.
- added code that sorts cached ConsoleAPI messages and the nsIScriptErrors.
- fixed a bug in ConsoleAPIStorage. getEvents() shouldn't return a reference to the original array in _consoleStorage.
- added logic to allow us to display custom timestamps for messages in outputNode.

Some of these changes fix bug 669861 as well.


Problems:

- displayCachedConsoleMessages() is rather ugly now. We get the ConsoleAPIStorage messages, we then filter nsIScriptErrors, sort and finally display them. Suggestions for improvements are welcome!

- We don't handle iframes. This should be easy ( and ugly :) ) to fix in a follow up patch, in some other bug. (as we agreed on IRC)

- nsIConsoleService does not have a way to remove individual messages, or to clear all messages associated to a specific inner window ID. This means that the Web Console clear button only temporarily clears nsIScriptErrors. They show again after reopen.

This should be fixed inside the nsIConsoleService. The 250 messages limit is also hard coded...

Looking forward to your review. Thank you!

Comment 62

[Mihai Sucan [:msucan]]

Attachment: v 0.11 rebase and cleanup

Updated the patch. Changes:

- rebased the patch on top of the latest fxteam repo, and on top of the latest changes from bug 670896.
- cleaned up. I removed the changes to browser.js - we no longer need to start the Web Console error observer on browser startup, since we are using the nsIConsoleService cache.

The problems mentioned in comment 61 are still valid. Please let me know if the handling of iframes and/or the nsIConsoleService clearing of messages per inner window ID ... problems need to be addressed here, or if we can do these in separate follow up bugs.

Thank you!

Comment 63

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 550140 [details] [diff] [review]
v 0.11 rebase and cleanup

>diff --git a/browser/devtools/webconsole/HUDService.jsm b/browser/devtools/webconsole/HUDService.jsm

>   displayCachedConsoleMessages: function HUD_displayCachedConsoleMessages()

>+    // Filter the errors to find only those we should display.
>+    (errors.value || []).forEach(function(aError) {
...
>+        messages.push(aError);

I think Array.filter() and then Array.concat() is more efficient (and you should only need to check (aError instanceof nsIScriptError2)).

>+    messages.sort(function(a, b) {
>+      let aTimeStamp = a instanceof Ci.nsIScriptError2 ?
>+                       Math.round(a.timeStamp / 1000) : a.timeStamp;

It's really unfortunate that the timestamps aren't the same. Can we fix that by making the nsIScriptError2 timestamp be in milliseconds?

>   init: function HCO_init()

>-    Services.obs.addObserver(this, "xpcom-shutdown", false);
>+    Services.obs.addObserver(this, "quit-application-granted", false);

Why this change?

>diff --git a/dom/base/ConsoleAPIStorage.jsm b/dom/base/ConsoleAPIStorage.jsm

>   getEvents: function CS_getEvents(aId)
>   {
>-    return _consoleStorage[aId] || [];

You could just change this to:

return (_consoleStorage[aId] || []).concat() (or .slice())

Comment 64

[Mihai Sucan [:msucan]]

(In reply to comment #63)
> Comment on attachment 550140 [details] [diff] [review] [diff] [details] [review]
> v 0.11 rebase and cleanup
> 
> >diff --git a/browser/devtools/webconsole/HUDService.jsm b/browser/devtools/webconsole/HUDService.jsm
> 
> >   displayCachedConsoleMessages: function HUD_displayCachedConsoleMessages()
> 
> >+    // Filter the errors to find only those we should display.
> >+    (errors.value || []).forEach(function(aError) {
> ...
> >+        messages.push(aError);
> 
> I think Array.filter() and then Array.concat() is more efficient (and you
> should only need to check (aError instanceof nsIScriptError2)).

aError instanceof Ci.nsIScriptError is also needed to get the other properties of the script error object. Anyhow, to address this I made some changes in the patch to "clean up" this. Please let me know if what I did is fine.


> >+    messages.sort(function(a, b) {
> >+      let aTimeStamp = a instanceof Ci.nsIScriptError2 ?
> >+                       Math.round(a.timeStamp / 1000) : a.timeStamp;
> 
> It's really unfortunate that the timestamps aren't the same. Can we fix that
> by making the nsIScriptError2 timestamp be in milliseconds?

We can, if bz agrees. ;)

I just updated the patch from bug 670896 to give us millisecond timestamps.

> >   init: function HCO_init()
> 
> >-    Services.obs.addObserver(this, "xpcom-shutdown", false);
> >+    Services.obs.addObserver(this, "quit-application-granted", false);
> 
> Why this change?

David Dahl had this change in earlier patches. I also asked him why, and he explained that it helps with making the HUDService shutdown earlier, less prone to errors. Having checked the MDN information it looks like a reasonable change, hence I kept it.

Please let me know if this is fine with you.


> >diff --git a/dom/base/ConsoleAPIStorage.jsm b/dom/base/ConsoleAPIStorage.jsm
> 
> >   getEvents: function CS_getEvents(aId)
> >   {
> >-    return _consoleStorage[aId] || [];
> 
> You could just change this to:
> 
> return (_consoleStorage[aId] || []).concat() (or .slice())

Done.

Thanks for your comments!

Comment 65

[Mihai Sucan [:msucan]]

Attachment: v 0.12 rebase and address comments

Rebased the patch and addressed the latest comments.

Looking forward to your review. Thank you!

Comment 66

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 550664 [details] [diff] [review]
v 0.12 rebase and address comments

>diff --git a/browser/devtools/webconsole/HUDService.jsm b/browser/devtools/webconsole/HUDService.jsm

>-  logConsoleAPIMessage: function HS_logConsoleAPIMessage(aHUDId, aMessage)
>+  logConsoleAPIMessage:
>+  function HS_logConsoleAPIMessage(aHUDId, aMessage, aUseTimeStamp)

>-  reportPageError: function HS_reportPageError(aCategory, aScriptError)
>+  reportPageError: function HS_reportPageError(aScriptError, aUseTimeStamp)

Why are these aUseTimeStamp changes necessary? Won't all of the message objects always have timeStamps? Can't you just always use them? I don't see any callers that wouldn't.

>   displayCachedConsoleMessages: function HUD_displayCachedConsoleMessages()

>+    messages.push.apply(messages, filteredErrors);

use .concat()

>diff --git a/browser/devtools/webconsole/test/browser/browser_WebConsoleErrorObserverTests.js b/browser/devtools/webconsole/test/browser/browser_WebConsoleErrorObserverTests.js

>+/* ***** BEGIN LICENSE BLOCK *****

Can use the shortened PD license here (https://www.mozilla.org/MPL/boilerplate-1.1/pd-c)

>diff --git a/dom/base/ConsoleAPIStorage.jsm b/dom/base/ConsoleAPIStorage.jsm

>   getEvents: function CS_getEvents(aId)
>   {
>-    return _consoleStorage[aId] || [];
>+    return (_consoleStorage[aId] || []).slice(0);
>   },

I think .concat() is the more idiomatic way to return a copy of an array, fwiw. Did this come up as an issue in practice? It's a shame we can't really easily produce a true copy - even with this callers need to be careful to avoid modifying the returned objects (in the array).

Having to merge together and sort entries from two separate stores is sucky. We should make sure to get a followup on file to make this sane, by getting rid of nsIConsoleService in favor of something more like ConsoleAPIStorage (merging the two, long term).

This also reminded me of some HUDService changes that could use followups, if they don't already exist:
- move reportPageError/logConsoleAPIMessage to be methods on HUD instances rather than HUD service
- have reportPageError/logConsoleAPIMessage share more code (consolidate into one method). This would be helped by making the message objects more similar.

r- because of the aUseTimeStamp changes which I think are unnecessary, but otherwise I think this looks fine.

Comment 67

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #66)
> Comment on attachment 550664 [details] [diff] [review]
> v 0.12 rebase and address comments
> 
> >diff --git a/browser/devtools/webconsole/HUDService.jsm b/browser/devtools/webconsole/HUDService.jsm
> 
> >-  logConsoleAPIMessage: function HS_logConsoleAPIMessage(aHUDId, aMessage)
> >+  logConsoleAPIMessage:
> >+  function HS_logConsoleAPIMessage(aHUDId, aMessage, aUseTimeStamp)
> 
> >-  reportPageError: function HS_reportPageError(aCategory, aScriptError)
> >+  reportPageError: function HS_reportPageError(aScriptError, aUseTimeStamp)
> 
> Why are these aUseTimeStamp changes necessary? Won't all of the message
> objects always have timeStamps? Can't you just always use them? I don't see
> any callers that wouldn't.

Yeah, unfortunately I know, it's ugly. I did what you request here in my initial implementation. The result was that the Web Console would show messages with varying microseconds. Messages do not come into the Web Console in a chronologically strict order, which means we see messages that appear "from past" and "future" (in relation to each other). The solution would be to keep the list always sorted irrespective of when the messages come, but that's more work than to add an attribute like aUseTimeStamp.

Thoughts?

Keeping the list sorted will be uglier and slower code...



> Having to merge together and sort entries from two separate stores is sucky.
> We should make sure to get a followup on file to make this sane, by getting
> rid of nsIConsoleService in favor of something more like ConsoleAPIStorage
> (merging the two, long term).

True. Will open a follow up bug.

> This also reminded me of some HUDService changes that could use followups,
> if they don't already exist:
> - move reportPageError/logConsoleAPIMessage to be methods on HUD instances
> rather than HUD service

Agreed, there's bug 592523 on moving methods from HUDService into the HUD instances.

> - have reportPageError/logConsoleAPIMessage share more code (consolidate
> into one method). This would be helped by making the message objects more
> similar.

This would probably be covered by work in bug 592523.

> r- because of the aUseTimeStamp changes which I think are unnecessary, but
> otherwise I think this looks fine.

Given the explanation above, please let me know what course of action you agree with. I will update the patch accordingly.


Thanks for your review!

Comment 68

[:Gavin Sharp [email: [e-mail]]]

(In reply to Mihai Sucan [:msucan] from comment #67)
> Yeah, unfortunately I know, it's ugly. I did what you request here in my
> initial implementation. The result was that the Web Console would show
> messages with varying microseconds. Messages do not come into the Web
> Console in a chronologically strict order, which means we see messages that
> appear "from past" and "future" (in relation to each other).

I don't understand this. Why are messages received out of order? Isn't it all error reporting synchronous?

Comment 69

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #68)
> (In reply to Mihai Sucan [:msucan] from comment #67)
> > Yeah, unfortunately I know, it's ugly. I did what you request here in my
> > initial implementation. The result was that the Web Console would show
> > messages with varying microseconds. Messages do not come into the Web
> > Console in a chronologically strict order, which means we see messages that
> > appear "from past" and "future" (in relation to each other).
> 
> I don't understand this. Why are messages received out of order? Isn't it
> all error reporting synchronous?

I didn't do a fine-grained check to see why these things happen, but we do receive messages from the window.console API and from the nsIConsoleService. At least between the two ... there are small micro-second differences. The two logging mechanisms are not in sync.

Comment 70

[:Gavin Sharp [email: [e-mail]]]

Ah, so it's just a matter of the timestamps having different precision/accuracy? That's unfortunate. I guess one uses Date.now() and the other users PR_Now()? I wonder whether there's an easy way to fix that discrepancy...

Comment 71

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

(In reply to Gavin Sharp from comment #70)
> Ah, so it's just a matter of the timestamps having different
> precision/accuracy? That's unfortunate. I guess one uses Date.now() and the
> other users PR_Now()? I wonder whether there's an easy way to fix that
> discrepancy...

bz mentions in bug 670896 comment 26 that PR_Now() does not guarantee non-decreasing timestamps.

Comment 72

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #70)
> Ah, so it's just a matter of the timestamps having different
> precision/accuracy? That's unfortunate. I guess one uses Date.now() and the
> other users PR_Now()? I wonder whether there's an easy way to fix that
> discrepancy...

The nsIScriptError2 timeStamp is in milliseconds (supposedly the same as Date.now()). But as Panos points out, PR_Now() doesn't guarantee non-decreasing timestamps.

I wouldn't say it's just a matter of having timestamps at the same precision/accuracy. The async nature of all messages going through the Web Console is also important.

Comment 73

[:Gavin Sharp [email: [e-mail]]]

(In reply to Mihai Sucan [:msucan] from comment #72)
> I wouldn't say it's just a matter of having timestamps at the same
> precision/accuracy. The async nature of all messages going through the Web
> Console is also important.

Where are things async? As far as I know error reporting it entirely synchronous.

Comment 74

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #73)
> (In reply to Mihai Sucan [:msucan] from comment #72)
> > I wouldn't say it's just a matter of having timestamps at the same
> > precision/accuracy. The async nature of all messages going through the Web
> > Console is also important.
> 
> Where are things async? As far as I know error reporting it entirely
> synchronous.

Inside Gecko I don't know the answer.

We use Services.console.registerListener() which is from the Web Console perspective an "event listener": we receive the error reports whenever they happen, our handler deals with the objects we get. It's async from our code's perspective. Same goes for the Services.obs.addObserver() which is also an "event listener" - we use it to track events coming from the window.console API. Is there anything that guarantees messages come in a specific order related to each other? Afaik, no.

Comment 75

[Mihai Sucan [:msucan]]

Here's a screenshot:

http://img.i7m.de/show/ervp8.png

(aUseTimeStamp = true, always)

Did a bit of testing and it looks like the diff only appears between console API and error messages (between the two types of messages). Otherwise, console API messages themselves (and nsIScriptErrors) seem to not have decreasing timestamps.

Comment 76

[:Gavin Sharp [email: [e-mail]]]

(In reply to Mihai Sucan [:msucan] from comment #74)
> We use Services.console.registerListener() which is from the Web Console
> perspective an "event listener": we receive the error reports whenever they
> happen, our handler deals with the objects we get. It's async from our
> code's perspective. Same goes for the Services.obs.addObserver() which is
> also an "event listener" - we use it to track events coming from the
> window.console API. Is there anything that guarantees messages come in a
> specific order related to each other? Afaik, no.

Those aren't really "event listeners", but even if they were, event dispatch is also generally synchronous. In this case, nsIObserver::observe and nsIConsoleListener::observe are called directly, so while it's theoretically possible for someone to trigger an error asynchronously, I'm pretty sure that doesn't actually happen in practice. Event listeners/observers allow for async communication, but they don't require it, and the majority of such uses are synchronous, so you are garanteed to receive errors in the order that they are triggered.

It sounds like the only issue here is the timestamp discrepancy, and I'm not sure how to best address that, short of rewriting nsScriptError in JS so that it can use Date.now() (I don't know whether that's actually feasible).

Comment 77

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #76)
> It sounds like the only issue here is the timestamp discrepancy, and I'm not
> sure how to best address that, short of rewriting nsScriptError in JS so
> that it can use Date.now() (I don't know whether that's actually feasible).

That's not easily doable, at least it goes far beyond the purpose of this bug.

What course of action would be best here, at this point?

Comment 78

[:Gavin Sharp [email: [e-mail]]]

(In reply to Mihai Sucan [:msucan] from comment #77)
> That's not easily doable, at least it goes far beyond the purpose of this
> bug.

Sure, but it seems like a problem that we need to solve at some point either way. Even with this patch's workaround of not using the message-provided timestamps for normal logging, we still run into the ordering issues when we display cached messages, right? That doesn't need to necessarily block this, but if we can find a solution that's easy enough to implement such that we can avoid the messier code, we should do that.

> What course of action would be best here, at this point?

bz might have ideas about a better timestamp to use for nsIScriptError.

Comment 79

[Boris Zbarsky [:bzbarsky]]

PR_Now and Date.now() are both system time, computed in slightly different ways.  Neither one is nondecreasing.

> As far as I know error reporting it entirely synchronous.

The console service notifies console listeners asynchronously.  Does that change any of the above discussion about timestamps, or are timestamps really our only problem here?

Comment 80

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #78)
> (In reply to Mihai Sucan [:msucan] from comment #77)
> > That's not easily doable, at least it goes far beyond the purpose of this
> > bug.
> 
> Sure, but it seems like a problem that we need to solve at some point either
> way. Even with this patch's workaround of not using the message-provided
> timestamps for normal logging, we still run into the ordering issues when we
> display cached messages, right? That doesn't need to necessarily block this,
> but if we can find a solution that's easy enough to implement such that we
> can avoid the messier code, we should do that.

The displaying of cached messages is a different story. We have two caches from where we read the messages (one is the nsIConsoleService and the other is the ConsoleAPIStorage). We read one, then we read the other. We have to sort the messages coming from both stores because we need to correctly interleave them in the output. This is not a problem related to timestamps or anything like that. Sorting works and we always get the messages with increasing timestamps - no ordering issues here.

Comment 81

[:Gavin Sharp [email: [e-mail]]]

(In reply to Mihai Sucan [:msucan] from comment #80)
> Sorting works and we always get the messages with
> increasing timestamps - no ordering issues here.

If that's true, then the different source for timestamps isn't the problem, since those two caches contain items that use those two different timestamps.

We need to understand the underlying cause of the ordering issue to move forward here.

If nsIConsoleService does indeed dispatch messages asynchronously as bz suggests, then that could be the problem. I don't see where that happens, though - nsConsoleService::LogMessage seems to notify observers synchronously.

Comment 82

[Josh Matthews [:jdm]]

The console service creates asynchronous proxies for all listeners so that observers can exist on any thread.

Comment 83

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp from comment #81)
> (In reply to Mihai Sucan [:msucan] from comment #80)
> > Sorting works and we always get the messages with
> > increasing timestamps - no ordering issues here.
> 
> If that's true, then the different source for timestamps isn't the problem,
> since those two caches contain items that use those two different timestamps.
> 
> We need to understand the underlying cause of the ordering issue to move
> forward here.
> 
> If nsIConsoleService does indeed dispatch messages asynchronously as bz
> suggests, then that could be the problem. I don't see where that happens,
> though - nsConsoleService::LogMessage seems to notify observers
> synchronously.

I'm almost sure the difference is caused by the async nature of some parts in nsIConsoleService. But we should get a Gecko expert opinion here.

Comment 84

[Boris Zbarsky [:bzbarsky]]

> I don't see where that happens, though

See comment 82.  That becomes explicit with the patch at https://bug675221.bugzilla.mozilla.org/attachment.cgi?id=549390

Comment 85

[Rob Campbell [:rc] (:robcee)]

poking this bug for a progress update. Any news here?

Comment 86

[Kevin Dangoor]

Resetting version/target milestone which was inadvertently set in the last change.

Comment 88

[Mihai Sucan [:msucan]]

Attachment: v 0.13 rebase and address comments

Rebased patch. Addressed (some of) the review comments from comment 66, with the notable exception of aUseTimeStamp.

To move things forwards I have rebased the patch (the dependency, bug 609890 still applies cleanly).

State:

- the provided solution is certainly not ideal (like many solutions inside HUDService ... which are less ideal).

- the existing code makes things harder to provide elegant solutions to problems and new features we are adding in HUDService.

- to users the ideal solution in the source code does not matter as long as the feature is there and it works well for their needs (here: display cached errors and messages).

Proposal:

- let's get this landed, file bug reports for things we want to change, and get them prioritized, to actually get them fixed. (depends on project managers)

Implementing the ideal solution in the current state of the code will take more work than needed (cost/benefit) - unless we do more patchy work. It's a can of worms that is not easy to close. This bug shouldn't be about these problems.

Basically I suggest a pragmatic approach here - fix and improve the code as we go.

I have filled two followups: bug 692824 and bug 692829.


Thank you!

Comment 89

[:aceman]

I have added dependency on bug 122213 as supposedly you use the timestamp property from nsIscriptError2. In that bug the timestamp will move to nsIScriptError (it will probably land sooner than this bug).

Also, bug 711721 may be relevant here, but that one probably won't be done sooner than this one.

Comment 90

[:aceman]

(In reply to Gavin Sharp (use [e-mail] for email) from comment #76)
> It sounds like the only issue here is the timestamp discrepancy, and I'm not
> sure how to best address that, short of rewriting nsScriptError in JS so
> that it can use Date.now() (I don't know whether that's actually feasible).

nsScriptError is now using Date.now (via JS_Now), see discussion in bug 122213 to accommodate your needs here.
Is there any other problem left here?

Mihai, it seems bug 711721 managed to land quickly so nsIScriptError2 is no more. You'll need to update your patch again.

Comment 91

[Mihai Sucan [:msucan]]

Attachment: v 0.14 rebase

Patch rebased and updated to fit the latest changes.

Aceman: thank you for your patches and for notifying me of your work. The switch to JS_Now() has helped the situation here.

Gavin: the work around to use/not use the message time stamp is not needed (for now). Things seem to work fine now - we can always display the time stamps coming from the nsIScriptErrors and from the ConsoleStorage. At a later time, when we go for async messages coming from the network we will most-likely have to deal with the situation then.

Looking forward for your review. Thank you!

Comment 92

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 586542 [details] [diff] [review]
v 0.14 rebase

>diff --git a/browser/devtools/webconsole/HUDService.jsm b/browser/devtools/webconsole/HUDService.jsm

>+  reportPageError: function HS_reportPageError(aScriptError)
>+  {
>+    if (!(aScriptError instanceof Ci.nsIScriptError) ||
>+        !aScriptError.outerWindowID) {

This check seems redundant - outerWindowID can't be null/0 assuming the instanceof check succeeds, right?

Should this just be an assertion, given that both callers of reportPageError() already do an instanceof nsIScriptError check?

>   displayCachedConsoleMessages: function HUD_displayCachedConsoleMessages()

How does this perform for large backlogs of errors?

>+    messages.push.apply(messages, filteredErrors);

Hmm, I suppose this is more efficient than concat() since it avoids copying "messages"? Seems to be the case for us, but V8 seems to perform better with concat() (http://jsperf.com/array-prototype-push-apply-vs-concat/3 ). Interesting!

>+        HUDService.reportPageError(aMessage, true);

>+        HUDService.logConsoleAPIMessage(this.hudId, aMessage, true);

Last parameter of these now doesn't exist :)

>diff --git a/browser/devtools/webconsole/test/browser_WebConsoleErrorObserverTests.js b/browser/devtools/webconsole/test/browser_WebConsoleErrorObserverTests.js

This looks like a generic test that checks console output for JS/CSS. Don't we already have that coverage? Shouldn't the test be checking that messages stay on close/reopen of the console?

Comment 93

[Mihai Sucan [:msucan]]

(In reply to Gavin Sharp (use [e-mail] for email) from comment #92)
> Comment on attachment 586542 [details] [diff] [review]
> v 0.14 rebase
> 
> >diff --git a/browser/devtools/webconsole/HUDService.jsm b/browser/devtools/webconsole/HUDService.jsm
> 
> >+  reportPageError: function HS_reportPageError(aScriptError)
> >+  {
> >+    if (!(aScriptError instanceof Ci.nsIScriptError) ||
> >+        !aScriptError.outerWindowID) {
> 
> This check seems redundant - outerWindowID can't be null/0 assuming the
> instanceof check succeeds, right?

The callers of reportPageError() do check if the given object is an instance of nsIScriptError, so yes, that check is redundant. I am going to remove this check.

However, outerWindowID is not guaranteed to be available for nsIScriptError messages. There are cases when we receive messages with outer/innerWindowIDs set to 0. (they can't be null) I'd like to keep this check.


> Should this just be an assertion, given that both callers of
> reportPageError() already do an instanceof nsIScriptError check?
> 
> >   displayCachedConsoleMessages: function HUD_displayCachedConsoleMessages()
> 
> How does this perform for large backlogs of errors?

This feature has been tested a lot. Performance will be something we need to be on the lookout on this one.


> >+        HUDService.reportPageError(aMessage, true);
> 
> >+        HUDService.logConsoleAPIMessage(this.hudId, aMessage, true);
> 
> Last parameter of these now doesn't exist :)

Thanks for the catch!


> >diff --git a/browser/devtools/webconsole/test/browser_WebConsoleErrorObserverTests.js b/browser/devtools/webconsole/test/browser_WebConsoleErrorObserverTests.js
> 
> This looks like a generic test that checks console output for JS/CSS. Don't
> we already have that coverage?

We do have those, but they are spread across different types of tests, for different categories and purposes. It made more sense to have a separate test for the purpose of cached messages.

You do have a point - I could merge this test into the ConsoleAPI cached messages test. Would that be fine with you? I believe the result would not be bloated - we can have a browser_cachedmessages.js test file.

> Shouldn't the test be checking that messages stay on close/reopen of the console?

Will do.

Comment 94

[Mihai Sucan [:msucan]]

Attachment: [in-fx-team] v 0.15 address review comments

Addressed the review comments.

Did some perf testing and noticed that hiding the outputNode before displaying the cached messages improves performance on sites that have many errors/warnings. This is similar to the strategy of disabling scroll during the output of the numerous messages.

If we will still have problems with the performance of this feature, we will fix them in new bugs.

Gavin, thank you very much for your review!


Try push results:
https://tbpl.mozilla.org/?tree=Try&rev=746127ed6c6f

Builds:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-746127ed6c6f

Comment 95

[Mihai Sucan [:msucan]]

Comment on attachment 587643 [details] [diff] [review]
[in-fx-team] v 0.15 address review comments

Landed:
https://hg.mozilla.org/integration/fx-team/rev/ef5124de30f3

Comment 96

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/mozilla-central/rev/ef5124de30f3

Comment 97

[Eric Shepherd [:sheppy]]

Documentation updated:

https://developer.mozilla.org/en/Tools/Web_Console/

And mentioned on Firefox 12 for developers.