Bug 300655 - Message transmission delay with ICQ
Summary: Message transmission delay with ICQ
Status: RESOLVED FIXED
Alias: None
Product: telepathy
Classification: Frameworks and Libraries
Component: text-ui (show other bugs)
Version: 0.3.0
Platform: Chakra Linux
: NOR major
Target Milestone: Future
Assignee: Telepathy Bugs
URL:
Keywords:
: 292719 (view as bug list)
Depends on:
Blocks:
 
Reported: 2012-05-26 11:18 UTC by Thomas Pfeiffer
Modified: 2012-07-21 13:48 UTC (History)
8 users (show)

See Also:
Latest Commit:
Version Fixed In: 0.4.1


Attachments
Haze log (170.31 KB, text/plain)
2012-07-17 17:27 UTC, Dominik Cermak
Details
Bustle log (439.57 KB, application/octet-stream)
2012-07-17 17:29 UTC, Dominik Cermak
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Thomas Pfeiffer 2012-05-26 11:18:50 UTC
When chatting via ICQ using KDE Telepathy, often some messages arrive with a very long delay (sometimes up to an hour). I noticed that when my chat partner suddenly answered to a message I sent her an hour ago, while we had continued chatting since then. It does not seem to happen with received messages, though.
This does not happen with Kopete (with the normal ICQ protocol handler).

Reproducible: Sometimes

Steps to Reproduce:
1. Open an ICQ chat window
2. Send some messages

Actual Results:  
Some sent messages arrive with a long delay.

Expected Results:  
Messages arrive instantly
Comment 1 Martin Klapetek 2012-05-28 18:17:45 UTC
That's a known problem :/ Can you install Pidgin and/or Empathy and try it with that? All use the same backend, so we can determine where the problem is and fix it if it lays in our code.
Comment 2 Thomas Pfeiffer 2012-06-11 21:50:02 UTC
I have tried Pidgin (there is no Empathy package in Chakra), and so far the problem did not occur there, whereas it occurs after the first few lmessages exchanged in KTP.
I also regularly use Pidgin (on Windows) at work and it never happened there.
This seems to point to the problem being in your code.
Comment 3 David Edmundson 2012-06-11 21:56:22 UTC
The point of using Empathy is they share the same backend.
Comment 4 Thomas Pfeiffer 2012-06-11 22:10:19 UTC
I tried Pidgin because Martin wrote that "all use the same backend". But I guess by that he meant libpurple, but not Telepathy, right?

I'm afraid I don't think I'll manage to get Empathy running here. Chakra does not natively support GTK/Gnome applications, only as Bundles. However there is no Bundle for Empathy and I don't have the skills to create one.

Is there any other way I can help with identifying the underlying problem, without installing Empathy?
Comment 5 David Edmundson 2012-06-11 22:33:09 UTC
Oh, Martin did say that. Telepathy wraps libPurple so it's the same backend but with an extra layer.

From our POV, it's almost certainly not our code but something beneath us.
Anyway, you're not alone in seeing this, so we'll see where this goes.
Comment 6 Andreas Sturmlechner 2012-07-08 22:28:19 UTC
I've had a 3-4min delay of all my messages with the live git version of ktp-text-ui - I was previously on master because I really don't want to install gnome-keyring, which doesn't work with ktp-auth-handler- and ktp-common-internals-0.4.0 yet. After downgrade of all the other packages to 0.4.0 that seemed to work at first., but will take some more testing.

Using libpurple.so.0.10.6
Comment 7 Andreas Sturmlechner 2012-07-08 22:37:27 UTC
Well, a few minutes later it was there again. Will build pidgin with GUI to check if it's the same there.
Comment 8 Martin Klapetek 2012-07-08 23:03:10 UTC
Yes, it's a known problem which still hasn't been fixed/investigated afaik. It most probably lies in telepathy-qt library, which is an upstream component. I'll try to nudge the devels.
Comment 9 Matt Gibbs 2012-07-11 03:22:58 UTC
I have (what I think is) the same issue with the AIM protocol.

