790539 - Participant list does not update properly while chat tab is inactive

Status: VERIFIED FIXED

(Thunderbird :: Instant Messaging, defect)

Description

[Wladimir Palant]

The participants list in the IRC chat is regularly getting out of sync and I finally noticed the actual instant where it went wrong. The chat window shows:

> user entered the room.
> mode (user +o) by ChanServ.

The user wasn't added to the participants list however. Looking at the Error Console I see:

> Error: [Exception... "'TypeError: item is undefined' when calling method: [nsIObserver::observe]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "JS frame :: resource:///modules/jsProtoHelper.jsm :: <TOP_LEVEL> :: line 409"  data: no]

> Error: Error running command MODE with handler RFC 2812:
{"rawMessage":":ChanServ![e-mail] MODE #channel +o user","command":"MODE","params":["#channel","+o","user"],"nickname":"ChanServ","user":"services","host":"mozilla.org","source":"[e-mail]"}

I figured out that the MODE command results in ircParticipant.setMode() being called which triggers "chat-buddy-update" observers. The problematic observer is in imconversation.xml, method updateBuddy(). This is likely a follow-up error however - this method expects to find the user in the participants list but doesn't, hence "undefined".

Comment 1

[Wladimir Palant]

As a work-around one can send a /names command to refresh the list. Unfortunately, there is no built-in functionality to do this, one has to run the following command from the Error Console:

> var conv = top.opener.document.querySelector("imconversation").conv.target.wrappedJSObject;conv.removeAllParticipants();conv._account.sendMessage("NAMES", conv.name);

Comment 2

[Florian Quèze [:florian]]

(In reply to Wladimir Palant from comment #1)
> As a work-around one can send a /names command to refresh the list.
> Unfortunately, there is no built-in functionality to do this, one has to run
> the following command from the Error Console:
> 
> > var conv = top.opener.document.querySelector("imconversation").conv.target.wrappedJSObject;conv.removeAllParticipants();conv._account.sendMessage("NAMES", conv.name);

This (sent in the conversation) should be less typing:
/quote NAMES <convname>

Comment 3

[Florian Quèze [:florian]]

Ah, I missed the removeAllParticipants call in your JS code, sorry.

Comment 4

[Florian Quèze [:florian]]

(In reply to Wladimir Palant from comment #0)
> The participants list in the IRC chat is regularly getting out of sync

Do you have any idea of the steps to reproduce? Is this always happening in the same channel?

Comment 5

[Wladimir Palant]

Unfortunately, I don't have any reliable steps to reproduce. I was suspecting that the list doesn't get updated after the automatic reconnect when my laptop wakes up. But it seems that this happens simply when somebody joins. It cannot be every time when a user joins and is immediately promoted to an OP, this works correctly most of the time.

Comment 6

[Patrick Cloke [:clokep]]

There's no error/warning before this? It'd be useful to have the command received from the server when the user joined to see if we didn't properly parse it for some reason.

This sounds a lot like https://bugzilla.instantbird.org/show_bug.cgi?id=1687 but I haven't been able to reproduce that.

I have a patch being reviewed that totally changes the way MODE is handled, so it's possible that this bug would be fixed by that...but I agree that the MODE error seems like fallout from a previous issue.

Comment 7

[Wladimir Palant]

No, there are no further error messages. Can I switch on additional logging somewhere to get more info the next time it happens?

Comment 8

[Wladimir Palant]

Just had the same thing happen again. Not an op this time so I could confirm that all the error messages are just follow-up errors - MODE handling has nothing to do with it. However, calling conv.removeAllParticipants() (as in the work-around above) caused this error:

> Error: NS_ERROR_XPC_JS_THREW_STRING: 'Cannot remove a buddy that was not in the room' when calling method: [nsIObserver::observe]
> Source File: resource:///modules/jsProtoHelper.jsm
> Line: 409

So I guess that the data is inconsistent. Maybe that helps figuring out what went wrong here.

Comment 9

[Patrick Cloke [:clokep]]

(In reply to Wladimir Palant from comment #7)
> No, there are no further error messages. Can I switch on additional logging
> somewhere to get more info the next time it happens?

Yup, set purple.debug.loglevel to 1, this will have an awful lot of debug information though, especially if you have many accounts.

Comment 10

[Wladimir Palant]

Here is what I got with the logging turned on:

> Timestamp: 14.09.2012 11:10:23
> Warning: onTransportStatus(STATUS_RECEIVING_FROM)
> irc
> 
> Timestamp: 14.09.2012 11:10:23
> Warning: :user![e-mail] JOIN :#channel
> irc
>
> Timestamp: 14.09.2012 11:10:23
> Warning: :user![e-mail] JOIN :#channel
> irc
>
> Timestamp: 14.09.2012 11:10:23
> Warning: {"rawMessage":":user![e-mail] JOIN :#channel","command":"JOIN","params":["#channel"],"nickname":"user","user":"user","host":"moz-2FF4FD1D.vserver-on.de","source":"[e-mail]"}
> irc

And that's all of it - preceding messages were about sending a PING message to the server, and the following ones were about what that user said. When he left I got some error messages but those are clearly follow-up errors:

> Timestamp: 14.09.2012 11:12:10
> Error: [Exception... "'Cannot remove a buddy that was not in the room' when calling method: [nsIObserver::observe]"  nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)"  location: "JS frame :: resource:///modules/jsProtoHelper.jsm :: <TOP_LEVEL> :: line 409"  data: no]
>
> Timestamp: 14.09.2012 11:12:10
> Error: Error running command QUIT with handler RFC 2812:
{"rawMessage":":user![e-mail] QUIT :Quit: Lost terminal","command":"QUIT","params":["Quit: Lost terminal"],"nickname":"user","user":"user","host":"moz-2FF4FD1D.vserver-on.de","source":"[e-mail]"}
> irc

Comment 11

[Wladimir Palant]

Apparently, this sometimes also happens when people leave. I currently had a user leave but he is still listed as a participant (I used /whois to confirm that he is indeed no longer there). The relevant log messages:

> Timestamp: 14.09.2012 11:47:55
> Warning: onTransportStatus(STATUS_RECEIVING_FROM)
> irc
>
> Timestamp: 14.09.2012 11:47:55
> Warning: :user![e-mail] QUIT :Input/output error
> irc
>
> Timestamp: 14.09.2012 11:47:55
> Warning: :user![e-mail] QUIT :Input/output error
> irc
>
> Timestamp: 14.09.2012 11:47:55
> Warning: {"rawMessage":":user![e-mail] QUIT :Input/output error","command":"QUIT","params":["Input/output error"],"nickname":"user","user":"uid2508","host":"moz-D63BDBD0.irccloud.com","source":"[e-mail]"}
> irc

Comment 12

[Wladimir Palant]

Strangely, my work-around in comment 1 doesn't work in this case - sending the /names command re-adds this user even though he wasn't in the list returned by the server (353 response lists four names but five names are being added to the participants list, with the extra name being the only one colored).

Comment 13

[Wladimir Palant]

Never mind comment 12 - he wasn't re-added, conv.removeAllParticipants() simply didn't remove his name in the first place.

Comment 14

[Wladimir Palant]

It seems that the data in the conversation is correct but imconversation.xml doesn't get the chat-buddy-add/chat-buddy-remove notification. I filed bug 791199 on one scenario that could cause that but I am unsure where a second observer would come from. At least right now I only have one observer (then again, right now things work).

Comment 15

[Michael T]

A regular nick list update (if possible with a configurable interval) would be a very nice thing to have - in addition to the issue described in this ticket, I use IRC over an http proxy and regularly get disconnected due to lack of activity!  Automatic nick list updates have the nice side-effect of preventing this.

Comment 16

[Patrick Cloke [:clokep]]

(In reply to Michael T from comment #15)
> A regular nick list update (if possible with a configurable interval) would
> be a very nice thing to have - in addition to the issue described in this
> ticket, I use IRC over an http proxy and regularly get disconnected due to
> lack of activity!  Automatic nick list updates have the nice side-effect of
> preventing this.

I'm not sure how this is related. When you reconnect the nick list will be redownloaded. I'm not sure how requesting the nick list on an interval would help this at all. We should have no issues tracking the nick list.

If I remember this bug correctly, it is about the conversation binding (the UI) displaying the incorrect information, not about the protocol layer having the wrong list of participants. Is this an accurate description Wladimir?

Michael, if you're seeing a different issue (or having an issue connecting through a proxy, etc.), please file a new bug. Thanks.

Comment 18

[Elico]

Something that will might help is that when I try to use the auto completion of a nick (using TAB TAB) it wont complete the name.
Is there anything I can do to help resolve it? find the source of the bug?
since Thunderbird irc was out I have been using it and this is one of the very good features.

Comment 19

[Wladimir Palant]

Note that my work-around in comment 1 is completely unnecessary. It's enough to switch to "Conversations" in the left pane and back to the specific channel. A new conversation view will be created, with the correct data. So the internal data is correct, only syncing the view with it fails sometimes.

Comment 20

[Florian Quèze [:florian]]

Fixing bug 791199 seems the best way to move forward here (unless we find good steps to reproduce).

Comment 21

[Petr Kocandrle]

I'm still facing this nasty bug wit TB 24.6.0 in Fedora 20. Is anybody working on resolving it?

Comment 22

[aleth [:aleth]]

Does this happen only when you have multiple TB windows open at the same time?

Comment 23

[Petr Kocandrle]

Nope. There is only one TB window which contains the basic e-mail tab, and opened e-mail tab and the chat tab. It happens only sometimes - a user gets in and he does not appear in the list, 5 minutes later another one comes and he appears. The same happens when someone changes his nickname or disconnects. But it is random. Not sure if windows focus play some role in this.

Comment 24

[aleth [:aleth]]

(In reply to Petr Kocandrle from comment #23)
> Nope. There is only one TB window which contains the basic e-mail tab, and
> opened e-mail tab and the chat tab. It happens only sometimes - a user gets
> in and he does not appear in the list, 5 minutes later another one comes and
> he appears. The same happens when someone changes his nickname or
> disconnects. But it is random. Not sure if windows focus play some role in
> this.

Thanks. The problem for us is that if we can't reliably reproduce the problem, it's hard to investigate how to fix it.

I wonder if there are similar binding issues to bug 954576 involved somehow.

Comment 25

[aleth [:aleth]]

(In reply to Petr Kocandrle from comment #23)
Could you please check, next time it happens for you, if you also see the errors reported in comment 0 in the error console?

Comment 26

[Petr Kocandrle]

It just happened and no error has appeared in the error console. However I think I found the circumstances - the chat tab cannot be active. There were ~10 connections/disconnections/nick changes when the chat tab was active and all worked ok. When I switched to e-mail tab and back in a few minutes, there was 1 user newly connected and his nickname was missing in the participants list.

Comment 27

[Frédéric Buclin]

When someone changes his nick on IRC, the list of usernames still has the old nick. Is that the same issue? I'm using Thunderbird 31.2.0 on Linux.

Comment 28

[Petr Kocandrle]

Yes, that's the problem. I can reproduce it under circumstances described in comment #26 and workaround is to switch to another chat room and back. The user list gets refreshed by that.

Comment 29

[aleth [:aleth]]

(In reply to Petr Kocandrle from comment #26)
> It just happened and no error has appeared in the error console. However I
> think I found the circumstances - the chat tab cannot be active.

These are indeed reliable STR. Using this, it turns out that when the chat tab is not selected, while messages get added correctly, no notifications arrive, as previously observed here:

(In reply to Wladimir Palant from comment #14)
> It seems that the data in the conversation is correct but imconversation.xml
> doesn't get the chat-buddy-add/chat-buddy-remove notification.

Reasons as yet unknown. A temporary workaround for TB38 wouldn't be hard though.

Comment 30

[aleth [:aleth]]

This is a little funky. The notifications actually arrive, but this.tab.selected becomes false when the tab is inactive (nb this.tab in TB is not the tab, but the imconv). However, a mutation observer on this.tab does not pick up the state change from true to false in this case.

Comment 31

[aleth [:aleth]]

Attachment: Patch

Comment 32

[Florian Quèze [:florian]]

Comment on attachment 8564346 [details] [diff] [review]
Patch

Review of attachment 8564346 [details] [diff] [review]:
-----------------------------------------------------------------

::: mail/components/im/content/imconversation.xml
@@ +1317,5 @@
>         ]]>
>         </body>
>       </method>
>  
> +     <property name="_isConversationActive">

Should this be _isConversationDisplayed or _isConversationSelected?

@@ +1323,5 @@
> +       <![CDATA[
> +         // TB-only: returns true if the conversation binding is the currently
> +         // selected one, i.e if it has to maintain the participant list.
> +         if (this.tab.selected)
> +           return true;

So why is this check still needed if you are going to check the selectedItem property?

Comment 33

[aleth [:aleth]]

Attachment: Patch v2

(In reply to Florian Quèze [:florian] [:flo] from comment #32)
> > +     <property name="_isConversationActive">
> 
> Should this be _isConversationDisplayed or _isConversationSelected?

I changed it to _isConversationSelected which is probably clearer.

> > +         if (this.tab.selected)
> > +           return true;
> 
> So why is this check still needed if you are going to check the selectedItem
> property?

Strictly speaking not needed, but it's much faster than the DOM call and the nicklist is slow enough as it is, so I kept it.

Comment 34

[Florian Quèze [:florian]]

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

I'm not entirely sure I understand what the problem was, but I assume you do, and it seems the worst that could happen with this patch is not fully fixing the problem :).

Comment 35

[aleth [:aleth]]

Attachment: Patch v3

It struck me that the fact that a mutation observer on the selected attribute wasn't firing as this.tab.selected changed to/from false might imply that this bug is due to the mirroring from the attribute to the JS property failing here for some unknown reason. This is indeed the case - the attribute always seems to retain the correct value - so we can simplify the patch a bit.

Comment 36

[Florian Quèze [:florian]]

Comment on attachment 8564445 [details] [diff] [review]
Patch v3

Assuming you meant to request review here...

Comment 37

[aleth [:aleth]]

(In reply to Florian Quèze [:florian] [:flo] from comment #36)
> Comment on attachment 8564445 [details] [diff] [review]
> Patch v3
> 
> Assuming you meant to request review here...

Right, thanks!

Comment 38

[aleth [:aleth]]

https://hg.mozilla.org/comm-central/rev/9e2d41506f0b

Comment 39

[aleth [:aleth]]

Could you please verify this fixes the problem for you (in tomorrow's daily build)?

Comment 40

[Petr Kocandrle]

Well, I downloaded the latest nightly build of 38 from http://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/2015-02-16-03-02-24-comm-central/ (for linux x86_64) but it is refusing to connect to IRC. It says "prpl-irc: Connection closed by server." with every attempt. Is it only me?

Comment 41

[aleth [:aleth]]

(In reply to Petr Kocandrle from comment #40)
> Well, I downloaded the latest nightly build of 38 from
> http://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/2015-02-16-03-02-
> 24-comm-central/ (for linux x86_64) but it is refusing to connect to IRC. It
> says "prpl-irc: Connection closed by server." with every attempt. Is it only
> me?

The current nightly connects fine to IRC for me on OSX. Maybe try again tomorrow, and/or check your account settings?

Comment 42

[Petr Kocandrle]

Ah, the update changed for some reason the port from 6667 to 6697 and I haven't noticed until now.

I tested the http://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/2015-02-24-03-02-02-comm-central and the participant list seems to be updated correctly now even when the chat tab is inactive. Thanks for the fix!

Comment 43

[aleth [:aleth]]

Thanks!