ReconnectionManager sends duplicate login requests while reconnecting

Smack Smack Support
1

I’m creating an android Xmpp client using Smack(4.1.7). While implementing the automatic re-connection feature using ReconnectionManager, I find that the library sends duplicate login requests. Because of that the second Reconnection is rejected by server with error - Client is already logged in.

Here is the XML dump from Smack:

06-20 15:42:37.704 26369-26612/in.gappi.gappichat D/SMACK: XMPPConnection closed due to an exception (0)

06-20 15:42:37.714 26369-26612/in.gappi.gappichat W/System.err: java.net.SocketException: recvfrom failed: ETIMEDOUT (Connection timed out)

06-20 15:42:37.714 26369-26612/in.gappi.gappichat W/System.err: at libcore.io.IoBridge.maybeThrowAfterRecvfrom(IoBridge.java:592)

06-20 15:42:37.714 26369-26612/in.gappi.gappichat W/System.err: at libcore.io.IoBridge.recvfrom(IoBridge.java:556)

…

…

06-20 15:42:38.714 26369-26829/in.gappi.gappichat D/GappiXmpp: Reconnecting 10

06-20 15:42:38.714 26369-26829/in.gappi.gappichat D/SMACK: XMPPConnection (0) will reconnect in 10

…

06-20 15:42:48.724 26369-26829/in.gappi.gappichat D/GappiXmpp: Reconnecting 0

06-20 15:42:48.724 26369-26829/in.gappi.gappichat D/SMACK: XMPPConnection (0) will reconnect in 0

06-20 15:42:48.894 26369-27615/in.gappi.gappichat D/SMACK: SENT (0): <stream:stream xmlns='jabber:client' to='gappi.in' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='9739937980@gappi.in' xml:lang='en'>

06-20 15:42:48.984 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='11040239326876846172' from='gappi.in' version='1.0' xml:lang='en'>

06-20 15:42:48.984 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): <stream:features><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='PXc8x7mNN6cEIZgjsEishHW4d3E='/><register xmlns='http://jabber.org/features/iq-register'/><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>DIGEST-MD5</mechanism><mech anism>SCRAM-SHA-1</mechanism><mechanism>PLAIN</mechanism><mechanism>X-OAUTH2</me chanism></mechanisms></stream:features>

06-20 15:42:48.994 26369-27615/in.gappi.gappichat D/SMACK: SENT (0): biwsbj05NzM5OTM3OTgwLHI9QncuaHNmXV8lOGAyInQzTEJacnpkXmB PVCR3Rl90J0M=

06-20 15:42:49.094 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): cj1Cdy5oc2ZdXyU4YDIidDNMQlpyemReYE9UJH dGX3QnQ0RsUkhLTTRJU2V5ZG1LNGtSRThva3c9PSxzPUpJemJtbXAxaExzRFNZV042M1EyK0E9PSxpPT QwOTY=

06-20 15:42:49.264 26369-26388/in.gappi.gappichat I/art: Background partial concurrent mark sweep GC freed 90062(4MB) AllocSpace objects, 20(540KB) LOS objects, 32% free, 33MB/49MB, paused 1.826ms total 137.089ms

06-20 15:42:49.564 26369-27615/in.gappi.gappichat D/SMACK: SENT (0): Yz1iaXdzLHI9QncuaHNmXV8lOGAyInQzTEJacn pkXmBPVCR3Rl90J0NEbFJIS000SVNleWRtSzRrUkU4b2t3PT0scD16UXpxR2xVeDArTnF1M1lERkxhN2 lubXphNnc9

06-20 15:42:49.654 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): dj1vdHAxTGtUVVZMZW1GdEVLOXdmZWlqQTdWK1 E9

06-20 15:42:49.654 26369-27615/in.gappi.gappichat D/SMACK: SENT (0): <stream:stream xmlns='jabber:client' to='gappi.in' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='9739937980@gappi.in' id='11040239326876846172' xml:lang='en'>

06-20 15:42:49.654 26369-27615/in.gappi.gappichat D/SMACK: SENT (0): 

06-20 15:42:49.734 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='5567512457513756075' from='gappi.in' version='1.0' xml:lang='en'>

06-20 15:42:49.734 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): <stream:features><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='PXc8x7mNN6cEIZgjsEishHW4d3E='/><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session><sm xmlns='urn:xmpp:sm:2'/><sm xmlns='urn:xmpp:sm:3'/><csi xmlns='urn:xmpp:csi:0'/></stream:features>

