Closed Bug 955592 Opened 10 years ago Closed 10 years ago

Make UTF-8 conversion warnings less noisy

Categories

(Chat Core :: IRC, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: aleth, Assigned: aleth)

References

Details

Attachments

(1 file, 7 obsolete files)

*** Original post on bio 2153 at 2013-09-06 11:42:00 UTC ***

STR: LIST on freenode.

We should certainly drop these warnings for LIST responses. 

Would it make sense to only log UTF-8 warnings for actual messages?
*** Original post on bio 2153 at 2013-09-06 11:46:40 UTC ***

Are you suggesting not trying to convert the entire message but only the payload of specific messages?

I don't really like this idea, I think it would break (hard) on networks that have everything in a different encoding.
*** Original post on bio 2153 at 2013-09-06 11:50:39 UTC ***

No, this bug is about when to log the conversion problem *with a separate warning*, not about changing the conversion behaviour.
*** Original post on bio 2153 at 2013-09-06 11:57:24 UTC ***

(In reply to comment #0)

> Would it make sense to only log UTF-8 warnings for actual messages?

Not sure, but I'm also sometimes annoyed by such warnings in the MOTD of some freenode servers. They are similarly pointless.
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2842 at 2013-09-06 19:45:00 UTC ***

This improves the situation in a few ways:

- Turn conversion warnings into DEBUG messages. I think it's OK if it takes looking at the debug log to see these? Maybe there is a use case I overlooked.

- Either log the raw message on its own, or a conversion warning containing the raw message, but not both (saves one this.DEBUG call).

- Either log "Unhandled message" or the stringified handled message, but not both (iirc this was the behaviour before the recent changes).

Looking at this code, I was wondering if we really need to log rawMessage twice (once at the beginning, and then once contained in the parsed message object). I suppose it may help if there is a bug in dequoting? Otherwise we could delete it from the message object before JSON.stringify.
Attachment #8354612 - Flags: review?(clokep)
Assignee: nobody → aleth
Status: NEW → ASSIGNED
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2843 at 2013-09-06 19:48:00 UTC ***

Removes a NOT for legibility.
Attachment #8354613 - Flags: review?(clokep)
Comment on attachment 8354612 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2842 at 2013-09-06 19:48:18 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354612 - Attachment is obsolete: true
Attachment #8354612 - Flags: review?(clokep)
Comment on attachment 8354613 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2843 at 2013-09-07 12:30:17 UTC ***

I think this is ok. I'll want to lol one more time though. Please don't arbitrarily remove whitespace.
Attachment #8354613 - Flags: review?(clokep) → review-
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2845 at 2013-09-07 12:47:00 UTC ***

In the interest of further lols, deletes rawMessage before the second DEBUG. Seems to produce more legible debug logs, YMMV.
Attachment #8354615 - Flags: review?(clokep)
Comment on attachment 8354613 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2843 at 2013-09-07 12:47:15 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354613 - Attachment is obsolete: true
Summary: Don't log UTF-8 conversion warnings during LIST → Make UTF-8 conversion warnings less noisy
*** Original post on bio 2153 at 2013-09-07 12:52:54 UTC ***

Comment on attachment 8354615 [details] [diff] [review] (bio-attmnt 2845)
Patch

>diff --git a/chat/protocols/irc/irc.js b/chat/protocols/irc/irc.js

>     try {
>-      // If nothing handled the message, throw a warning.
>-      if (!ircHandlers.handleMessage(this._account, new ircMessage(aRawMessage)))
>+      let message = new ircMessage(aRawMessage);
>+      // If nothing handled the message, throw a warning, otherwise log it.
>+      if (ircHandlers.handleMessage(this._account, message)) {
>+        delete message.rawMessage;
>+        this.DEBUG(JSON.stringify(message));
>+      }
>+      else
>         this.WARN("Unhandled IRC message: " + aRawMessage);

It's a bit confusing to have this in the opposite order of the comment.

>     } catch (e) {
>       // Catch the error, display it and hope the connection can continue with
>       // this message in error. Errors are also caught inside of handleMessage,
>       // but we expect to handle message parsing errors here.
>       this.ERROR(e);

Wouldn't you want to log the raw message if we caught an exception?
*** Original post on bio 2153 at 2013-09-07 12:54:47 UTC ***

(In reply to comment #8)
> >       // Catch the error, display it and hope the connection can continue with
> >       // this message in error. Errors are also caught inside of handleMessage,
> >       // but we expect to handle message parsing errors here.
> >       this.ERROR(e);
> 
> Wouldn't you want to log the raw message if we caught an exception?

The raw message is always already logged earlier in the same method.

I wonder however if we shouldn't optimize this and only call this.DEBUG once per correctly handled message (rather than the two per message we currently have). Thoughts?
Attached patch Better patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2846 at 2013-09-07 14:23:00 UTC ***

I prefer this patch which only writes one DEBUG message per correctly handled message. It ensures we always have the unprocessed raw message in the log. (If there are problems there will be additional messages.) Seems easier to read too.
Attachment #8354616 - Flags: review?(clokep)
Comment on attachment 8354616 [details] [diff] [review]
Better patch

*** Original change on bio 2153 attmnt 2846 at 2013-09-09 11:58:49 UTC ***

>diff --git a/chat/protocols/irc/irc.js b/chat/protocols/irc/irc.js
>     // Low level dequote: replace quote character \020 followed by 0, n, r or
>     // \020 with a \0, \n, \r or \020, respectively. Any other character is
>     // replaced with itself.
>     const lowDequote = {"0": "\0", "n": "\n", "r": "\r", "\x10": "\x10"};
>-    aRawMessage = aRawMessage.replace(/\x10./g,
>+    let dequotedMessage = aRawMessage.replace(/\x10./g,
>       function(aStr) lowDequote[aStr[1]] || aStr[1]);
Is this used anywhere? Won't this break our quoting?

> 
>     try {
>-      // If nothing handled the message, throw a warning.
>-      if (!ircHandlers.handleMessage(this._account, new ircMessage(aRawMessage)))
>+      let message = new ircMessage(dequotedMessage);
>+      // Log the message if it was handled, otherwise throw a warning.
>+      if (ircHandlers.handleMessage(this._account, message)) {
>+        delete message.rawMessage;
>+        this.DEBUG(aRawMessage + "\n" + JSON.stringify(message));
>+      }
I really don't understand this, why are we deleting the raw message and then printing it out separately? Can't we just JSON.stringify the whole thing?
Attachment #8354616 - Flags: review?(clokep) → review-
Comment on attachment 8354615 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2845 at 2013-09-09 23:59:44 UTC ***

I'm going to r- this as you seem to be happier with the other patch (and the description seems to imply it's a better way of doing it).
Attachment #8354615 - Flags: review?(clokep) → review-
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2865 at 2013-09-11 15:11:00 UTC ***

(In reply to comment #11)
> >+    let dequotedMessage = aRawMessage.replace(/\x10./g,
> >       function(aStr) lowDequote[aStr[1]] || aStr[1]);
> Is this used anywhere? Won't this break our quoting?

The code was correct, but I've changed it in the current patch to make it clearer what is going on.

> >+      if (ircHandlers.handleMessage(this._account, message)) {
> >+        delete message.rawMessage;
> >+        this.DEBUG(aRawMessage + "\n" + JSON.stringify(message));
> >+      }
> I really don't understand this, why are we deleting the raw message and then
> printing it out separately? Can't we just JSON.stringify the whole thing?

The point is to ensure the original raw message is the one included in the debug log. message.rawMessage is potentially converted, and dequoted.
I decided to remove message.rawMessage as I think it doesn't need including in the debug log - it makes it harder to read and it's right underneath the original raw message anyway, now that there is only one DEBUG line per message rather than two. (Instead one could drop the original message and just JSON.stringify the handled message, but apart from the obvious drawback it also makes debug logs harder to read imho than if the message is on its own line in plaintext.)
Attachment #8354635 - Flags: review?(clokep)
Comment on attachment 8354615 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2845 at 2013-09-11 15:11:05 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354615 - Attachment is obsolete: true
Comment on attachment 8354616 [details] [diff] [review]
Better patch

*** Original change on bio 2153 attmnt 2846 at 2013-09-11 15:11:05 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354616 - Attachment is obsolete: true
Comment on attachment 8354635 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2865 at 2013-09-11 16:50:36 UTC ***

(In reply to comment #13)
> Created attachment 8354635 [details] [diff] [review] (bio-attmnt 2865) [details]
> Patch
> 
> (In reply to comment #11)
> > >+    let dequotedMessage = aRawMessage.replace(/\x10./g,
> > >       function(aStr) lowDequote[aStr[1]] || aStr[1]);
> > Is this used anywhere? Won't this break our quoting?
> 
> The code was correct, but I've changed it in the current patch to make it
> clearer what is going on.
> 
> > >+      if (ircHandlers.handleMessage(this._account, message)) {
> > >+        delete message.rawMessage;
> > >+        this.DEBUG(aRawMessage + "\n" + JSON.stringify(message));
> > >+      }
> > I really don't understand this, why are we deleting the raw message and then
> > printing it out separately? Can't we just JSON.stringify the whole thing?
> 
> The point is to ensure the original raw message is the one included in the
> debug log. message.rawMessage is potentially converted, and dequoted.
> I decided to remove message.rawMessage as I think it doesn't need including in
> the debug log - it makes it harder to read and it's right underneath the
> original raw message anyway, now that there is only one DEBUG line per message
> rather than two. (Instead one could drop the original message and just
> JSON.stringify the handled message, but apart from the obvious drawback it also
> makes debug logs harder to read imho than if the message is on its own line in
> plaintext.)

Let's save the original message then like you had it. (I did ask a question, not ask you to revert it. ;)) Please just log everything using JSON.stringify, it's less confusing, in my opinion. We can always tweak that later if we need to.
Attachment #8354635 - Flags: review?(clokep) → review-
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2867 at 2013-09-11 16:58:00 UTC ***

Reverts to JSON.stringifying the full message object. (I didn't completely revert the change to the temporary variable because this way also allows to save a this.DEBUG call when there is a conversion error.)
Attachment #8354637 - Flags: review?(clokep)
Comment on attachment 8354635 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2865 at 2013-09-11 16:58:40 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354635 - Attachment is obsolete: true
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2153 as attmnt 2872 at 2013-09-11 19:37:00 UTC ***

Follows your suggestion of only logging the raw message within the JSON.stringify output. I decided to keep dequoting where it is for the moment, as I'm not sure moving it to ircMessage (message parsing) is a good idea.
Attachment #8354642 - Flags: review?(clokep)
Comment on attachment 8354637 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2867 at 2013-09-11 19:37:41 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354637 - Attachment is obsolete: true
Attachment #8354637 - Flags: review?(clokep)
Comment on attachment 8354642 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2872 at 2013-09-11 19:44:21 UTC ***

>diff --git a/chat/protocols/irc/irc.js b/chat/protocols/irc/irc.js
>+      let message = new ircMessage(dequotedMessage);
>+      let isHandled = ircHandlers.handleMessage(this._account, message);
>+      message.rawMessage = aRawMessage; // Log the undequoted message.
Nit: "Log the quoted message." Undequoted makes my head hurt.

>+      let logEntry = JSON.stringify(message) + conversionWarning;
>+      // Log the message if it was handled, otherwise throw a warning.
>+      if (isHandled)
>+        this.DEBUG(logEntry);
>+      else
>+        this.WARN("Unhandled IRC message: " + logEntry);
Can we add a \n instead of a " " here, this will have the JSON always be the started of a line then.
Attachment #8354642 - Flags: review?(clokep) → review-
*** Original post on bio 2153 as attmnt 2873 at 2013-09-11 19:48:00 UTC ***

Nits begone.
Attachment #8354643 - Flags: review?(clokep)
Comment on attachment 8354642 [details] [diff] [review]
Patch

*** Original change on bio 2153 attmnt 2872 at 2013-09-11 19:48:50 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354642 - Attachment is obsolete: true
Comment on attachment 8354643 [details] [diff] [review]
Yet another patch

*** Original change on bio 2153 attmnt 2873 at 2013-09-11 19:52:28 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354643 - Flags: review?(clokep) → review+
Whiteboard: [checkin-needed]
*** Original post on bio 2153 at 2013-09-12 23:05:47 UTC ***

http://hg.instantbird.org/instantbird/rev/6bd72bbe30e1
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Whiteboard: [checkin-needed]
Target Milestone: --- → 1.5
Depends on: 955623
You need to log in before you can comment on or make changes to this bug.