openSUSE 12.1
Repository: openSUSE BuildService - Telepathy
Name: ktp-common-internals
Version: 0.4.60git.1340811013-14.1
Arch: x86_64
Vendor: obs://build.opensuse.org/KDE:Unstable
Installed: Yes
Status: up-to-date
Installed Size: 535.0 KiB
Summary: Telepathy common module
Description: 
ktp-common-internals is the base library for all the KDE Telepathy packages.
Comment 10 Thomas Pfeiffer 2012-07-11 09:46:03 UTC
(In reply to comment #9)
> I have (what I think is) the same issue with the AIM protocol.

This indeed seems to be independent from the protocol. Other Chakra users have the same problem with XMPP (see http://chakra-project.org/bbs/viewtopic.php?id=7941 ).
Comment 11 Andreas Sturmlechner 2012-07-14 16:34:01 UTC
I am through with telepathy-qt-0.9.1, 0.9.2 and 0.9.3 with the problem not solved. I have added timestamps to each of my messages and random ones seem to be delayed from 3 to 10 minutes, yet some do arrive instantly.
Comment 12 David Edmundson 2012-07-14 16:41:54 UTC
Marking this as "new" by popular vote.
There's still not a lot we can do without useful output from someone who sees this and ideally the same output from someone who uses Empathy too.

http://community.kde.org/Real-Time_Communication_and_Collaboration/FAQ#Providing_debug
Comment 13 Andreas Sturmlechner 2012-07-14 19:28:24 UTC
Well I just tried and went through the atrocity that is an empathy installation, including dependencies that I never wanted to have any trace of on my system, only to find out that it would not let me open any chat windows, a bug that seems to be known for months. It seems telepathy clients have combined forces against any attempts to dig deeper here. ;)
Comment 14 Andreas Sturmlechner 2012-07-14 19:29:27 UTC
Oh, you can widen the platform to Gentoo Linux ~amd64 in my case.
Comment 15 George Kiagiadakis 2012-07-17 09:09:24 UTC
Imho, I believe this is a networking/server issue. I've seen the code of empathy and the respective tp-qt and text-ui code and I don't see anything being done differently. I would love it if someone can provide dbus traffic logs with bustle of a conversation that got completely screwed with delays.

Btw, this "bug" may actually be 2 bugs. I remember somebody recently did a screenshot of an ICQ conversation where messages were re-ordered and some of them omitted in the text-ui, while the other side showed them correctly. This is one bug, I believe a CM one.

There is the other thing though that sometimes happen even with XMPP. You type a message, hit enter, then nothing happens for a while. After a couple of seconds or even minutes, you see the message that you typed. I sometimes experience this with facebook and google talk when my network connection is not very stable. If I open the web interface immediately and see what happens on the server, I notice that my message has not been sent indeed. If at some point the text-ui shows the message, then after a small delay, it appears on the server as well.

What happens here is that every message has in fact 3 different states and we only handle one of them.
- State 1: You type a message and send it to the CM. Message has been sent to the CM, but not to the network.
- State 2: The CM acknowledges by emitting the MessageSent signal. This only happens when the CM has successfully sent the message to the network and this is the point where we show it in the text UI. Any initial delay that you may see from the point that the message was typed to the point that the message was shown is because the CM isn't able to send it to the network.
- State 3: On protocols that support it, the CM signals a "delivery report" message when the server acknowledges that the other person(s) have received the message. This is when the message actually appears on the fb/gtalk web interface.

It would probably be less confusing for the users if we handled all 3 states properly. Step 1, send the message to the CM and show it in the text UI with some indication that it hasn't been sent yet. When the CM signals MessageSent, remove the indication or replace it with some "awaiting delivery" indication if the protocol supports delivery reports. When the delivery report comes, remove the indication or replace it with a warning icon if delivery failed. IIRC, kopete did something similar and so does skype and so does the N9 chat ui (which actually uses telepathy; if you have one, take a careful look).
Comment 16 Dominik Cermak 2012-07-17 11:35:04 UTC
(In reply to comment #15)
> Imho, I believe this is a networking/server issue. I've seen the code of
> empathy and the respective tp-qt and text-ui code and I don't see anything
> being done differently. I would love it if someone can provide dbus traffic
> logs with bustle of a conversation that got completely screwed with delays.

If you can tell me how to get the logs you want, maybe I can provide them.

> Btw, this "bug" may actually be 2 bugs. I remember somebody recently did a
> screenshot of an ICQ conversation where messages were re-ordered and some of
> them omitted in the text-ui, while the other side showed them correctly.
> This is one bug, I believe a CM one.

Not the case for me, as text-ui showed all of my messages, but my contact didn't got them/got them much later.

> There is the other thing though that sometimes happen even with XMPP. You
> type a message, hit enter, then nothing happens for a while. After a couple
> of seconds or even minutes, you see the message that you typed. I sometimes
> experience this with facebook and google talk when my network connection is
> not very stable. If I open the web interface immediately and see what
> happens on the server, I notice that my message has not been sent indeed. If
> at some point the text-ui shows the message, then after a small delay, it
> appears on the server as well.

Also not the case for me, text-ui showed the message immediately after pressing enter, but it arrived like 10 minutes later on the other side.
Comment 17 Thomas Pfeiffer 2012-07-17 11:51:20 UTC
(In reply to comment #15)
> Btw, this "bug" may actually be 2 bugs. I remember somebody recently did a
> screenshot of an ICQ conversation where messages were re-ordered and some of
> them omitted in the text-ui, while the other side showed them correctly.
> This is one bug, I believe a CM one.

Then this report initially was for this kind of bug, since that's exactly what I experienced as well. 
And the bug has to be on the sending side, because my chat partners used different clients which work fine with all other clients. This may be a problem specific to the combination of KTP and ICQ, since I've not experienced it with XMPP yet.
Comment 18 Martin Klapetek 2012-07-17 11:52:55 UTC
To provide a debug, install bustle and then disable all accounts but the ICQ/AIM, close all text chats and make sure telepathy-haze is not running. Then run 

bustle-dbus-monitor > ~/bustle.log

then run

HAZE_PERSIST=1 HAZE_DEBUG=all /usr/lib/telepathy-haze 2>&1 > ~/haze.log

(you might need to adjust the path)

Then connect and start a chat untill the delays happen, make sure you have logged at least few of the delays and then stop the logging and upload the files.
Comment 19 Dominik Cermak 2012-07-17 12:32:17 UTC
Just tried to build bustle, but it fails (more exactly one of it's thousands haskell dependencies fails) to build. And as it is exam time, I don't have the time to struggle with haskell... So unfortunately I won't be of help.
Only thing I could provide is the haze log.
Comment 20 Martin Klapetek 2012-07-17 12:33:30 UTC
Have you checked packages? Kubuntu provides a package for bustle.
Comment 21 David Edmundson 2012-07-17 12:34:33 UTC
/me overrides. As a lecturer - exams first. This can wait/someone else can do it.
Comment 22 Thomas Pfeiffer 2012-07-17 14:08:32 UTC
(In reply to comment #18)
> To provide a debug, install bustle and then disable all accounts but the
> ICQ/AIM, close all text chats and make sure telepathy-haze is not running.
> Then run 

Problem here: bustle depends on GTK, so it's not available on Chakra. Sorry :(
Chakra works great if you just want to use KDE and nothing else, but it turns out to not be the ideal distribution when it comes to debugging Telepathy stuff...
Comment 23 Dominik Cermak 2012-07-17 17:25:42 UTC
So I downloaded the binary tarballs from http://willthompson.co.uk/bustle/ and hoped it will work with my local libs. Now there are a few attachments coming...
Comment 24 Dominik Cermak 2012-07-17 17:27:21 UTC
Created attachment 72589 [details]
Haze log

That's the haze log. There are these
"purple/oscar-Message: Attempting to send 78 queued SNACs and ..."
messages while I have the delay.
Comment 25 Dominik Cermak 2012-07-17 17:29:20 UTC
Created attachment 72590 [details]
Bustle log

This is the bustle log. Because it needs loots of memory I didn't had it running all the time. But it contains some time before the delays until I stopped logging.
Comment 26 Dominik Cermak 2012-07-17 17:56:08 UTC
Some things to add:
In the bustle log the first message delayed is the one at 84639ms.
In this case it was a delay from around 3-5 minutes until my messages arrived.
My partner send messages too, they arrived instantly.

Because of the last fact I don't see how it could be a server or connection issue, as then also the messages from my partner should have the delay.
Comment 27 George Kiagiadakis 2012-07-18 11:38:47 UTC
I had a look at those logs. It appears that every SendMessage call is immediately accompanied by the MessageSent signal. I had a look at the relevant tp-qt code and it seems there are no delays in sending or receiving the messages (no pending operations trying to make stuff ready), so as soon as you hit enter in the text-ui, the SendMessage d-bus call is made in the context of that slot and when the MessageSent signal arrives, it immediately emits in the same context the equivalent Tp::TextChannel signal which is processed immediately from the UI.

Therefore, I am fairly confident that this is not a bug in any telepathy part. It might be libpurple or something even lower than that, or just a server issue.
Comment 28 Martin Klapetek 2012-07-18 12:01:22 UTC
I just tried with KTp, Kopete and Empathy. Only KTp is affected. What's noteworthy is that if I send lots of messages from Kopete and Empathy, they both arrive delayed, but uniformly delayed and it's like 1-2 secs. IOW - they all always arrive in 1-2s intervals, but arrive all and in correct order. While KTp tries to send it all at once, succeeds with the first few and fails after them and the delays are bigger and bigger with every message sent.

Possible conclusion - maybe we actually need to delay the message sending? It might be a big shot in the dark, but still....maybe the OSCAR spec has something about it?

I'll try to get a log from Empathy as well, maybe there's something too.
Comment 29 George Kiagiadakis 2012-07-18 12:09:28 UTC
There is one possibility that libpurple gets somehow confused by the "SetChatState" spamming that we do. This is the only difference that I could see between Empathy and KTp.
Comment 30 David Edmundson 2012-07-18 12:12:04 UTC
Well lets fix that and see if it makes a difference. It's only a one line if statement, and worth doing anyway.
Comment 31 Martin Klapetek 2012-07-18 13:00:24 UTC
Git commit 04a419887ba7102726ae4168294da613ea58a6e2 by Martin Klapetek.
Committed on 18/07/2012 at 14:58.
Pushed by mklapetek into branch 'kde-telepathy-0.4'.

Don't spam the channel with Composing state if the state actually hasn't changed

This fixes delays in messages with some accounts like ICQ/AIM, however if user sends quickly too many messages,
they will still be delayed (by libpurple), just considerably less. Now we're on par with Empathy and Kopete,
that's all we can do about it.

Reviewed-by: George Kiagiadakis
FIXED-IN: 0.4.1

M  +11   -3    lib/chat-widget.cpp

http://commits.kde.org/telepathy-text-ui/04a419887ba7102726ae4168294da613ea58a6e2
Comment 32 George Kiagiadakis 2012-07-21 13:48:57 UTC
*** Bug 292719 has been marked as a duplicate of this bug. ***