06-20 15:42:49.814 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): 

06-20 15:42:49.814 26369-26829/in.gappi.gappichat D/SMACK: User logged (0): 9739937980@gappi.in:5222/Smack

06-20 15:42:49.814 26369-27616/in.gappi.gappichat D/SMACK: RECV (0):

06-20 15:42:49.814 26369-26829/in.gappi.gappichat D/SMACK: XMPPConnection authenticated (0) and resumed

06-20 15:42:49.814 26369-27615/in.gappi.gappichat D/SMACK: SENT (0):

06-20 15:42:49.824 26369-26829/in.gappi.gappichat D/SMACK: XMPPConnection connected (0)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat D/GappiXmpp: ReconnectionFailed!

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: org.jivesoftware.smack.SmackException$AlreadyLoggedInException: Client is already logged in

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at org.jivesoftware.smack.tcp.XMPPTCPConnection.throwAlreadyLoggedInExceptionIfApp ropriate(XMPPTCPConnection.java:358)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java :452)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java :414)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at org.jivesoftware.smack.tcp.XMPPTCPConnection.connectInternal(XMPPTCPConnection. java:863)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at org.jivesoftware.smack.AbstractXMPPConnection.connect(AbstractXMPPConnection.ja va:364)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at org.jivesoftware.smack.ReconnectionManager$2.run(ReconnectionManager.java:241)

06-20 15:42:49.834 26369-26829/in.gappi.gappichat W/System.err: at java.lang.Thread.run(Thread.java:818)

At times 06-20 15:42:48.894 and 06-20 15:42:49.654 two different <stream/> stanzas are sent, which ultimately cause the exception later on. Is there any reason for such behavior? My client side xmpp code looks like this:

XMPPTCPConnectionConfiguration connConfig = XMPPTCPConnectionConfiguration.builder().setHost(serverAddress)
                .setPort(5222).setDebuggerEnabled(true).setSecurityMode(ConnectionConfiguration.SecurityMode.disabled)
                .setUsernameAndPassword(loginUser, passwordUser).setServiceName(serverAddress).build();
        XMPPTCPConnection.setUseStreamManagementDefault(true);
        XMPPTCPConnection.setUseStreamManagementResumptionDefault(true);
        connection = new XMPPTCPConnection(connConfig);
        connection.setUseStreamManagement(true);
        connection.setUseStreamManagementResumption(true);         XMPPConnectionListener connectionListener = new XMPPConnectionListener();
        connection.addConnectionListener(connectionListener);
        connection.setPacketReplyTimeout(10000);
        connection.addStanzaAcknowledgedListener(new StanzaListener() {
            @Override
            public void processPacket(Stanza packet) throws SmackException.NotConnectedException {
                String id = packet.getStanzaId();
                if (StringUtils.isNullOrEmpty(id)) {
                    return;
                }
                stanzaAcknowledged(id);
            }
        });         ReconnectionManager reconnectionManager = ReconnectionManager.getInstanceFor(connection);
        reconnectionManager.setEnabledPerDefault(true);
        reconnectionManager.enableAutomaticReconnection();
2

At times 06-20 15:42:48.894 and 06-20 15:42:49.654 two different <stream/> stanzas are sent, which ultimately cause the exception later on.
No, that is not what is causing the exception nor what the exception is about. You see two open tags, which is perfectly normal (See RFC 6120). The exception just tells you that ReconnectionManager couldn’t do its job because the connection already is authenticated.

3

The odd thing is that ReconnectionManager did do its job.

Here is the scenario. I turned off my device’s wifi, and this causes the ReconnectionManager to kick in. I turn wifi back on. After waiting for x seconds, ReconnectionManager tries and succeeds in reconnecting with the server. But it also throws the exception at the same time.

Is it because the xmpp server(ejabberd) is still waiting for my client to resume the connections and hasn’t closed the connection at its end?

4

No, you provided the relevant information in android - Smack: ReconnectionManager sends duplicate login requests while reconnecting - Stack Overflow

It’s a bug in Smack’s ReconnectionManager logic.

5

Created [SMACK-725] ReconnectionManager should handle AlreadyConnectedException and AlreadyLoggedInException not as failure - Ig…