Closed Bug 954740 Opened 10 years ago Closed 10 years ago

"Adding a chat buddy twice" errors (JS-IRC sending bad chat-buddy-add notifications)

Categories

(Chat Core :: IRC, defect)

defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: aleth, Assigned: aleth)

References

Details

(Whiteboard: [1.2-wanted][regression])

Attachments

(2 files, 2 obsolete files)

*** Original post on bio 1308 at 2012-03-02 10:20:00 UTC ***

Error: [Exception... "'Adding a chat buddy twice?!' when calling method: [nsIObserver::observe]"  nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)"  location: "JS frame :: resource:///modules/jsProtoHelper.jsm :: <TOP_LEVEL> :: line 441"  data: no]
Source File: resource:///modules/jsProtoHelper.jsm
Line: 441

Error: Error running command 366 with handler RFC 2812:
{"rawMessage":":barjavel.freenode.net 366 aleth #ubuntu :End of /NAMES list.","source":"barjavel.freenode.net","command":"366","params":["aleth","#ubuntu","End of /NAMES list."]}
Source File: resource:///modules/ircHandlers.jsm
Line: 117
Source Code:
irc

Error: [Exception... "'Adding a chat buddy twice?!' when calling method: [nsIObserver::observe]"  nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)"  location: "JS frame :: resource:///modules/jsProtoHelper.jsm :: <TOP_LEVEL> :: line 441"  data: no]
Source File: resource:///modules/ircHandlers.jsm
Line: 118

Warning: Unhandled IRC message: :barjavel.freenode.net 366 aleth #ubuntu :End of /NAMES list.
Source File: jar:file:///instantbird/omni.jar!/components/irc.js
Line: 331
Source Code:
irc

Warning: Unhandled IRC message: :services. 328 aleth #ubuntu :http://www.ubuntu.com
Source File: jar:file:///instantbird/omni.jar!/components/irc.js
Line: 331
Source Code:
irc

Warning: Unhandled IRC message: :barjavel.freenode.net 330 aleth _schism_ _schism_ :is logged in as
Source File: jar:file:///instantbird/omni.jar!/components/irc.js
Line: 331
Source Code:
irc
*** Original post on bio 1308 at 2012-03-02 20:55:59 UTC ***

Now also seen on mozilla.org. Same sequence of error messages, apart from the last two warnings, which were absent.
Status: UNCONFIRMED → NEW
Ever confirmed: true
*** Original post on bio 1308 at 2012-03-02 21:00:22 UTC ***

Possibly relevant to reproduce this: Both times, the errors appeared immediately after restarting Instantbird.
Summary: Errors on connecting to #ubuntu: Strange nick clash? → Errors on joining channel: Strange nick clash?
Summary: Errors on joining channel: Strange nick clash? → Errors on joining channel: "Adding a chat buddy twice"
*** Original post on bio 1308 as attmnt 1262 at 2012-03-18 23:21:00 UTC ***

This trivial patch adds the name of the buddy to the error message and will hopefully help to get STR for this bug.
Attachment #8353015 - Flags: review?(clokep)
Comment on attachment 8353015 [details] [diff] [review]
Error message patch

*** Original change on bio 1308 attmnt 1262 at 2012-03-19 13:02:36 UTC ***

I'm fine with this change, I might prefer a different formatting ("Adding a chat buddy (<name>) twice?!"), but it's an error message so I don't care /that/ much. We'll see what Florian thinks.
Attachment #8353015 - Flags: review?(clokep) → review+
Attachment #8353015 - Flags: review?(florian)
Comment on attachment 8353015 [details] [diff] [review]
Error message patch

*** Original change on bio 1308 attmnt 1262 at 2012-03-19 13:08:54 UTC ***

This change is fine with me (I think at some point while debugging JS-IRC, I had something very similar locally, but reverted it because I was also adding a dump() in there :)).

I don't think bikeshedding the wording is worth spending time on, so I think we can keep what's in the current patch. If I wanted to change it, I would try to have the name (the useful info) at the end of the message so that it's easy to see it without reading the message. ("blah blah blah: <name>")
Attachment #8353015 - Flags: review?(florian) → review+
*** Original post on bio 1308 at 2012-03-20 22:42:30 UTC ***

The better error message is checked in as http://hg.instantbird.org/instantbird/rev/5c12cc9e43d4
*** Original post on bio 1308 at 2012-04-08 18:44:39 UTC ***

The nick in question is the user's own nick, at least in the 2 instances I have observed.
*** Original post on bio 1308 at 2012-04-09 22:07:14 UTC ***

