955260 - Add an easy way to copy an account specific debug log

Status: RESOLVED FIXED

(Chat Core :: Debug, enhancement)

Description

[Florian Quèze [:florian]]

*** Original post on bio 1827 at 2012-11-25 00:28:00 UTC ***

*** Due to BzAPI limitations, the initial description is in comment 1 ***

Comment 1

[Florian Quèze [:florian]]

Attachment: WIP1

*** Original post on bio 1827 as attmnt 2128 at 2012-11-25 00:28:00 UTC ***

We discussed better debug logs several times and there are lots of great ideas floating around. I think it's time to start implementing something, even if it doesn't do half of the things we want yet.

I've scratched my head for a while today, trying to define the minimum we need to implement for this to be useful. I think the most common frustration related to debug logs these days is users sending us incomplete debug logs because copying messages from the Error Console is extremely painful.

For this first WIP, I've focused on making it trivially easy to copy a debug log with the last few (50) messages of a single account. (This still requires tweaking the log level in about:config though.)

This supports Twitter and purplexpcom.

ToDo:
- support JS-IRC and JS-XMPP (I wanted to have some feedback first though)
- check if my changes to http.jsm conflict if Thunderbird's fork of that file, and resolve the (likely) conflict.

Possible future improvements (not required for landing IMHO):
- a decent viewer available both in the UI and on the web, so that we can look at colored logs.
- start the log with the user agent (or version number + OS info), buildid and prplid.
- (not sure) a dump of all the advanced account preferences that have a non-default value.

Comment 2

[Florian Quèze [:florian]]

*** Original post on bio 1827 at 2012-11-25 00:37:19 UTC ***

