Severe message sending delay

[rspeed@neonge.com]

There is a very significant lag when sending messages from AIM accounts. This issue appeared after installing 1.0b9.

Symptoms:

First I thought I was on drugs as many of my conversations became impossible to follow. It occurred to me that people appeared to be replying to messages long after I sent them. My testing consisted of two parts: First I had one of my contacts reply to a message immediately. In both tests the reply took nearly a minute. The second test was to open iChat and set up a conversation between the two screennames on the same machine. Messages going from iChat to Adium appeared instantly. Messages going from Adium to iChat were delayed by at least 1 minute.

Product/Component:

I tried similar testing with Jabber accounts and encountered no issues.

Reproducibility:

The issue has occurred in 100% of my tests.

[rspeed@…]

This issue still occurs as of revision 17392.

[mlf]

Can you please attach your adiumdebug.log and adiumjoscardebug.log? Also, can you do a sample (see Sampling ) while the lag is happening (after you send but before the other recieves)? Thanks!

[rspeed@…]

Adium Debug Log

[rspeed@…]

Adium Joscar Debug Log

[rspeed@…]

Adium Sample

[anonymous]

I have a Shark time profile as well, but it's too large to attach. If it would be helpful I can email it.

[anonymous]

I also just experienced this problem. Some of my messages weren't even received; I had to go back to .89 again.

[Patrick]

I've experienced this too. However, it doesn't occur 100% of the time. In my case, I was noticing a long delay as well. But once the messages finally showed up on iChat, the delay stopped for all new messages.

[rspeed@…]

Well here's something odd...

I'm at work now, and the issue no longer occurs. I haven't restarted or logged out, so that's not related.

So perhaps this is somehow related to the network? I'll try closing the forwarded ports for AIM when I get home.

[glowacz@…]

I noticed this after updating to b9. This only happens to me right after signing on. I suspect that this has to do with the new rate limiting "fix". My messages finally got sent after eveyone's away messages and icons were retrieved. Are outgoing messages getting added to the end of the away message retrival queue?

[mlf]

Replying to rspeed@neonge.com:

Well here's something odd...

I'm at work now, and the issue no longer occurs. I haven't restarted or logged out, so that's not related.

So perhaps this is somehow related to the network? I'll try closing the forwarded ports for AIM when I get home.

rspeed, your comment is interesting. If you can test this a couple of times and verify it is always the case, home vs work, (wireless vs wired?), to see if you can find the permanent fail case, that would be helpful. Is your work connection a pretty "high speed" one (100BaseT wired, vs 802.11[bg] at home?) And providing a tcpdump wen this is happening in the beginning would be helpful as well. BTW, how many people are on your buddy list (total, regular ones and recent buddies)? And do you also find that this clears up in a couple of minutes?

The developers might find the shark time sample useful.

thanks!

[A88Laptop <mgarrison@…>]

1.0b9 has fixed the rate limiting when signing on with a large buddy list, however, now when I send a message right after I have signed on it takes 4 or 5 minutes for it to actually get sent.

[7:24:22 PM EDT] ClientSnacProcessor: Queueing Snac request #100: SendTypingNotification from chok0nothi
ng (nulls=0, code=1): typing
[7:24:22 PM EDT] RateQueue: Enqueuing SendTypingNotification from chok0nothing (nulls=0, code=1): typing
 within ratequeue (class 1)...