The error only seems to occur when the "chat-buddy-add" event sent by the 366 End of /Names handler actually reaches the conversation binding. In this case, the conversation binding initConversationUI method will already have added (some?) participants, the user's nick being the first in the instances I tested, and therefore appearing in the error message.
*** Original post on bio 1308 at 2012-04-09 22:09:33 UTC ***

The laziest solution here would be to tolerate "adding the same chat buddy twice", and just ignoring such duplicate calls.
Blocks: 954741
Hardware: x86 → All
Whiteboard: [1.2-wanted][regression]
*** Original post on bio 1308 at 2012-05-04 09:45:11 UTC ***

(In reply to comment #9)
> The laziest solution here would be to tolerate "adding the same chat buddy
> twice", and just ignoring such duplicate calls.

This is not really a solution.

IRC channels should know which nicks have been added since the last getParticipants call or the last chat-buddy-add notification, and only notify for them.
Summary: Errors on joining channel: "Adding a chat buddy twice" → "Adding a chat buddy twice" errors (JS-IRC sending bad chat-buddy-add notifications)
Attached patch Patch (obsolete) — Splinter Review
*** Original post on bio 1308 as attmnt 1447 at 2012-05-05 13:07:00 UTC ***

Turns out to be not so hard to fix after all, I think. (As long as one makes the assumption that all sent notifications do reach the conversation, which seems valid?).

This patch doesn't cover the chat-buddy-updates in setMode, so isn't ready for review.
Attachment #8353200 - Flags: feedback?(clokep)
Comment on attachment 8353200 [details] [diff] [review]
Patch

*** Original change on bio 1308 attmnt 1447 at 2012-05-05 14:05:00 UTC ***

So as part of this, I'd like to move the handler from 366 to 353, to update the participant list as we build it.

>diff --git a/components/irc.js b/components/irc.js
>+      this._participants[normalizedNick]._notified = true;
Can you add this to the ircParticipant prototype and add a comment explaining why it's necessary, etc. (I guess pointing to this bug?)

>+  getParticipants: function() {
I dislike overriding this. :(

>+  getNewParticipants: function() {
I think you can remove this method and inline this into the 353 handler and stop notifying at the end of the 366 handler. So instead of iterating over all keys, you can just iterate over the new items.

>@@ -196,42 +216,52 @@ ircChannel.prototype = {
>-    this.notifyObservers(participant, "chat-buddy-update", aOldNick);
>+    if (participant._notified)
>+      this.notifyObservers(participant, "chat-buddy-update", aOldNick);
>+    else {
>+      this.notifyObservers(new nsSimpleEnumerator([participant]),
>+                           "chat-buddy-add");
>+      this._participants[normalizedNick]._notified = true;
>+    }
Would it make more sense to not have the else here and just let it be added however it would have been added? I assume the only time this could happen is if we receive a name change before the participant is added.
Attachment #8353200 - Flags: feedback?(clokep) → feedback-
*** Original post on bio 1308 at 2012-05-05 15:57:25 UTC ***

(In reply to comment #12)
> Comment on attachment 8353200 [details] [diff] [review] (bio-attmnt 1447) [details]
> Patch
> 
> So as part of this, I'd like to move the handler from 366 to 353, to update the
> participant list as we build it.

Are you certain the conversation binding is ready to receive notifications before any 353 messages arrive? I don't think this is the case, because if it was, getParticipants() called from initConversationUI would always have returned empty, and there would be no bug to fix. 

Maybe my underlying assumptions are wrong, but the thinking behind this patch was that either 366 sends notifications before the UI is ready, in which case initConversationUI calls getParticipants() which fixes the problem, or it sends them after the UI is ready (and then fills in the gaps).

> >+  getParticipants: function() {
> I dislike overriding this. :(

Yes, but it's necessary because that's what initConversationUI calls :(

> >@@ -196,42 +216,52 @@ ircChannel.prototype = {
> >-    this.notifyObservers(participant, "chat-buddy-update", aOldNick);
> >+    if (participant._notified)
> >+      this.notifyObservers(participant, "chat-buddy-update", aOldNick);
> >+    else {
> >+      this.notifyObservers(new nsSimpleEnumerator([participant]),
> >+                           "chat-buddy-add");
> >+      this._participants[normalizedNick]._notified = true;
> >+    }
> Would it make more sense to not have the else here and just let it be added
> however it would have been added? I assume the only time this could happen is
> if we receive a name change before the participant is added.

I can't think of another case either.
*** Original post on bio 1308 at 2012-05-05 16:19:33 UTC ***

(In reply to comment #13)
> (In reply to comment #12)
> > So as part of this, I'd like to move the handler from 366 to 353, to update the
> > participant list as we build it.
> 
> Are you certain the conversation binding is ready to receive notifications
> before any 353 messages arrive? I don't think this is the case, because if it
> was, getParticipants() called from initConversationUI would always have
> returned empty, and there would be no bug to fix. 
No, but then it just gets dropped on the floor and they get picked up when getParticipants is called, I think you don't need to special case getParticipants anymore then: it just returns everything that's available (and we assume the conversation doesn't know about any of it).

> Maybe my underlying assumptions are wrong, but the thinking behind this patch
> was that either 366 sends notifications before the UI is ready, in which case
> initConversationUI calls getParticipants() which fixes the problem, or it sends
> them after the UI is ready (and then fills in the gaps).
This bug is because some of the participants (as added by response 353) are returned by the getParticipants method and added before the 366 response comes in, in which case we try to add them again.

Adding them in 353 lets you build the list incrementally: which is a better UX in my opinion. In something like #ubuntu, I can almost guarantee you that we're receiving some 353 response after the conversation is built.

This is my understanding:
 - We join a new conversation and the conversation start initializing.
 - We potentially receive 353s and tell the conversation about the new participants, but no one is listening.
 - The conversation finishes initializing, calls getParticipants, which then returns everything that has been received already.
 - We potentially receive more 353s and tell the conversation about the new participants, it's now listening and receives our updates.
 - We receive a 366 and we're done. This is a NOP though.

I'm actually not sure if you even need a flag telling about notifications anymore if you do this, but perhaps I'm missing something with this style?
Attached patch Patch v2 (obsolete) — Splinter Review
*** Original post on bio 1308 as attmnt 1449 at 2012-05-05 23:15:00 UTC ***

(In reply to comment #14)
> This bug is because some of the participants (as added by response 353) are
> returned by the getParticipants method and added before the 366 response comes
> in, in which case we try to add them again.

Sure, I was just explaining how the previous patch fixed this.

> > Are you certain the conversation binding is ready to receive notifications
> > before any 353 messages arrive? I don't think this is the case, because if it
> > was, getParticipants() called from initConversationUI would always have
> > returned empty, and there would be no bug to fix. 
> No, but then it just gets dropped on the floor and they get picked up when
> getParticipants is called, I think you don't need to special case
> getParticipants anymore then: it just returns everything that's available (and
> we assume the conversation doesn't know about any of it).

This is in fact the key idea :)

So, of course I much prefer sending notifications from 353 too, as that hopefully also staggers the load on the conversation binding a bit, and removes the need for all the manual tracking. 

It works exactly as you described in the previous comment: I've checked as well as I can think of that notifications that are sent before initConversationUI is called never arrive. This removes the need to track whether to send out notifications or not, and for which participants this has happened, because when initConversationUI calls getParticipants(), it will receive the current state of the participant list. Notifications sent by further 353s, nick updates and removals then send notifications which will be received and act on a UI participant list that is in sync with the channel participant list.
Attachment #8353202 - Flags: review?(clokep)
Comment on attachment 8353200 [details] [diff] [review]
Patch

*** Original change on bio 1308 attmnt 1447 at 2012-05-05 23:15:09 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8353200 - Attachment is obsolete: true
Attached patch Patch v2.1Splinter Review
*** Original post on bio 1308 as attmnt 1461 at 2012-05-11 02:25:00 UTC ***

This is the same as attachment 8353202 [details] [diff] [review] (bio-attmnt 1449) without the unnecessary hunk at the top that adds Cc. Additionally this fixes the paths so it will apply.

Looks good though and works as advertised! :) Thanks for doing this!
Attachment #8353214 - Flags: review+
Comment on attachment 8353202 [details] [diff] [review]
Patch v2

*** Original change on bio 1308 attmnt 1449 at 2012-05-11 02:25:26 UTC was without comment, so any subsequent comment numbers will be shifted ***
Attachment #8353202 - Attachment is obsolete: true
Attachment #8353202 - Flags: review?(clokep)
Assignee: nobody → aleth
Status: NEW → ASSIGNED
Whiteboard: [1.2-wanted][regression] → [1.2-wanted][regression][checkin-needed]
*** Original post on bio 1308 at 2012-05-16 15:59:04 UTC ***

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