search

google-code-export / pyicqt

Automatically exported from code.google.com/p/pyicqt
0 stars 0 forks source link

Connect breaks frequently: non-clean fashion #5

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
 Posted by guest at 2005-08-24 08:26:53

[2005-08-24 12:22:52] B: updateBuddy <OSCARUser 59880091, flags ['aim'],
online for 1 minutes>
[2005-08-24 12:22:52] User: 4886816@balancer.ru - JabberConnection sending
presence "4886816@balancer.ru" "59880091@icq.balancer.ru"
"None" "None" "None" "None"
[2005-08-24 12:22:52] ICQContacts: updating contact 59880091
[2005-08-24 12:22:52] User: 94471026@balancer.ru - JabberConnection sending
message "94471026@balancer.ru" "icq.balancer.ru/registered"
"ICQ connection lost! Reason: [Failure instance: Traceback (failure with no
frames): twisted.internet.error.ConnectionLost: Connection to the other
side was
lost in a non-clean fashion.
]" "error"
[2005-08-24 12:22:52] jabw: Sending a Jabber message
"94471026@balancer.ru" "icq.balancer.ru/registered"
"ICQ connection lost! Reason: [Failure instance: Traceback (failure with no
frames): twisted.internet.error.ConnectionLost: Connection to the other
side was
lost in a non-clean fashion.
]" "error"
[2005-08-24 12:22:52] xmlify: class is <type 'str'>: ICQ connection lost!
Reason: [Failure instance: Traceback (failure with no frames):
twisted.internet.error.ConnectionLost: Connection to the other side was lost in
a non-clean fashion.
]
[2005-08-24 12:22:52] Session: Removing "94471026@balancer.ru"
[2005-08-24 12:22:52] User: 94471026@balancer.ru - JabberConnection sending
presence "94471026@balancer.ru" "icq.balancer.ru/registered"
"None" "None" "None" "error"
[2005-08-24 12:22:52] LegacyConnection: removeMe
[2005-08-24 12:22:52] ICQConnection: removeMe
[2005-08-24 12:22:52] Session: Completed removal
"94471026@balancer.ru"
2005/08/24 12:22 MSD [B,client] Connection Lost! <legacy.icqt.B instance at
0xb74e024c>
2005/08/24 12:22 MSD [B,client] Stopping factory
<twisted.internet.protocol._InstanceFactory instance at 0xb74f518c>

Posted by jadestorm at 2005-08-24 11:40:15

What is this new "non-clean fashion" break I'm seeing lately?  Hrm....
 I'm not sure what would be causing that!  Unless we sent something to ICQ that
"crashed" our session and ICQ disconnected us 'rudely'.  Hrm.... 
maybe that's it.

Posted by jadestorm at 2005-08-24 11:40:52

From Subject: Very much connection frequently breaks: ICQ connection lost!
ConnectionLost: Connection to the other side was lost in a non-clean fashion.

Posted by Eythian at 2005-09-07 10:32:59

Just a note: I'm seeing this a reasonable amount also.

Posted by jadestorm at 2005-12-31 17:28:52

This seems to be mother ICQ outright disconnecting you.  The real ICQ client
"hides" this a tad as it auto reconnects and doesn't tell you about
it.  Not sure what to do about this yet.

Posted by guest at 2006-03-05 22:06:45

Is there a fix in SVN yet? I'm using 0.7 and get this error several times a
day.
At least 7 times today I guess.

Wouldn't it be a good idea to handle this like the official clients do:
Silently
reconnect. Maybe an additional debug message to the log.

Posted by jadestorm at 2006-03-05 23:03:54

Nope, I have no idea what causes it.  If anyone else happens to find a way to
fix it let me know.  (or is able to figure out what causes it)

As for the reconnect, still haven't thought that through.

Posted by guest at 2006-05-30 11:38:04

I used Rev 159 with jabberd 1.4.3 where everything worked (more or less) fine.
But now I upgraded to ejabberd 1.1.1 with pyicq-t 0.7a, using the same
configuration for icq.
After that all my users were able to use the transport without problems (even
better: no strange away-messages anymore, someone said), but I am not able to
use the transport:
I log on, have to wait some minutes and then comes the non-clean-fashion-stuff.
I started pyicq with -D and saw "message" is "oversized" (I
didn't send a message though, I just wanted to log in).
I'm using the transport with twisted 2.4.0, ~web 0.6.0, ~words 0.4.0, ~xish
0.1.0

Posted by jadestorm at 2006-05-30 11:44:56

You shouldn't have to worry about the oversized message thing.  That's just a
debug message intended to make it so your debug logs don't get tooooooo
ridiculous.  =)  Doesn't really mean that anything you were doing was
oversized.

