GNOME Bugzilla – Bug 773201
Polari reorders messages
Last modified: 2021-06-10 11:05:55 UTC
I use an IRC bouncer (ZNC) that replays messages I've missed while I wasn't connected to IRC as soon as I reconnect. This means Polari (or Telepathy) gets a flood of new messages at connection time. These messages are not shown in the correct order. ZNC's replayed messages all have been modified to contain an ISO 8601 timestamp. I trust ZNC to replay the messages in the right order. Let's take a specific example. This morning I reconnected and I see this in the #pypa channel on FreeNode: - "New messages" bar - the timestamp says 08:40 above it - a message with ZNC's timestamp [2016-10-18 18:00:41] - a message with ZNC's timestamp [2016-10-18 18:04:19] - more messages with increasing timestamps - a message with ZNC's timestamp [2016-10-19 01:15:48] - grey text the right saying "Yesterday, 08:26" - a message with ZNC's timestamp [2016-10-17 20:29:21] - a message with ZNC's timestamp [2016-10-17 20:29:06] - more messages with *decreasing* timestamps - the last message has ZNC's timestamp [2016-10-17 19:35:13] If I check ~/.local/share/TpLogger/logs/idle_irc_mgedmin0/chatrooms/#pypa/, I see a 20161019.log with <message time='20161019T05:40:47' id='alexhayes' name='alexhayes' token='' isuser='false' type='normal'>[2016-10-19 01:15:48] ... ... <message time='20161019T05:40:47' id='jkilpatr' name='jkilpatr' token='' isuser='false' type='normal'>[2016-10-18 18:00:41] ... (all the elements have the same 'time' attribute, and all of them have ZNC's timestamps in reverse order) and I see a 20161018.log with <message time='20161018T05:26:54' id='dw' name='dw' token='' isuser='false' type='normal'>[2016-10-18 00:29:18] ... ... <message time='20161018T05:26:54' id='yoh_' name='yoh_' token='' isuser='false' type='normal'>[2016-10-17 20:30:06] ... <message time='20161018T05:26:54' id='dstufft' name='dstufft' token='' isuser='false' type='normal'>[2016-10-17 20:29:21] ... ... <message time='20161018T05:26:54' id='mitsuhiko' name='mitsuhiko' token='' isuser='false' type='normal'>[2016-10-17 19:35:13] ... (again, all the elements have the same 'time' attribute and all of them have ZNC's timestamps in reverse order). So it looks like Telepathy reorders the messages (which is not Polari's fault), but then Polaris *also* reorders the messages: - all the messages from 20161018.log are there, but in reverse order from the log file (i.e. correct order accoding to ZNC's timestamps) - half of the messages from 20161017.log are there AFTER the messages from 20161018.log, in reverse order FWIW more messages with ZNC timestamps from [2016-10-17] are above the "New messages" line, and some messages with ZNC's timestamps saying [2016-10-18] are above those. I've scrolled up in the backlog trying to find the beginnings of conversations, so it's possible that some of the ordering has been messed up by Polari loading the logs from history and inserting them into the stream at the wrong place.
I traced this down a bit further. Both the telepathy-idle debug log and a ru of dbus-monitor while opening Polari (excerpt below from a couple of messages in #gnome-hackers) show the messages in correct order, the problem happens somewhere after those in the pipeline. In addition, the messages that get reordered don't even show up in Polari chat view before I close and reopen Polari. Somehow they do get partly in, because the channel list shows as black the channels that have new messages, even though the actual messages don't appear before a reboot. ==== signal time=1485613758.432929 sender=:1.136 -> destination=(null destination) serial=1075 path=/org/freedesktop/Telepathy/Connection/idle/irc/dlandau_40landau_2efi0xb455d0/MucChannel4; inter face=org.freedesktop.Telepathy.Channel.Interface.Messages; member=MessageReceived array [ array [ dict entry( string "pending-message-id" variant uint32 18 ) dict entry( string "message-sender-id" variant string "ebassi" ) dict entry( string "message-received" variant int64 1485613758 ) dict entry( string "message-sender" variant uint32 100 ) ] array [ dict entry( string "content" variant string "[23:39:17] cfoch: An answer to your question is: find another API that uses arrays of strings and/or values, and see what happens when you try usin g it from language bindings; then, copy the annotations" ) dict entry( string "content-type" variant string "text/plain" ) ] ] signal time=1485613758.433286 sender=:1.136 -> destination=(null destination) serial=1079 path=/org/freedesktop/Telepathy/Connection/idle/irc/dlandau_40landau_2efi0xb455d0/MucChannel4; inter face=org.freedesktop.Telepathy.Channel.Interface.Messages; member=MessageReceived array [ array [ dict entry( string "pending-message-id" variant uint32 19 ) dict entry( string "message-sender-id" variant string "ebassi" ) dict entry( string "message-received" variant int64 1485613758 ) dict entry( string "message-sender" variant uint32 100 ) ] array [ dict entry( string "content" variant string "[23:39:58] cfoch: You may need an override for pygobject, because you may need some hand-holding in turning python values into GValue" ) dict entry( string "content-type" variant string "text/plain" ) ] ]
Filed a bug and a patch at Telepathy-logger: https://bugs.freedesktop.org/show_bug.cgi?id=99593
*** Bug 747833 has been marked as a duplicate of this bug. ***
> In addition, the messages that get reordered don't even show up in Polari chat view before I close and reopen Polari. Somehow they do get partly in, because the channel list shows as black the channels that have new messages, even though the actual messages don't appear before a reboot. I can see that too -- even when the replayed messages mention me by nick, I get a blue 1 next to a channel name in Polari, but clicking the channel itself doesn't show me the message I was notified about. It seems that the channels that are first alphabetically get ZNC's replayed messages to show up, but further channels show none of them, even though Polari indicates that those channels have unread messages. I was planning to file that as a separate bug, but now I wonder. I see you posted a Telepathy patch, Daniel -- does it also fix the missing messages problem for you?
Missing messages I think is a bug on Polari's end, related probably to this: https://gitlab.gnome.org/GNOME/polari/blob/master/src/telepathyClient.js#L584. The Telepathy fix is also at https://github.com/TelepathyIM/telepathy-logger/pull/1, but even talking to Telepathy maintainers at FOSDEM didn't seem to help getting that one line patch merged so I don't know what will.
(In reply to Daniel Landau from comment #5) > Missing messages I think is a bug on Polari's end Very likely, yes - see bug 777486 and bug 780729. > related probably to this: > https://gitlab.gnome.org/GNOME/polari/blob/master/src/telepathyClient. > js#L584. But this isn't the issue, no. That code deals with showing a notification for highlighted messages, it doesn't influence which messages appear in the log.
GNOME is going to shut down bugzilla.gnome.org in favor of gitlab.gnome.org. As part of that, we are mass-closing older open tickets in bugzilla.gnome.org which have not seen updates for a longer time (resources are unfortunately quite limited so not every ticket can get handled). If you can still reproduce the situation described in this ticket in a recent and supported software version of Polari, then please follow https://wiki.gnome.org/GettingInTouch/BugReportingGuidelines and create a new ticket at https://gitlab.gnome.org/GNOME/polari/-/issues/ Thank you for your understanding and your help.