Bug 246156 - kopete connection timeout around every 3 minutes (jabber)
Summary: kopete connection timeout around every 3 minutes (jabber)
Status: RESOLVED FIXED
Alias: None
Product: kopete
Classification: Unmaintained
Component: libkopete (other bugs)
Version First Reported In: 1.0.0
Platform: Arch Linux Linux
: NOR normal
Target Milestone: ---
Assignee: Kopete Developers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-07-29 15:04 UTC by Ike Devolder
Modified: 2010-07-30 21:25 UTC (History)
1 user (show)

See Also:
Latest Commit:
Version Fixed/Implemented In:
Sentry Crash Report:


Attachments
proposed patch to make it reachable (1.04 KB, patch)
2010-07-29 15:04 UTC, Ike Devolder
Details
no action when data_sent == 0 (1.08 KB, patch)
2010-07-30 09:27 UTC, Ike Devolder
Details
show some tcp debug logging when started from konsole (857 bytes, patch)
2010-07-30 11:10 UTC, Ike Devolder
Details
tcpdum & kopete konsole output (37.56 KB, text/plain)
2010-07-30 12:26 UTC, Ike Devolder
Details
another tcpdump & kopete (62.03 KB, text/plain)
2010-07-30 12:46 UTC, Ike Devolder
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Ike Devolder 2010-07-29 15:04:26 UTC
Created attachment 49636 [details]
proposed patch to make it reachable

Version:           1.0.0 (using KDE 4.4.5) 
OS:                Linux

kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  48336992 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  0 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: mTimeoutThreshold  15000 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: getSockOpt == 0 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  1 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  32767 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: mTimeoutThreshold  15000 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: getSockOpt == 0 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: Connection timeout for   QHostAddress( "193.168.4.117" )  
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  38237024 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  4294967295 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: mTimeoutThreshold  15000 
kopete(3401) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: getSockOpt == 0


there is some unreachable code in kopetesockettimeoutwatcher.cpp

you will never reach the 
else if ( info.tcpi_last_ack_recv < info.tcpi_last_data_sent )

since the if will be sattisfactory for an 'false' connection timeout

Reproducible: Always

Steps to Reproduce:
just connect to an jabber server

Actual Results:  
from time to time i get a "false" connection timeout

Expected Results:  
connectiontimeout

just stay online
Comment 1 Ike Devolder 2010-07-29 15:07:26 UTC
ok every 3 minutes was just before i submitted this bug, its not that simple, sometimes it keeps up for hours
Comment 2 Ike Devolder 2010-07-30 09:26:07 UTC
sorry, i had it wrong

changed the logging and found the real problem

kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  10000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  10000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_recv  43530 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: ack_recv - data_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  25000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  25000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_recv  58530 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: ack_recv - data_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  40000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  40000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_recv  73530 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: ack_recv - data_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  55000 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_recv  88530 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: ack_recv - data_sent  55000 <<------- because data_sent == 0 !!!
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: Connection timeout for   QHostAddress( "193.168.4.117" )  
Unknown signature value:  795 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_sent  0 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_ack_recv  963 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_sent  966 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: info.tcpi_last_data_recv  963 
kopete(22308) Kopete::SocketTimeoutWatcher::ackTimeoutCheck: ack_recv - data_sent  4294967293
Comment 3 Ike Devolder 2010-07-30 09:27:44 UTC
Created attachment 49663 [details]
no action when data_sent == 0
Comment 4 Roman Jarosz 2010-07-30 09:58:30 UTC
The patch looks good (I actually created the same patch 5 min ago :( ).

Could you capture the tcpi_last_ack_recv, tcpi_last_data_sent with your patch, I would like to know what will happen after the tcpi_last_data_sent is 0. Thanks
Comment 5 Ike Devolder 2010-07-30 11:08:45 UTC
do you mean just kWarning() ?

then i attach the patch i used for checking it out, apply after previously attached patch
Comment 6 Ike Devolder 2010-07-30 11:10:43 UTC
Created attachment 49667 [details]
show some tcp debug logging when started from konsole

apply after kopetesockettimeoutwatcher.cpp.patch

in kdenetwork:
patch -Np0 -i ${srcdir}/kopetesockettimeoutwatcher.cpp.patch
patch -Np0 -i ${srcdir}/kopetesockettimeoutwatcher.cpp.logmsg.patch
Comment 7 Ike Devolder 2010-07-30 11:13:34 UTC
(In reply to comment #5)
> do you mean just kWarning() ?
> 
> then i attach the patch i used for checking it out, apply after previously
> attached patch

sorry for the overload of reply's and so

the patch as given, is now running for 3 hours straight without one disconnect
Comment 8 Roman Jarosz 2010-07-30 11:18:03 UTC
No I meant, if you could show me Kopete console log with the fix and "show some tcp debug logging when started from konsole" patches applied. I'm interested in the part right after tcpi_last_data_sent is 0.
Comment 9 Ike Devolder 2010-07-30 12:26:28 UTC
Created attachment 49670 [details]
tcpdum & kopete konsole output

tried to get the data requested with tcpdump

started:
tcpdump -n > tcpdump.log 2>&1
kopete > kopete.log 2>&1

logged with:
tail -n 0 --silent --follow=name --retry kopete.log tcpdump.log
Comment 10 Ike Devolder 2010-07-30 12:33:09 UTC
extra info:

my ip = 193.168.4.112
jabber server ip = 193.168.4.117
Comment 11 Ike Devolder 2010-07-30 12:46:23 UTC
Created attachment 49671 [details]
another tcpdump & kopete

another tcpdump & kopete konsole output log
Comment 12 Roman Jarosz 2010-07-30 16:35:16 UTC
Thanks for the logs.
Do you have SVN account or should I commit your patch?
Comment 13 Ike Devolder 2010-07-30 18:18:01 UTC
i have no svn account, you can commit the patch
Comment 14 Roman Jarosz 2010-07-30 21:24:37 UTC
SVN commit 1157349 by rjarosz:

Fix bug 246156, kopete connection timeout around every 3 minutes.
Patch by Ike Devolder, thanks.

BUG: 246156


 M  +5 -5      kopetesockettimeoutwatcher.cpp  


WebSVN link: http://websvn.kde.org/?view=rev&revision=1157349
Comment 15 Roman Jarosz 2010-07-30 21:25:26 UTC
SVN commit 1157350 by rjarosz:

Backport commit 1157349.
Fix bug 246156, kopete connection timeout around every 3 minutes                                                                            
Patch by Ike Devolder, thanks.                                                                                                              
                                                                                                                                            
CCBUG: 246156  



 M  +5 -5      kopetesockettimeoutwatcher.cpp  


WebSVN link: http://websvn.kde.org/?view=rev&revision=1157350