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:
6-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><mechanism>SCRAM-SHA-1</mechanism><mechanism>PLAIN</mechanism><mechanism>X-OAUTH2</mechanism></mechanisms></stream:features>
06-20 15:42:48.994 26369-27615/in.gappi.gappichat D/SMACK: SENT (0): <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>biwsbj05NzM5OTM3OTgwLHI9QncuaHNmXV8lOGAyInQzTEJacnpkXmBPVCR3Rl90J0M=</auth>
06-20 15:42:49.094 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj1Cdy5oc2ZdXyU4YDIidDNMQlpyemReYE9UJHdGX3QnQ0RsUkhLTTRJU2V5ZG1LNGtSRThva3c9PSxzPUpJemJtbXAxaExzRFNZV042M1EyK0E9PSxpPTQwOTY=</challenge>
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): <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>Yz1iaXdzLHI9QncuaHNmXV8lOGAyInQzTEJacnpkXmBPVCR3Rl90J0NEbFJIS000SVNleWRtSzRrUkU4b2t3PT0scD16UXpxR2xVeDArTnF1M1lERkxhN2lubXphNnc9</response>
06-20 15:42:49.654 26369-27616/in.gappi.gappichat D/SMACK: RECV (0): <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1vdHAxTGtUVVZMZW1GdEVLOXdmZWlqQTdWK1E9</success>
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): <resume xmlns='urn:xmpp:sm:3' h='2' previd='g2gCbQAAAAVTbWFja2gDYgAABbpiAAbIgmIAAAIt'/>
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): <resumed xmlns='urn:xmpp:sm:3' h='2' previd='g2gCbQAAAAVTbWFja2gDYgAABbpiAAbIgmIAAAIt'/>
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): <r xmlns='urn:xmpp:sm:3'/>
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): <a xmlns='urn:xmpp:sm:3' h='2'/>
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.throwAlreadyLoggedInExceptionIfAppropriate(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.java: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();
At times 06-20 15:42:48.894 and 06-20 15:42:49.654 two different 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.