[7:24:22 PM EDT] RateClassMonitor: Class 3 should be waiting 3334ms (avg is 2033ms)
[7:24:22 PM EDT] RateClassMonitor: Class 3 should be waiting 3334ms (avg is 2033ms)
[7:24:22 PM EDT] RateClassMonitor: Class 1 should be waiting -271726ms (avg is 5096ms)
[7:24:22 PM EDT] Conversation: ImConversation: firing outgoing event: TypingInfo{TYPING}
[7:24:22 PM EDT] RateClassMonitor: Class 1 should be waiting -271726ms (avg is 5096ms)
[7:24:22 PM EDT] RateQueue: Dequeueing SendTypingNotification from chok0nothing (nulls=0, code=1): typin
g from ratequeue (class 1)...
[7:24:22 PM EDT] RateQueue: sendAndDequeueReadyRequests(): RateQueue: rateMonitor=RateClassMonitor: rateInf
o=RateClassInfo for class 1, currentAvg=5376, windowSize=80, clearAvg=2500, warnAvg=2000, limitedAvg=1500, 
disconnectAvg=800, max=6000, lastTime=0, currentState=0, families: 186, last=1156202647342, runningAvg=4971
, limited=false, errorMargin=-1, queued: 0 will attempt to send 1
[7:24:22 PM EDT] RateClassMonitor: Class 1 should be waiting -271726ms (avg is 5096ms)
[7:24:22 PM EDT] ClientSnacProcessor: Sending SNAC request SnacRequest for SendTypingNotification from chok
0nothing (nulls=0, code=1): typing: listeners: null, responses: null
[7:24:22 PM EDT] FlapProcessor: Sending Flap packet FlapPacket (channel=2, seq=36): 44 total bytes
[7:24:24 PM EDT] ClientSnacProcessor: Queueing Snac request #101: SendImIcbm to chok0nothing (id=0, ackr
eq=true): IM: <HTML>can you see this?</HTML>
[7:24:24 PM EDT] RateQueue: Enqueuing SendImIcbm to chok0nothing (id=0, ackreq=true): IM: <HTML>can you 
see this?</HTML> within ratequeue (class 3)...
[7:24:24 PM EDT] RateClassMonitor: Class 3 should be waiting 1443ms (avg is 2127ms)
[7:24:24 PM EDT] RateClassMonitor: Class 3 should be waiting 1443ms (avg is 2127ms)
[7:24:24 PM EDT] Conversation: ImConversation: firing outgoing event: net.kano.joustsim.oscar.oscar.service
.icbm.ImMessageInfo@a39121
[7:24:24 PM EDT] ClientSnacProcessor: Queueing Snac request #102: SendTypingNotification from chok0nothi
ng (nulls=0, code=1): no text
[7:24:24 PM EDT] RateQueue: Enqueuing SendTypingNotification from chok0nothing (nulls=0, code=1): no tex
t within ratequeue (class 1)...
[7:24:24 PM EDT] Conversation: ImConversation: firing outgoing event: TypingInfo{NO_TEXT}
[7:24:24 PM EDT] RateClassMonitor: Class 3 should be waiting 1435ms (avg is 2128ms)
[7:24:24 PM EDT] RateClassMonitor: Class 3 should be waiting 1434ms (avg is 2128ms)
[7:24:24 PM EDT] RateClassMonitor: Class 1 should be waiting -263426ms (avg is 4992ms)
[7:24:24 PM EDT] RateClassMonitor: Class 1 should be waiting -263426ms (avg is 4992ms)
[7:24:24 PM EDT] RateQueue: Dequeueing SendTypingNotification from chok0nothing (nulls=0, code=1): no te
xt from ratequeue (class 1)...
[7:24:24 PM EDT] RateQueue: sendAndDequeueReadyRequests(): RateQueue: rateMonitor=RateClassMonitor: rateInf
o=RateClassInfo for class 1, currentAvg=5376, windowSize=80, clearAvg=2500, warnAvg=2000, limitedAvg=1500, 
disconnectAvg=800, max=6000, lastTime=0, currentState=0, families: 186, last=1156202662361, runningAvg=5032
, limited=false, errorMargin=-1, queued: 0 will attempt to send 1
[7:24:24 PM EDT] RateClassMonitor: Class 1 should be waiting -263428ms (avg is 4992ms)
[7:24:24 PM EDT] ClientSnacProcessor: Sending SNAC request SnacRequest for SendTypingNotification from chok
0nothing (nulls=0, code=1): no text: listeners: null, responses: null

Then it's finally sent:

[7:29:04 PM EDT] RateQueue: Dequeueing SendImIcbm to choking0nothing (id=0, ackreq=true): IM: <HTML>can you
 see this?</HTML> from ratequeue (class 3)...
[7:29:04 PM EDT] RateClassMonitor: Class 3 should be waiting -1ms (avg is 2200ms)
[7:29:04 PM EDT] RateQueue: sendAndDequeueReadyRequests(): RateQueue: rateMonitor=RateClassMonitor: rateInf
o=RateClassInfo for class 3, currentAvg=6000, windowSize=20, clearAvg=3100, warnAvg=2500, limitedAvg=2000, 
disconnectAvg=1500, max=6000, lastTime=182, currentState=0, families: 6, last=1156202940451, runningAvg=209
0, limited=false, errorMargin=-1, queued: 4 will attempt to send 1
[7:29:04 PM EDT] RateClassMonitor: Class 3 should be waiting -2ms (avg is 2200ms)
[7:29:04 PM EDT] ClientSnacProcessor: Sending SNAC request SnacRequest for SendImIcbm to choking0nothing (i
d=0, ackreq=true): IM: <HTML>can you see this?</HTML>: listeners: [net.kano.joustsim.oscar.oscar.service.ic
bm.ImConversation$2@8cb0d2], responses: null

[dcclark]

(posting this in a 3rd thread -- hopefully THIS is the correct thread finally)

