[Pidgin] #5589: Single disconnect triggers series of repeat disconnects

Fri Apr 25 06:31:40 EDT 2008

#5589: Single disconnect triggers series of repeat disconnects
-----------------------+----------------------------------------------------
  Reporter:  Endymion  |       Owner:  nwalp             
      Type:  defect    |      Status:  new               
  Priority:  minor     |   Milestone:                    
 Component:  XMPP      |     Version:  2.4.1             
Resolution:            |    Keywords:  Jabber, disconnect
   Pending:  1         |  
-----------------------+----------------------------------------------------
Changes (by Endymion):

  * pending:  1 => 0

Comment:

 This has proven more difficult than I'd have expected; hopefully, I got
 all the relevant bits. I took out identifiable information (sorry, that's
 a company server and I don't want anything identifiable publicly posted).

 First of all, what I can see in the debug window that seems related is a
 bunch of

 (11:35:00) jabber: Sending (ssl): <iq type='get' id='purple3fc07ed2'><ping
 xmlns='urn:xmpp:ping'/></iq>

 (11:35:01) jabber: Recv (ssl)(211): <iq type="error" id="purple3fc07ed2"
 to="XXX at XXX.net/Gaim"><ping xmlns="urn:xmpp:ping"/><error code="503"
 type="cancel"><service-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-
 stanzas"/></error></iq>

 This happens during normal, mostly functional usage.

 And here is the original disconnect, followed by reconnect and
 disconnecting again.

 (11:39:30) jabber: Sending (ssl): <iq type='get' id='purple3fc07ed6'><ping
 xmlns='urn:xmpp:ping'/></iq>

 (11:39:31) account: Disconnecting account 00C911E0

 (11:39:31) connection: Disconnecting connection 06333EB0

 (11:39:31) connection: Deactivating keepalive.

 (11:39:31) connection: Destroying connection 06333EB0

 (11:39:36) util: Writing file accounts.xml to directory C:\Documents and
 Settings\XXX\Application Data\.purple

 (11:39:36) util: Writing file C:\Documents and Settings\XXX\Application
 Data\.purple\accounts.xml

 (11:39:36) util: Writing file blist.xml to directory C:\Documents and
 Settings\XXX\Application Data\.purple

 (11:39:36) util: Writing file C:\Documents and Settings\XXX\Application
 Data\.purple\blist.xml

 (11:40:04) autorecon: do_signon called

 (11:40:04) autorecon: calling purple_account_connect

 (11:40:04) account: Connecting to account XXX at XXX.net/Gaim

 (11:40:04) connection: Connecting. gc = 07A37860

 (11:40:04) dnssrv: querying SRV record for _xmpp-client._tcp.XXX.net

 (11:40:04) autorecon: done calling purple_account_connect

 (11:40:04) dnssrv: found 1 SRV entries

 (11:40:04) dnsquery: Performing DNS lookup for jabber.XXX.net

 (11:40:04) dnsquery: IP resolved for jabber.XXX.net

 (11:40:04) proxy: Attempting connection to XX.XXX.XXX.XXX

 (11:40:04) proxy: Connecting to jabber.XXX.net:5222 with no proxy

 (11:40:04) proxy: Connection in progress

 (11:40:04) proxy: Connected to jabber.XXX.net:5222.

 [A lot of protocol and SSL negotiation stuff that looks like a pain to
 anonymize - will do if it's required, but skipping for now]

 (11:40:08) jabber: jabber_actions: have pep: NO

 (11:40:08) connection: Activating keepalive.

 (11:40:08) jabber: Sending (ssl): <presence
 to='SOMECHAT at conference.XXX.net/XXX'><priority>1</priority><c
 xmlns='http://jabber.org/protocol/caps' node='http://pidgin.im/caps'
 ver='2.4.1' ext='moodn nickn tunen avatar'/><x
 xmlns='http://jabber.org/protocol/muc'/></presence>

 [More stuff that hopefully is not relevant]

 (11:40:17) jabber: Sending (ssl): <iq type='get'
 id='purplebd80e840'><vCard xmlns='vcard-temp'/></iq>

 (11:40:17) jabber: Sending (ssl): <iq type='get'
 id='purplebd80e841'><query xmlns='jabber:iq:roster'/></iq>

 (11:40:17) jabber: attempt to send presence before roster retrieved

 (11:40:17) jabber: jabber_actions: have pep: YES

 (11:40:17) jabber: Found bytestream proxy server: proxy.XXX.net

 [...]

 (11:40:18) jabber: Discovered bytestream proxy server: jid='proxy.XXX.net'
 host='192.168.XX.XX' port='7777' zeroconf=''

 [...]

 (11:41:38) jabber: Sending (ssl): <iq type='get' id='purplebd80e84a'><ping
 xmlns='urn:xmpp:ping'/></iq>

 (11:41:38) jabber: Recv (ssl)(211): <iq type="error" id="purplebd80e84a"
 to="XXX at XXX.net/Gaim"><ping xmlns="urn:xmpp:ping"/><error code="503"
 type="cancel"><service-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-
 stanzas"/></error></iq>

 [more of these]

 (11:44:31) jabber: Recv (ssl)(382): <presence to="XXX at XXX.net/Gaim"
 from="SOMECHAT at conference.XXX.net/XXX"
 type="unavailable"><priority>1</priority><c
 xmlns="http://jabber.org/protocol/caps" node="http://pidgin.im/caps"
 ver="2.4.1" ext="moodn nickn tunen avatar"/><x
 xmlns="http://jabber.org/protocol/muc#user"><item jid="XXX at XXX.net/Gaim"
 affiliation="none" role="none"/></x></presence>

 (11:44:32) jabber: Recv (ssl)(382): <presence to="XXX at XXX.net/Gaim"
 from="SOMECHAT at conference.XXX.net/XXX"
 type="unavailable"><priority>1</priority><c
 xmlns="http://jabber.org/protocol/caps" node="http://pidgin.im/caps"
 ver="2.4.1" ext="moodn nickn tunen avatar"/><x
 xmlns="http://jabber.org/protocol/muc#user"><item jid="XXX at XXX.net/Gaim"
 affiliation="none" role="none"/></x></presence>

 (11:44:32) jabber: Got presence for unknown buddy
 SOMECHAT at conference.XXX.net on account XXX at XXX.net/Gaim (00C911E0)

 (11:44:32) jabber: Recv (ssl)(391): <presence to="XXX at XXX.net/Gaim"
 from="OTHERCHAT at conference.XXX.net/XXX"
 type="unavailable"><priority>1</priority><c
 xmlns="http://jabber.org/protocol/caps" node="http://pidgin.im/caps"
 ver="2.4.1" ext="moodn nickn tunen avatar"/><x
 xmlns="http://jabber.org/protocol/muc#user"><item jid="XXX at XXX.net/Gaim"
 affiliation="none" role="none"/></x></presence>

 (11:44:32) jabber: Recv (ssl)(391): <presence to="XXX at XXX.net/Gaim"
 from="OTHERCHAT at conference.XXX.net/XXX"
 type="unavailable"><priority>1</priority><c
 xmlns="http://jabber.org/protocol/caps" node="http://pidgin.im/caps"
 ver="2.4.1" ext="moodn nickn tunen avatar"/><x
 xmlns="http://jabber.org/protocol/muc#user"><item jid="XXX at XXX.net/Gaim"
 affiliation="none" role="none"/></x></presence>

 (11:44:32) blist: Updating buddy status for
 OTHERCHAT at conference.XXX.net/NONEXISTANTNICK (XMPP)

 (11:44:32) blist: Updating buddy status for
 OTHERCHAT at conference.XXX.net/OTHERNONEXISTANTNICK (XMPP)

 [This part seems interesting to me. I should note - when this series of
 disconnects happen, I only auto-rejoin the two chat rooms there every
 *second* reconnect. Note that I did not duplicate the lines above - they
 appeared like that. Also curious is the "updating buddy status for..."
 with a name who hasn't been on that chat for months - that account is
 deactivated since early March - if anyone has comments on this, I'd be
 glad to hear, too!]

 (11:45:08) jabber: Sending (ssl): <iq type='get' id='purplebd80e850'><ping
 xmlns='urn:xmpp:ping'/></iq>

 [Note that between the above and this I did not leave out anything other
 than MSN pings - the received error message that shows for the other pings
 (see first lines) does not show here. Does this mean the problem is on our
 server's side?]

 (11:47:08) account: Disconnecting account 00C911E0

 (11:47:08) connection: Disconnecting connection 07A37860

 (11:47:08) connection: Deactivating keepalive.

 (11:47:08) connection: Destroying connection 07A37860

 [Followed by reconnecting as usual. Repeat every few minutes.]

-- 
Ticket URL: <http://developer.pidgin.im/ticket/5589#comment:2>
Pidgin <http://pidgin.im>
Pidgin