Could you email me some debug logs from when you log in until when you get the
disconnection?

Posted by guest at 2006-05-30 20:32:54

ok, first the xml-stuff being sent from psi to ejabberd and back directly after
clicking on "Log on" (I shortened the statusmessage and "x
xmlns="jabber:x:signed" and removed an ICQ#):

=============================================================================
<presence to="icq.schattenwelten.dyndns.org" >
<status>statusmsg </status>
<priority>5</priority>
<x
xmlns="jabber:x:signed">c8C/Ic98lGuCd+YCZhAQCeKH5E=gLaQ</x>
<x xmlns="jabber:x:avatar">
<hash></hash>
</x>
<x xmlns="vcard-temp:x:update">
<photo></photo>
<nickname>Paganlord</nickname>
</x>
</presence>

<presence from="XXXXXXXX@icq.schattenwelten.dyndns.org"
type="unavailable"
to="paganlord@schattenwelten.dyndns.org/tvk" >
<x xmlns="vcard-temp:x:update"/>
<c xmlns="http://jabber.org/protocol/caps"
node="http://pyicq-t.blathersource.org/protocol/caps"
ver="0.7a" />
</presence>

<iq type="get"
to="XXXXXXXX@icq.schattenwelten.dyndns.org" id="a1192a"
>
<query xmlns="jabber:iq:version"/>
</iq>

<iq from="icq.schattenwelten.dyndns.org" type="get"
id="347" to="paganlord@schattenwelten.dyndns.org/tvk" >
<query xmlns="http://jabber.org/protocol/disco#info"/>
</iq>

<iq type="result" to="icq.schattenwelten.dyndns.org"
id="347" >
<query xmlns="http://jabber.org/protocol/disco#info">
<identity category="client" type="pc" />
<feature var="http://jabber.org/protocol/bytestreams" />
<feature var="http://jabber.org/protocol/si" />
<feature var="http://jabber.org/protocol/si/profile/file-transfer"
/>
<feature var="http://jabber.org/protocol/muc" />
</query>
</iq>

<iq from="XXXXXXXX@icq.schattenwelten.dyndns.org"
type="result" id="a1192a"
to="paganlord@schattenwelten.dyndns.org/tvk" >
<query xmlns="jabber:iq:version">
<name>ICQ Transport</name>
<version>0.7a</version>
<os>Python2.4.3 (#1, May  7 2006, 20:31:58) 
[GCC 3.4.6 (Gentoo 3.4.6-r1, ssp-3.4.5-1.0, pie-8.7.9)]</os>
</query>
</iq>

=============================================================================

And now the stuff when the non clean fashion arrives:

=============================================================================
<message from="icq.schattenwelten.dyndns.org"
type="error" id="355"
to="paganlord@schattenwelten.dyndns.org" >
<body>ICQ connection lost! Reason: [Failure instance: Traceback (failure
with no frames): twisted.internet.error.ConnectionLost: Connection to the other
side was lost in a non-clean fashion.
]</body>
<x xmlns="jabber:x:event">
<composing/>
</x>
<active xmlns="http://jabber.org/protocol/chatstates"/>
</message>

<presence from="icq.schattenwelten.dyndns.org"
type="unavailable"
to="paganlord@schattenwelten.dyndns.org/tvk" >
<x xmlns="vcard-temp:x:update"/>
</presence>

<iq type="get" to="icq.schattenwelten.dyndns.org"
id="a1193a" >
<query xmlns="jabber:iq:version"/>
</iq>

<iq from="icq.schattenwelten.dyndns.org" type="result"
id="a1193a" to="paganlord@schattenwelten.dyndns.org/tvk"
>
<query xmlns="jabber:iq:version">
<name>ICQ Transport</name>
<version>0.7a</version>
<os>Python2.4.3 (#1, May  7 2006, 20:31:58) 
[GCC 3.4.6 (Gentoo 3.4.6-r1, ssp-3.4.5-1.0, pie-8.7.9)]</os>
</query>
</iq>

=============================================================================

The transport -D messages will follow tomorrow morning, when my users are
sleeping, I don't want to annoy them with several restarts ^^

Posted by guest at 2006-05-31 07:20:23

ok, here is the -D output directly after klicking on "Log on":

=============================================================================
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
onPresence :: {'el': <twisted.words.xish.domish.Element object at
0xb747d1cc>, 'self': 'instance'} ::
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org ::
glue.LegacyConnection :: setStatus :: {'url': None, 'self': 'instance',
'nickname': u'Paganlord', 'friendly': None, 'show': None} ::
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
onPresence :: {'status': None, 'el': <twisted.words.xish.domish.Element
object at 0xb747d1cc>, 'child2': <twisted.words.xish.domish.Element object
at 0xb74768ec>, 'froj': <twisted.words.protocols.jabber.jid.JID instance
at 0xad3d39ec>, 'show': None, 'url': None, 'self': 'instance', 'fro':
u'paganlord@schattenwelten.dyndns.org/tvk', 'avatarHash': ' ', 'ptype': None,
'priority': u'5', 'to': u'icq.schattenwelten.dyndns.org', 'child':
<twisted.words.xish.domish.Element object at 0xb7476d2c>, 'nickname':
u'Paganlord', 'toj': <twisted.words.protocols.jabber.jid.JID instance at
0xb74a052c>} :: Parsed presence packet
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
handleResourcePresence :: {'status': None, 'resource': u'tvk', 'show': None,
'url': None, 'self': 'instance', 'ptype': None, 'existing': True, 'priority':
u'5', 'to': u'icq.schattenwelten.dyndns.org', 'tor': None, 'source':
u'paganlord@schattenwelten.dyndns.org'} :: Setting status
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
handleResourcePresence :: {'status': None, 'resource': u'tvk', 'show': None,
'url': None, 'self': 'instance', 'ptype': None, 'existing': True, 'priority':
u'5', 'to': u'icq.schattenwelten.dyndns.org', 'tor': None, 'source':
u'paganlord@schattenwelten.dyndns.org', 'highestActive': u'tvk'} :: Updating
status on legacy service
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org ::
glue.LegacyConnection :: setStatus :: {'url': None, 'self': 'instance',
'nickname': u'Paganlord', 'friendly': None, 'show': None} ::

=============================================================================

and this happens on nonclean-fasion:

=============================================================================
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
onPresence :: {'status': None, 'el': <twisted.words.xish.domish.Element
object at 0xb747d1cc>, 'child2': <twisted.words.xish.domish.Element object
at 0xb74768ec>, 'froj': <twisted.words.protocols.jabber.jid.JID instance
at 0xad3d39ec>, 'show': None, 'url': None, 'self': 'instance', 'fro':
u'paganlord@schattenwelten.dyndns.org/tvk', 'avatarHash': ' ', 'ptype': None,
'priority': u'5', 'to': u'icq.schattenwelten.dyndns.org', 'child':
<twisted.words.xish.domish.Element object at 0xb7476d2c>, 'nickname':
u'Paganlord', 'toj': <twisted.words.protocols.jabber.jid.JID instance at
0xb74a052c>} :: Parsed presence packet
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
handleResourcePresence :: {'status': None, 'resource': u'tvk', 'show': None,
'url': None, 'self': 'instance', 'ptype': None, 'existing': True, 'priority':
u'5', 'to': u'icq.schattenwelten.dyndns.org', 'tor': None, 'source':
u'paganlord@schattenwelten.dyndns.org'} :: Setting status
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
handleResourcePresence :: {'status': None, 'resource': u'tvk', 'show': None,
'url': None, 'self': 'instance', 'ptype': None, 'existing': True, 'priority':
u'5', 'to': u'icq.schattenwelten.dyndns.org', 'tor': None, 'source':
u'paganlord@schattenwelten.dyndns.org', 'highestActive': u'tvk'} :: Updating
status on legacy service
[2006-05-31 09:11:35] INFO :: paganlord@schattenwelten.dyndns.org ::
glue.LegacyConnection :: setStatus :: {'url': None, 'self': 'instance',
'nickname': u'Paganlord', 'friendly': None, 'show': None} ::
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org :: icqt.B ::
connectionLost :: {'message': 'Oversize arg', 'reason':
<twisted.python.failure.Failure twisted.internet.error.ConnectionLost>,
'self': 'instance'} :: ICQ connection lost! Reason: [Failure instance:
Traceback
(failure with no frames): twisted.internet.error.ConnectionLost: Connection to
the other side was lost in a non-clean fashion.
        ]
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
sendMessage :: {'body': 'Oversize arg', 'delay': None, 'self': 'instance',
'fro': 'icq.schattenwelten.dyndns.org', 'mtype': 'error', 'to':
u'paganlord@schattenwelten.dyndns.org', 'xhtml': None} ::
[2006-05-31 09:12:40] INFO ::  :: 4/site-packages/pyicq-t/src/jabw.p ::
sendMessage :: {'body': 'Oversize arg', 'delay': None, 'fro':
'icq.schattenwelten.dyndns.org', 'mtype': 'error', 'to':
u'paganlord@schattenwelten.dyndns.org', 'xhtml': None, 'pytrans':
<main.PyTransport instance at 0xb772f08c>} ::
[2006-05-31 09:12:40] Connection Lost! <legacy.icqt.B instance at
0xb748bf8c>
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
removeMe :: {'self': 'instance'} ::
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
sendPresence :: {'status': None, 'show': None, 'url': None, 'self': 'instance',
'fro': 'icq.schattenwelten.dyndns.org', 'ptype': 'unavailable', 'avatarHash':
None, 'priority': None, 'to': u'paganlord@schattenwelten.dyndns.org',
'nickname': None, 'payload': []} ::
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org ::
glue.LegacyConnection :: removeMe :: {'self': 'instance', 'icq2jid':
<function icq2jid at 0xb771564c>} ::
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org ::
ContactList
:: removeMe :: {'self': 'instance'} ::
[2006-05-31 09:12:40] INFO :: paganlord@schattenwelten.dyndns.org :: Session ::
removeMe :: {'self': 'instance', 'tmpjid': 'icq.schattenwelten.dyndns.org'} ::
Removed!
[2006-05-31 09:12:40] INFO ::  :: ServerDiscovery :: onIq :: {'el':
<twisted.words.xish.domish.Element object at 0xb748ab6c>, 'froj':
<twisted.words.protocols.jabber.jid.JID instance at 0xb74a12ec>, 'iqType':
u'get', 'self': 'instance', 'fro': u'paganlord@schattenwelten.dyndns.org/tvk',
'ulang': None, 'to': u'icq.schattenwelten.dyndns.org', 'ID': u'aac1a'} ::
Looking for handler
[2006-05-31 09:12:40] INFO ::  :: ServerDiscovery :: onIq :: {'node': None,
'el': <twisted.words.xish.domish.Element object at 0xb748ab6c>, 'froj':
<twisted.words.protocols.jabber.jid.JID instance at 0xb74a12ec>, 'iqType':
u'get', 'self': 'instance', 'fro': u'paganlord@schattenwelten.dyndns.org/tvk',
'feature': 'jabber:iq:version', 'xmlns': u'jabber:iq:version', 'ulang': None,
'to': u'icq.schattenwelten.dyndns.org', 'handler': <bound method
VersionTeller.incomingIq of <misciq.VersionTeller instance at
0xb772f1ac>>, 'query': <twisted.words.xish.domish.Element object at
0xb748ab4c>, 'searchjid': u'icq.schattenwelten.dyndns.org', 'ID': u'aac1a'}
:: Handler found
[2006-05-31 09:12:40] INFO ::  :: VersionTeller :: sendVersion :: {'el':
<twisted.words.xish.domish.Element object at 0xb748ab6c>, 'self':
'instance'} ::

=============================================================================

Posted by jadestorm at 2006-05-31 13:40:12

How odd, I don't see anything there that's actually causing a problem  =/

Posted by guest at 2006-09-03 10:58:58

I  can confirm that bug. I spent one day on configuring JIT and one day on
configuring pyICQt and still without much success, so I almost gave up on the
idea of jabber2icq gateway :-/. 

Thing is... I have about 200 people in my ICQ contact list, and when I try to
add this account into pyICQt, it just ends up with this bug reported above.
However, when I instead try my secondary account that I use in work and
that has
only about 30 people in the contact list, everything works fine, it just
connects, shows correct presence information for everyone in the contactlist
etc. So maybe this bug is related to contactlist size? 

Posted by jadestorm at 2006-09-05 19:36:56

Out of curiousity, how long have you had your ICQ account?

Posted by guest at 2006-09-09 23:24:50

Please, make a silent reconnect! I'm 80% sure that this is normal for icq to
disconnect sometimes. Good error handling is the way to ownage ;)

Posted by jadestorm at 2006-09-09 23:25:40

I'm open to patches.  ;)  I haven't had time lately.

Original issue reported on code.google.com by jadest...@gmail.com on 10 Dec 2007 at 2:55

GoogleCodeExporter commented 9 years ago 
Bumped against this (apparently old) issue as well and wrote a suggested 
"silent reconnect" patch (attached).

I didn't dig deep into code, just wrote a test-case (connection breaker) and 
compared the log of broken connection and a cleanly closed one, noticing that 
former gets connectionLost event before removing the session, while latter gets 
it as a result, and exploited this difference by introducing a "active_close" 
flag to session and a simple session re-creation sequence in removeMe method.

Note that it's probably not the best way to do it, and it's only designed to be 
a cure for unexpectedly broken (for whatever reason) TCP connections.

Attached are the patch for 838d7a8af86 (git) and the simple scapy-based script 
to hijack and break the tcp connection after any activity on it, which can be 
used as a simple real-world test-case (unless icq server bans you for too 
frequent reconnects) for further improvements.

Original comment by mk.fraggod@gmail.com on 22 Jan 2011 at 7:05

Attachments: