Closed Bug 955623 Opened 10 years ago Closed 10 years ago

this._account socket error on disconnect [regression]

Categories

(Chat Core :: IRC, defect)

defect
Not set
minor

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: aleth, Assigned: aleth)

References

Details

(Whiteboard: [1.5-wanted])

Attachments

(1 file, 2 obsolete files)

*** Original post on bio 2180 at 2013-09-24 20:01:00 UTC ***

Timestamp: 09/24/2013 10:00:01 PM
Error: [Exception... "'TypeError: this._account is undefined' when calling method: [nsIStreamListener::onDataAvailable]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0"  data: no]
Blocks: 955592, 955430
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 2180 as attmnt 2901 at 2013-09-24 20:28:00 UTC ***

Caused by the ERROR message being logged after the socket has disconnected.

This is annoying and I can't think of a better fix.
Attachment #8354671 - Flags: review?(clokep)
Assignee: nobody → aleth
Status: NEW → ASSIGNED
Comment on attachment 8354671 [details] [diff] [review]
Patch

*** Original change on bio 2180 attmnt 2901 at 2013-10-11 17:30:55 UTC ***

Does this occur when we've successfully disconnected or is it if we get data on the socket after we've disconnected? (I.e. is this from when we receive the QUIT call?)

This won't work if handleMessage throws.
Attachment #8354671 - Flags: review?(clokep) → review-
*** Original post on bio 2180 at 2013-10-11 17:35:19 UTC ***

This happens on every successful disconnect due to the attempt to log the ERROR message as per comment 1, not due to data on the socket after disconnect.

If handleMessage throws for this particular ERROR message, we won't have disconnected, so there won't be a problem ;) (Unless there is some conspiracy)
Whiteboard: [1.5-wanted]
Attached patch Better alternative (obsolete) — Splinter Review
*** Original post on bio 2180 as attmnt 2982 at 2013-10-24 17:08:00 UTC ***

Looking at the pastebin in bug 955677 (bio 2229) made me think of this alternative solution, which is I think better: Log the message before handling it, and then log a warning if handling failed. This does mean two rather than one entries if there was a problem, but I now think this is actually a plus because the DEBUG and WARN messages bracket whatever logging may have happened during the handling, which can be useful.
Attachment #8354763 - Flags: review?(clokep)
Comment on attachment 8354763 [details] [diff] [review]
Better alternative

*** Original change on bio 2180 attmnt 2982 at 2013-10-24 18:21:48 UTC ***

>diff --git a/chat/protocols/irc/irc.js b/chat/protocols/irc/irc.js
>@@ -677,24 +677,23 @@ ircSocket.prototype = {
>     try {
>       let message = new ircMessage(dequotedMessage);
>-      let isHandled = ircHandlers.handleMessage(this._account, message);
>-      message.rawMessage = aRawMessage; // Log the quoted message.
>-      let logEntry = JSON.stringify(message) + conversionWarning;
>-      // Log the message if it was handled, otherwise throw a warning.
>-      if (isHandled)
>-        this.DEBUG(logEntry);
>-      else
>+      this.DEBUG(JSON.stringify(message) + conversionWarning);
>+      if (!ircHandlers.handleMessage(this._account, message)) {
>+        // If the message was not handled, throw a warning.
>+        message.rawMessage = aRawMessage; // Log the quoted message.
>+        let logEntry = JSON.stringify(message) + conversionWarning;
You could still define this above and reuse it twice, either that or inline it.

>         this.WARN("Unhandled IRC message:\n" + logEntry);
>+      }
>     } 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.DEBUG(aRawMessage + conversionWarning);
Is this debug extraneous now?

This won't regress the other changes we recently made, right?
Attachment #8354763 - Flags: review?(clokep) → review-
*** Original post on bio 2180 at 2013-10-24 18:26:38 UTC ***

(In reply to comment #5)
> >       let message = new ircMessage(dequotedMessage);
> >-      let isHandled = ircHandlers.handleMessage(this._account, message);
> >-      message.rawMessage = aRawMessage; // Log the quoted message.
> >-      let logEntry = JSON.stringify(message) + conversionWarning;
> >-      // Log the message if it was handled, otherwise throw a warning.
> >-      if (isHandled)
> >-        this.DEBUG(logEntry);
> >-      else
> >+      this.DEBUG(JSON.stringify(message) + conversionWarning);
> >+      if (!ircHandlers.handleMessage(this._account, message)) {
> >+        // If the message was not handled, throw a warning.
> >+        message.rawMessage = aRawMessage; // Log the quoted message.
> >+        let logEntry = JSON.stringify(message) + conversionWarning;
> You could still define this above and reuse it twice, either that or inline it.

It can't be reused directly as we don't want to overwrite the rawMessage property with the quoted raw message before handling the message (or doesn't that matter?).  

The question is "is it bad to always log the quoted rawMessage unless there is a problem"?

> >     } 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.DEBUG(aRawMessage + conversionWarning);
> Is this debug extraneous now?

No, it's needed when there is a message parsing error.

> This won't regress the other changes we recently made, right?

Not as far as I can see.
Attached patch PatchSplinter Review
*** Original post on bio 2180 as attmnt 2985 at 2013-10-25 10:42:00 UTC ***

This may be simpler: We always log the message object (with the dequoted raw message). If the message couldn't be handled, we log the original quoted raw message.

I don't really have a strong preference either way.
Attachment #8354766 - Flags: review?(clokep)
Comment on attachment 8354671 [details] [diff] [review]
Patch

*** Original change on bio 2180 attmnt 2901 at 2013-10-25 10:42:44 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354671 - Attachment is obsolete: true
Comment on attachment 8354766 [details] [diff] [review]
Patch

*** Original change on bio 2180 attmnt 2985 at 2013-10-25 10:50:11 UTC ***

I think this is the simplest and most reasonable change. I vaguely recall Florian not liking having any messages pop up twice though, I'd like to hear his thoughts.
Attachment #8354766 - Flags: review?(clokep) → review+
*** Original post on bio 2180 at 2013-10-25 10:54:58 UTC ***

(In reply to comment #8)
> I think this is the simplest and most reasonable change. I vaguely recall
> Florian not liking having any messages pop up twice though, I'd like to hear
> his thoughts.

I changed my mind on this after looking at the pastebin in bug 955677 (bio 2229), where I was initially confused because I couldn't see what was triggering the nick change. Of course it was triggered by the usual message, but logging the message /after/ it was handled made that just a little harder to read.

Instead we should just remove warnings which are not helpful (such as we did in the preceding bugs).
Whiteboard: [1.5-wanted] → [1.5-wanted][checkin-needed]
Comment on attachment 8354763 [details] [diff] [review]
Better alternative

*** Original change on bio 2180 attmnt 2982 at 2013-10-25 11:02:34 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8354763 - Attachment is obsolete: true
*** Original post on bio 2180 at 2013-11-02 17:04:16 UTC ***

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