Opened 11 years ago

Closed 10 years ago

#5589 closed defect

Single disconnect triggers series of repeat disconnects

Reported by: Endymion Owned by: deryni
Milestone: Component: XMPP
Version: 2.4.1 Keywords: Jabber, disconnect
Cc: irabinovitch

Description

I've been having this issue for quite some time. In short, when I get disconnected from my company's Jabber server, Pidgin will automatically reconnect, but then I will repeatedly get disconnected with a "read error" every 17 minutes (approximately) until I manually disconnect, wait (usually a minute is sufficient), then reconnect.

This is reproducable behaviour for me and happens every time. Since I'm a German customer of T-Online, I have forced disconnects (they don't want people permanently online to keep IPs free) every 24h on my DSL line, so this happens at least once per day. Note that when these disconnects happen, my IP changes; however, I've seen this happen without an IP change as well (in case of some network blurp somewhere else). Currently I'm connected through a router, but this happened with direct connection through a DSL modem before as well.

The fact that manually disconnecting, then reconnecting after some wait reliably fixes the issue means that this is not a networking problem.

From a look around, I'm not sure if http://developer.pidgin.im/ticket/5278 and http://developer.pidgin.im/ticket/5441 might be related.

Change History (11)

comment:1 Changed 11 years ago by deryni

  • pending changed from 0 to 1

Can you get the debug window (Help->Debug Window) output of this happening?

comment:2 Changed 11 years ago by Endymion

  • pending changed from 1 to 0

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@…/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@…/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@…/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@…/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@…/Gaim" from="SOMECHAT@…/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@…/Gaim" affiliation="none" role="none"/></x></presence>

(11:44:32) jabber: Recv (ssl)(382): <presence to="XXX@…/Gaim" from="SOMECHAT@…/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@…/Gaim" affiliation="none" role="none"/></x></presence>

(11:44:32) jabber: Got presence for unknown buddy SOMECHAT@… on account XXX@…/Gaim (00C911E0)

(11:44:32) jabber: Recv (ssl)(391): <presence to="XXX@…/Gaim" from="OTHERCHAT@…/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@…/Gaim" affiliation="none" role="none"/></x></presence>

(11:44:32) jabber: Recv (ssl)(391): <presence to="XXX@…/Gaim" from="OTHERCHAT@…/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@…/Gaim" affiliation="none" role="none"/></x></presence>

(11:44:32) blist: Updating buddy status for OTHERCHAT@…/NONEXISTANTNICK (XMPP)

(11:44:32) blist: Updating buddy status for OTHERCHAT@…/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.]

comment:3 follow-up: Changed 11 years ago by deryni

  • Owner changed from nwalp to deryni

If you send a ping to the server and the server doesn't respond that would explain why you are disconnected, and would put the ball in the server's court. The server wouldn't happen to be running OpenFire would it?

comment:4 in reply to: ↑ 3 Changed 11 years ago by Endymion

Replying to deryni:

If you send a ping to the server and the server doesn't respond that would explain why you are disconnected, and would put the ball in the server's court. The server wouldn't happen to be running OpenFire would it?

It does indeed run OpenFire. Do you have suggestions regarding this that might help our admins fix the issue?

comment:5 Changed 11 years ago by deryni

No, this just isn't the first time I've seen what looks to be a problem with OpenFire dropping/not sending iq responses. See http://www.igniterealtime.org/community/thread/32156 for instance.

comment:6 Changed 11 years ago by unclemike79

I'm experiencing the same disconnects using Pidgin 2.4.0 and 2.4.1 with Openfire. Log to follow:

(10:27:15) account: Disconnecting account 00CCBD90<br> (10:27:15) connection: Disconnecting connection 01ED73D8 (10:27:15) connection: Deactivating keepalive. (10:27:16) connection: Destroying connection 01ED73D8 (10:27:20) util: Writing file accounts.xml to directory C:\Documents and Settings\joe.user\Application Data\.purple (10:27:20) util: Writing file C:\Documents and Settings\joe.user\Application Data\.purple\accounts.xml (10:27:21) util: Writing file blist.xml to directory C:\Documents and Settings\joe.user\Application Data\.purple (10:27:21) util: Writing file C:\Documents and Settings\joe.user\Application Data\.purple\blist.xml (10:27:24) autorecon: do_signon called (10:27:24) autorecon: calling purple_account_connect (10:27:24) account: Connecting to account joe.user@…/Laptop (10:27:24) connection: Connecting. gc = 0238D240 (10:27:24) dnssrv: querying SRV record for _xmpp-client._tcp.jabber.company.local (10:27:24) autorecon: done calling purple_account_connect

comment:7 Changed 11 years ago by deryni

unclemike79: That debug output snippet doesn't contain anything useful, you would need the bit immediately before that. That is the part where pidgin sends the ping and the server either does or does not respond. If most of the time pidgin sends pings the server responds but on occasion it doesn't (and it is those times that pidgin disconnects) then this is an Openfire bug.

comment:8 Changed 11 years ago by unclemike79

Sorry about that. How about this:

(09:22:35) jabber: Recv (ssl)(16): </stream:stream>
(09:23:15) jabber: Sending (ssl): <iq type='get' id='purple5a03ac69'><ping xmlns='urn:xmpp:ping'/></iq>
(09:23:15) account: Disconnecting account 00CCBDC8
(09:23:15) connection: Disconnecting connection 0206CE90
(09:23:15) connection: Deactivating keepalive.
(09:23:15) connection: Destroying connection 0206CE90
(09:23:20) util: Writing file accounts.xml to directory C:\Documents and Settings\joe.user\Application Data\.purple
(09:23:20) util: Writing file C:\Documents and Settings\joe.user\Application Data\.purple\accounts.xml
(09:23:21) util: Writing file blist.xml to directory C:\Documents and Settings\joe.user\Application Data\.purple
(09:23:21) util: Writing file C:\Documents and Settings\joe.user\Application Data\.purple\blist.xml
(09:23:55) autorecon: do_signon called
(09:23:55) autorecon: calling purple_account_connect
(09:23:55) account: Connecting to account joe.user@…/Laptop
(09:23:55) connection: Connecting. gc = 0237E5A0
(09:23:55) dnssrv: querying SRV record for _xmpp-client._tcp.jabber.company.local
(09:23:55) autorecon: done calling purple_account_connect

I suppose it is possible that this could be an issue with Openfire, but we only experienced this issue after upgrading Pidgin FWIW.

comment:9 Changed 11 years ago by deryni

The ping timeouts in pidgin are relatively new, so the fact that they only showed up recently is expected.

As to your debug output, the top line there is one of your accounts receiving a disconnection from the server (I can't tell which one because it doesn't say and we don't output that information there). Can you post a bit more from above that? Can you also do this with only the one account connected (that will help avoid cross-account confusion).

comment:10 Changed 10 years ago by darkrain42

  • Status changed from new to pending

Are you still experiencing this issue? If so, could you post the debug output deryni requested?

comment:11 Changed 10 years ago by trac-robot

  • Status changed from pending to closed

This ticket was closed automatically by the system. It was previously set to a Pending status and hasn't been updated within 14 days.

Note: See TracTickets for help on using tickets.
All information, including names and email addresses, entered onto this website or sent to mailing lists affiliated with this website will be public. Do not post confidential information, especially passwords!