I have this problem as well. Outgoing messages delay about 3 minutes before they are received by the other end. Incoming messages appear immediately, as they should. This happens only on AIM: I have tested with Yahoo, Jabber, and MSN and had no delay problems at all. I have about 190 AIM contacts.

I will attach adium and joscar logs, but here are some relevant joscar log snips for a message I sent to a contact:

Sending: [11:17:27 PM EDT] ClientSnacProcessor: Queueing Snac request #304: SendImIcbm to wearecs (id=0, ackreq=true): IM: <HTML>hey, I need to send you a test message</HTML> [11:17:27 PM EDT] RateQueue: Enqueuing SendImIcbm to wearecs (id=0, ackreq=true): IM: <HTML>hey, I need to send you a test message</HTML> within ratequeue (class 3)...

Actually Sent: [11:19:54 PM EDT] RateQueue: Dequeueing SendImIcbm to wearecs (id=0, ackreq=true): IM: <HTML>hey, I need to send you a test message</HTML> from ratequeue (class 3)... [11:19:54 PM EDT] ClientSnacProcessor: Sending SNAC request SnacRequest for SendImIcbm to wearecs (id=0, ackreq=true): IM: <HTML>hey, I need to send you a test message</HTML>: listeners: [net.kano.joustsim.oscar.oscar.service.icbm.ImConversation$2@afb02d], responses: null

[anonymous]

Additional info: I have experienced approximately the same behavior (2-3 minute delays) on both a fast (cable) connection, and a very slow (21.6kbps) dialup connection. This does not clear up after several minutes of waiting.

[dcclark]

Adium debug log from dcclark

[dcclark]

joscar debug log from dcclark

[anonymous]

Replying to mlf:

rspeed, your comment is interesting. If you can test this a couple of times and verify it is always the case, home vs work, (wireless vs wired?), to see if you can find the permanent fail case, that would be helpful. Is your work connection a pretty "high speed" one (100BaseT wired, vs 802.11[bg] at home?) And providing a tcpdump wen this is happening in the beginning would be helpful as well. BTW, how many people are on your buddy list (total, regular ones and recent buddies)? And do you also find that this clears up in a couple of minutes?

Both are wireless. Home is cable running through a SMC router and an Airport Express base station. Signal is full and there are no issues with latency or bandwith.

Work is a partial T1 line going through a G4 acting as a router, then through an Airport Extreme base station with external omnidirectional antenna. The signal is full as well. There are no issues with latency and bandwidth is decent (though less than at home).

I tried closing the ports, but it had no effect.

I'll try a TCP dump in the morning.

I have around 80+ contacts on one buddy list and 40+ on another. I've tested with a different account which had roughly 30 contacts and the issue was still present.

Unlike other reports, the issue does not clear up, though messages occasionally appear to be sent in a timely manner.

[aileron@…]

I have the issue as well: standard wireless connecting to a campus antenna. Problem occurs at all times, and seems to build in frequency the more conversations I have. The problem itself is always there, but that's because we're used to waiting for others to respond; it doesn't let up.

[tom.rund@…]

I too have this problem, the lag seems to very between 10 seconds all the way up to 5+ minutes at times. If there is any information I can provide to help rectify this issue please e-mail me.

Thanks, Tom

[anonymous]

It feels like every 10 minutes Adium tries to refresh my 100+ contacts away messages. Some kind of filter mechanism is activated, and I can't chat to people for 2+ minutes (even though it says it went through)

Please fix this, it's a program ruining bug :(

[dcclark]

The problem persists on a 3rd (wireless, Cable speed) network. Unfortunately, it makes AIM completely unusable. I would suggest making the severity of this ticket "major" or "severe", since it makes one main service unusable.

[rspeed@…]

As of today the lag is happening at my workplace as well.

[anonymous]

I just downloaded beta 10 (after experiencing the problem in beta 9), hoping it would fix things. I still get the delay, same as ever.

Please fix this, I'm dying to use Adium again.

[anonymous]

I just tried b11, same deal. Delays were about 3 minutes.

I think the priority of this one should be bumped up. This is not cool.

[evands]

#5283 has logs as well; they appear to be the same.

[adium]

(from dcclark) I deleted about a dozen AIM contacts from my list, and the delay seems to be down to: 1) a few seconds after first signing on, and 2) pretty much nothing after waiting a few minutes. Seems that quantity of contacts is key.

[adium]

(from glowacz@…) I haven't seen this problem in a few weeks. I remember first seeing it just after an AOL serve change. Maybe everythig worked itself out on their end.

[evands]

(In [18120]): joscar [484] which fixes rate limiting problems. Fixes #5367. Fixes #5252.

[zacw]

Removing component 'adium-joscar'.