Note: there are ways to optimize the code in purpleDebug to reduce the number of times we get and use the accountsService from there. (I'm not sure it's needed, and it would make the patch complicated; something I didn't want for a first proof of concept that I wanted readable :))

Comment 3

[Patrick Cloke [:clokep]]

Comment on attachment 8353889 [details] [diff] [review]
WIP1

*** Original change on bio 1827 attmnt 2128 at 2012-11-25 05:02:48 UTC ***

So I think the changes to imXPCOMUtils will make it so we log to both the error console and this new way. Is this correct? The checking of imAccount there almost makes me think we should just expose the methods directly in the interface...but maybe that is overkill.

Do the messages not have a "level" (ERROR, WARN, DEBUG, etc.)? If so, how is it specified?

Overall, I think it looks OK, but I don't love it.

Comment 4

[Florian Quèze [:florian]]

*** Original post on bio 1827 at 2012-11-25 10:16:58 UTC ***

(In reply to comment #2)
> Comment on attachment 8353889 [details] [diff] [review] (bio-attmnt 2128) [details]
> WIP1
> 
> So I think the changes to imXPCOMUtils will make it so we log to both the error
> console and this new way. Is this correct?

Correct.

> The checking of imAccount there
> almost makes me think we should just expose the methods directly in the
> interface...but maybe that is overkill.

Which interface?

> Do the messages not have a "level" (ERROR, WARN, DEBUG, etc.)? If so, how is it
> specified?

nsIScriptError doesn't have a field to store that. There's a "flags" integer that we could maybe abuse. Currently it just tells us if something is an ERROR, a warning or an exception.

> Overall, I think it looks OK, but I don't love it.

What's missing to make you love it? :-)

Comment 5

[Patrick Cloke [:clokep]]

*** Original post on bio 1827 at 2012-11-25 13:50:44 UTC ***

(In reply to comment #3)
> (In reply to comment #2)
> > So I think the changes to imXPCOMUtils will make it so we log to both the error
> > console and this new way. Is this correct?
> Correct.
Do we really want that? (Or is this until we have an awesome UI for this?)

> > The checking of imAccount there
> > almost makes me think we should just expose the methods directly in the
> > interface...but maybe that is overkill.
> Which interface?
imIAccount/prplIAccount

> > Do the messages not have a "level" (ERROR, WARN, DEBUG, etc.)? If so, how is it
> > specified?
> nsIScriptError doesn't have a field to store that. There's a "flags" integer
> that we could maybe abuse. Currently it just tells us if something is an ERROR,
> a warning or an exception.
Hmm...OK. We could add another field to the function call too, no?

> > Overall, I think it looks OK, but I don't love it.
> What's missing to make you love it? :-)
It seems clumsier to use than what we currently have. You have to initLog with the imAccount which magically adds a bunch of functions to it. I dislike this. Maybe it is just missing some of the other features we've discussed and that's why I don't love it yet. :)

Comment 6

[Florian Quèze [:florian]]

*** Original post on bio 1827 at 2012-11-25 14:32:21 UTC ***

(In reply to comment #4)
> (In reply to comment #3)
> > (In reply to comment #2)
> > > So I think the changes to imXPCOMUtils will make it so we log to both the error
> > > console and this new way. Is this correct?
> > Correct.
> Do we really want that? (Or is this until we have an awesome UI for this?)

My goal here was to fix the "it's hard/impossible to get a debug log quickly for a misbehaving account". Until we have a better UI somewhere, I think we need to keep the display in the error console.
I think we will eventually want to get rid of it (or just display errors and warnings there).

> > > The checking of imAccount there
> > > almost makes me think we should just expose the methods directly in the
> > > interface...but maybe that is overkill.
> > Which interface?
> imIAccount/prplIAccount

In prplIAccount, it would force me to implement it in purplexpcom, for no obvious benefit.
In imIAccount, it would be more difficult to reach for internal code of js prpls.
And I don't think add-ons or the UI (or anything outside the prpl implementation really) has good reasons to touch that, so I see no obvious reason to want it in the interface.

> > > Do the messages not have a "level" (ERROR, WARN, DEBUG, etc.)? If so, how is it
> > > specified?
> > nsIScriptError doesn't have a field to store that. There's a "flags" integer
> > that we could maybe abuse. Currently it just tells us if something is an ERROR,
> > a warning or an exception.
> Hmm...OK. We could add another field to the function call too, no?

We can add a level parameter to the logDebugMessage function of the imIAccount interface, yes. That will force us to create a JS object for each debug message before pushing it to the array, but I think that's a price we have to pay anyway.

> It seems clumsier to use than what we currently have. You have to initLog with
> the imAccount which magically adds a bunch of functions to it.

It's done automatically by jsProtoHelper, and seems overall cleaner to me than the current state, where we pollute the global namespace of each prpl code file.

> Maybe it is just missing some of the other features we've discussed and that's
> why I don't love it yet. :)

That's possible. I think it's important to start somewhere.

Comment 7

[aleth [:aleth]]

Comment on attachment 8353889 [details] [diff] [review]
WIP1

*** Original change on bio 1827 attmnt 2128 at 2012-11-25 14:59:36 UTC ***

This will be a great improvement, thanks! The this.LOG etc is a pain, but probably the best way (as sometimes it might need to be aAccount.LOG or such).

+1 for the suggestion of a simple viewer using colours to make the output more readable.

Comment 8

[Florian Quèze [:florian]]

Attachment: Patch v2

*** Original post on bio 1827 as attmnt 2134 at 2012-11-25 22:57:00 UTC ***

- Handled the result of our IRC discussion (1. Preserve the log level of each message. 2. Ignore the loglevel prefs for the debug logs.)
- Handled JS-XMPP.
- Tweaked the socket.jsm file to use both LOG and DEBUG instead of just one log level for everything (long overdue!)

Missing:
- Changes for JS-IRC.

Random thoughts:
- Isn't all of this wasteful for the 99% of the times where the user doesn't need any debug log and doesn't look at the error console? Shouldn't we enable all this debugging stuff only after the user has checked a box in the Advanced pane of the pref window?
- I think we need to drop the debug log of an account some time after it's been cleanly disconnected.
- The "50" const could well be worth a hidden pref with a much higher default value for debug builds.

I think only the JS-IRC point needs to be addressed before this lands (especially now that the socket.jsm logging API has changed).

Comment 9

[Florian Quèze [:florian]]

Comment on attachment 8353889 [details] [diff] [review]
WIP1

*** Original change on bio 1827 attmnt 2128 at 2012-11-25 22:57:56 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 10

[Patrick Cloke [:clokep]]

Comment on attachment 8353895 [details] [diff] [review]
Patch v2

*** Original change on bio 1827 attmnt 2134 at 2012-11-25 23:39:33 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 11

[Patrick Cloke [:clokep]]

Comment on attachment 8353895 [details] [diff] [review]
Patch v2

*** Original change on bio 1827 attmnt 2134 at 2012-11-25 23:56:39 UTC ***

>diff --git a/chat/modules/imXPCOMUtils.jsm b/chat/modules/imXPCOMUtils.jsm
> function initLogModule(aModule, aThis)
> {
>   let obj = aThis || {};
>   obj.DEBUG = scriptError.bind(obj, aModule, DEBUG_MISC);
>   obj.LOG   = scriptError.bind(obj, aModule, DEBUG_INFO);
>   obj.WARN  = scriptError.bind(obj, aModule, DEBUG_WARNING);
>   obj.ERROR = scriptError.bind(obj, aModule, DEBUG_ERROR);
Shouldn't these now refer to the imIDebugMessage levels? (They match, I just think it's weird to have these constants defined now instead of using the interface.)

My only other question is whether initLogModule is used by anything other than imAccount? Do we really need to special case it or should we make it only work for imAccounts?

r+ with using the constants from the interface.

Comment 12

[Florian Quèze [:florian]]

*** Original post on bio 1827 at 2012-11-26 00:43:46 UTC ***

(In reply to comment #8)

> >   obj.DEBUG = scriptError.bind(obj, aModule, DEBUG_MISC);
> >   obj.LOG   = scriptError.bind(obj, aModule, DEBUG_INFO);
> >   obj.WARN  = scriptError.bind(obj, aModule, DEBUG_WARNING);
> >   obj.ERROR = scriptError.bind(obj, aModule, DEBUG_ERROR);
> Shouldn't these now refer to the imIDebugMessage levels?

Yes.

> My only other question is whether initLogModule is used by anything other than
> imAccount?

I'm not aware of anything else using it, which means we could inline it in jsProtoHelper!

However, Mook may have another use case, otherwise I don't see why he would have bothered with bug 955113 (bio 1685).

Things in the UI, or in the emoticons or message themes code, or in the message filtering code, or in the interruption manager code may want to use it (they don't currently).

Comment 13

[aleth [:aleth]]

Comment on attachment 8353895 [details] [diff] [review]
Patch v2

*** Original change on bio 1827 attmnt 2134 at 2012-11-26 15:00:28 UTC ***

>- Isn't all of this wasteful for the 99% of the times where the user doesn't
>need any debug log and doesn't look at the error console? Shouldn't we enable
>all this debugging stuff only after the user has checked a box in the Advanced
>pane of the pref window?
Good idea! Even if someone reports a hard-to-reproduce problem, we can get them to turn it on "in case it happens again", and that's OK, as by the time we hear about it the first time the debug log will have been lost anyway.

>- The "50" const could well be worth a hidden pref with a much higher default
>value for debug builds.
This sounds like it would be useful (including a 0 value for capturing everything). We may wish to tweak the default value too in the next few weeks...

Comment 14

[Patrick Cloke [:clokep]]

Attachment: IRC patch

*** Original post on bio 1827 as attmnt 2135 at 2012-11-27 01:15:00 UTC ***

Here's the IRC prpl part. I had to still use initLogModule in one place (in ircHandlers.jsm) since two parts of it don't actually have a reference to any account (they're done for the protocol, not on an account basis). Let me know if this seems unreasonable.

Besides that it was mostly s/(ERROR|WARN|LOG|DEBUG)/this.\1/.

Comment 15

[Florian Quèze [:florian]]

*** Original post on bio 1827 at 2012-11-27 11:12:15 UTC ***

(In reply to comment #11)
> Created attachment 8353896 [details] [diff] [review] (bio-attmnt 2135) [details]
> IRC patch
> 
> Here's the IRC prpl part. I had to still use initLogModule in one place (in
> ircHandlers.jsm) since two parts of it don't actually have a reference to any
> account (they're done for the protocol, not on an account basis).

Is this the two ERROR calls in the _registerHandlers method? If so, would Cu.reportError(new Error("foo")); work? (and by "work" I mean report your error message with the correct location info to the Error Console.)

Comment 16

[Patrick Cloke [:clokep]]

Attachment: IRC part - v2

*** Original post on bio 1827 as attmnt 2136 at 2012-11-27 11:33:00 UTC ***

(In reply to comment #12)
> (In reply to comment #11)
> > Created attachment 8353896 [details] [diff] [review] (bio-attmnt 2135) [details]
> > IRC patch
> > 
> > Here's the IRC prpl part. I had to still use initLogModule in one place (in
> > ircHandlers.jsm) since two parts of it don't actually have a reference to any
> > account (they're done for the protocol, not on an account basis).
> 
> Is this the two ERROR calls in the _registerHandlers method? If so, would
> Cu.reportError(new Error("foo")); work? (and by "work" I mean report your error
> message with the correct location info to the Error Console.)

That works. :)

Comment 17

[Patrick Cloke [:clokep]]

Comment on attachment 8353896 [details] [diff] [review]
IRC patch

*** Original change on bio 1827 attmnt 2135 at 2012-11-27 11:33:01 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 18

[aleth [:aleth]]

Comment on attachment 8353897 [details] [diff] [review]
IRC part - v2

*** Original change on bio 1827 attmnt 2136 at 2012-11-27 14:50:32 UTC ***

NB This patch is bitrotted by http://hg.instantbird.org/instantbird/rev/e2ff32e19c78. Maybe following up on your discussion on IRC with flo we can copy the location info from the original error into the new one where we append  + e ?

Looks good otherwise :)

Comment 19

[Florian Quèze [:florian]]

Comment on attachment 8353897 [details] [diff] [review]
IRC part - v2

*** Original change on bio 1827 attmnt 2136 at 2012-11-28 00:04:57 UTC ***

>diff --git a/chat/protocols/irc/ircDCC.jsm b/chat/protocols/irc/ircDCC.jsm

>       // Parse the message and attempt to handle it.
>-      return ircHandlers.handleDCCMessage(this, DCCMessage(aMessage));
>+      return ircHandlers.handleDCCMessage(this,
>+                                          new DCCMessage(aMessage, aAccount));

Remove the "new" operator here.


>diff --git a/chat/protocols/irc/ircHandlers.jsm b/chat/protocols/irc/ircHandlers.jsm

>       } catch (e) {
>         // We want to catch an error here because one of our handlers are broken,
>         // if we don't catch the error, the whole IRC plug-in will die.
>-        ERROR("Error running command " + aCommand + " with handler " +
>-              handler.name + ":\n" + JSON.stringify(aMessage));
>+        aAccount.ERROR("Error running command " + aCommand + " with handler " +
>+                       handler.name + ":\n" + JSON.stringify(aMessage));
>         Cu.reportError(e);

I think you want the exception e to be in the debug log, so I would suggest adding:
+ "\n" + e
to the parameter given to aAccount.ERROR

The downside is that the error will be visible twice in the error console.

If we don't think the clickable location is of much value we can remove the Cu.reportError call.
If we want to keep it, I would suggest moving the Cu.reportError call before the aAccount.ERROR call as the order of the resulting errors in the Error Console would be more logicial.


Looks good otherwise, but has bitrotted from bug 954854 (bio 1419).

Comment 20

[Patrick Cloke [:clokep]]

Attachment: IRC part - v3

*** Original post on bio 1827 as attmnt 2138 at 2012-11-28 00:13:00 UTC ***

Meets review comments. I chose to remove the Cu.reportError, if we find we miss it...we can add it back.

Comment 21

[Patrick Cloke [:clokep]]

Comment on attachment 8353897 [details] [diff] [review]
IRC part - v2

*** Original change on bio 1827 attmnt 2136 at 2012-11-28 00:13:59 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 22

[Patrick Cloke [:clokep]]

*** Original post on bio 1827 at 2012-11-28 00:37:54 UTC ***

Checked in as http://hg.instantbird.org/instantbird/rev/5e9a515b6042 and http://hg.instantbird.org/instantbird/rev/3da2d24bcccc

Comment 23

[Florian Quèze [:florian]]

Comment on attachment 8353895 [details] [diff] [review]
Patch v2

*** Original change on bio 1827 attmnt 2134 at 2012-11-28 00:39:19 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 24

[Florian Quèze [:florian]]

Comment on attachment 8353899 [details] [diff] [review]
IRC part - v3

*** Original change on bio 1827 attmnt 2138 at 2012-11-28 00:39:36 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 25

[Florian Quèze [:florian]]

Comment on attachment 8353897 [details] [diff] [review]
IRC part - v2

*** Original change on bio 1827 attmnt 2136 at 2012-11-28 00:39:56 UTC was without comment, so any subsequent comment numbers will be shifted ***

Comment 26

[Florian Quèze [:florian]]

Comment on attachment 8353899 [details] [diff] [review]
IRC part - v3

*** Original change on bio 1827 attmnt 2138 at 2012-11-28 00:41:31 UTC ***

Looks good except:
01:23:14 - flo-retina: you removed conversationErrorMessage from the exported symbols
01:23:28 - clokep: Doh. Bitrot indeed.

I fixed that before the check-in.

Comment 27

[Patrick Cloke [:clokep]]

*** Original post on bio 1827 at 2012-11-28 01:10:51 UTC ***

And http://hg.instantbird.org/instantbird/rev/7388215d9c62 to fix the test bustage for IRC.