powered by Jive Software

Smack Android XMPP BOSH Reconnection fails with HTTP ERROR: 404 Invalid SID value


#1

I have an Android application where I’m connecting to an XMPP server using BOSH. I created a bound and started service that runs in its own thread and does all connection, disconnection etc.

Here’s the skeleton for the service:

public class XMPPConnectionService extends Service {
@Override
public void onCreate() {
    super.onCreate();
    ...

}
public class XMPPConnectionServiceBinder extends Binder {
    ...
}


@Override
public int onStartCommand(Intent intent, int flags, int startId) {
    ...
    return START_STICKY;
}


private void initializeXMPPConnection() {
    if (xmppConnection != null && isConnected && isAuthenticated)
        return;
    if(xmppConnection == null) {
        System.out.println(TAG + " First time connnection to xmpp ");
        try {
            configurationBuilder = BOSHConfiguration.builder()
                    .setUsernameAndPassword(jabberId, proxyToken)
                    .setCustomSSLContext(getCustomSSLContext())
                    .setXmppDomain("mydomain")
                    .setFile("/http-bind/")
                    .setHost(Utility.getHostForChat())
                    .setPort(ServerConstants.PORT_FOR_CHAT)
                    .setResource("Smack")
                    .setSecurityMode(ConnectionConfiguration.SecurityMode.disabled)
                    .setUseHttps(true)
                    .setSendPresence(true)
                    .build();
        } catch (XmppStringprepException xse) {
            xse.printStackTrace();
            Logger.logException(xse.getMessage(), xse);
        }
        xmppConnection = new XMPPBOSHConnection(configurationBuilder);
    }

    try {
        System.out.println(TAG + " connecting to XMPP");
        xmppConnection.connect();
        xmppConnection.login();

    } catch (SmackException | IOException | XMPPException | InterruptedException sixi) {
        sixi.printStackTrace();
        Logger.logException(sixi.getMessage(), sixi);

    }
    if(reconnectionManager== null)
        reconnectionManager = ReconnectionManager.getInstanceFor(xmppConnection);
    reconnectionManager.enableAutomaticReconnection();

    if(offlineMessageManager == null)
        offlineMessageManager = new OfflineMessageManager(xmppConnection);

    isConnected = true;
    isAuthenticated = true;


}


@Override
public void onDestroy() {
    super.onDestroy();
    Logger.logDebug(TAG, "Closing and destroying XMPP connection");
    System.out.println("Closing xmpp connection.");
    if(xmppConnection!=null){
        reconnectionManager.disableAutomaticReconnection();
        xmppConnection.disconnect();
        isConnected = false;
        isAuthenticated = false;

    }

}

}

The service is started via a call to startService and ended on activity’s logout via a call to stopService. Everything works perfectly when I log into the application the first time. I’m able to chat, check offline messages etc. I then proceed to logging out from the application and that too works as expected. The logout code calls stopService as below:

protected void logout() {        
    Intent stopXMPPConnectionService = new Intent(MyApplication.getAppContext(), XMPPConnectionService.class);
    stopXMPPConnectionService.setAction(XMPPConnectionService.ACTION_XMPP_DISCONNECT);
    stopService(stopXMPPConnectionService);        
    ...
}

This works fine too. I can see from the logs the onDestroy method of the service being invoked and a XMPP message being sent to the server to set the status as unavailable. I can see the following trace messages in logcat when the user logs out from the application:

10-27 13:07:21.772 6922-6922/io.xxxxx.user I/System.out: Closing xmpp connection.
10-27 13:07:21.773 6922-6922/io.xxxxx.user D/SMACK: XMPPConnection closed (XMPPBOSHConnection[alphauser1\40xxxxx.io@inuka/Smack] (0))

10-27 13:07:21.951 6922-7269/io.inuka.user W/Roster: Roster not loaded while processing Presence Stanza [to=alphauser1\40xxxxx.io@inuka/Smack,from=alphauser1\40xxxxx.io@xxxxx/Smack,id=9V2W6-8,type=unavailable,]

The problem comes when I try to log into the application again. When the XMPP service is started again via a call to the startService method, I see the following error in logcat:

10-27 13:10:54.881 6922-7349/io.xxxx.user I/System.out: io.xxxx.user.service.XMPPConnectionService First time connnection to xmpp 
10-27 13:10:54.884 6922-7349/io.xxxx.user I/System.out: io.xxxx.user.service.XMPPConnectionService connecting to XMPP
10-27 13:10:54.887 6922-7349/io.xxxx.user I/BOSHClient: Starting with 1 request processors
10-27 13:10:55.555 6922-7352/io.xxxx.user D/SMACK: RECV (1): <body xmlns="http://jabber.org/protocol/httpbind" xmlns:stream="http://etherx.jabber.org/streams" from="xxxx" authid="5fpgkrm94h" sid="5fpgkrm94h" secure="true" requests="200" inactivity="600" polling="300" wait="60" hold="1" ack="4678127962453164" maxpause="300" ver="1.6"><stream:features><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism><mechanism>EXTERNAL</mechanism></mechanisms><register xmlns="http://jabber.org/features/iq-register"/><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"><optional/></session></stream:features></body>
10-27 13:10:56.357 6922-7352/io.xxxx.user D/SMACK: RECV (1): <body xmlns='http://jabber.org/protocol/httpbind' ack='4678127962453165'><success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/></body>
10-27 13:10:56.526 6922-7352/io.xxxx.user D/SMACK: RECV (1): <body xmlns="http://jabber.org/protocol/httpbind" xmlns:stream="http://etherx.jabber.org/streams"><stream:features><register xmlns="http://jabber.org/features/iq-register"/><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"><optional/></session></stream:features></body>
10-27 13:10:57.049 6922-7349/io.xxxx.user D/SMACK: User logged (1): alphauser1\40xxxx.io@xxxx:0/Smack
10-27 13:10:57.049 6922-7352/io.xxxx.user D/SMACK: RECV (1): <body xmlns='http://jabber.org/protocol/httpbind' ack='4678127962453167'><iq type="result" id="9V2W6-12" to="xxxx/5fpgkrm94h" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>alphauser1\40xxxx.io@xxxx/Smack</jid></bind></iq></body>
10-27 13:10:57.050 6922-7349/io.xxxx.user D/SMACK: XMPPConnection authenticated (XMPPBOSHConnection[alphauser1\40xxxx.io@xxxx/Smack] (1))
10-27 13:10:57.225 6922-7352/io.xxxx.user D/SMACK: RECV (1): <body xmlns='http://jabber.org/protocol/httpbind' ack='4678127962453168'><iq type="result" id="9V2W6-14" to="alphauser1\40xxxx.io@xxxx/Smack" xmlns="jabber:client"><query xmlns="jabber:iq:roster"/></iq></body>
10-27 13:10:57.326 6922-7076/io.xxxx.user W/AbstractXMPPConnection: Connection XMPPBOSHConnection[alphauser1\40xxxx.io@xxxx/Smack] (0) closed with error
    org.igniterealtime.jbosh.BOSHException: Could not parse body:
    <html>
    <head>
    <meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/>
    <title>Error 404 </title>
    </head>
    <body>
    <h2>HTTP ERROR: 404</h2>
    <p>Problem accessing /http-bind/. Reason:
    <pre>    Invalid SID value.</pre></p>
    <hr /><i><small>Powered by Jetty://</small></i>
    </body>
    </html>
    
        at org.igniterealtime.jbosh.BodyParserXmlPull.parse(BodyParserXmlPull.java:132)
        at org.igniterealtime.jbosh.StaticBody.fromString(StaticBody.java:114)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.awaitResponse(ApacheHTTPResponse.java:241)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:187)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1114)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:990)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1719)
        at java.lang.Thread.run(Thread.java:818)
     Caused by: java.lang.IllegalStateException: Root element was not 'body' in the 'http://jabber.org/protocol/httpbind' namespace.  (Was 'html' in '')
        at org.igniterealtime.jbosh.BodyParserXmlPull.parse(BodyParserXmlPull.java:98)
        at org.igniterealtime.jbosh.StaticBody.fromString(StaticBody.java:114) 
        at org.igniterealtime.jbosh.ApacheHTTPResponse.awaitResponse(ApacheHTTPResponse.java:241) 
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:187) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1114) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:990) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1719) 
        at java.lang.Thread.run(Thread.java:818) 
10-27 13:10:57.326 6922-7076/io.xxxx.user D/SMACK: XMPPConnection closed due to an exception (XMPPBOSHConnection[alphauser1\40xxxx.io@xxxx/Smack] (0))
    org.igniterealtime.jbosh.BOSHException: Could not parse body:
    <html>
    <head>
    <meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/>
    <title>Error 404 </title>
    </head>
    <body>
    <h2>HTTP ERROR: 404</h2>
    <p>Problem accessing /http-bind/. Reason:
    <pre>    Invalid SID value.</pre></p>
    <hr /><i><small>Powered by Jetty://</small></i>
    </body>
    </html>
    
        at org.igniterealtime.jbosh.BodyParserXmlPull.parse(BodyParserXmlPull.java:132)
        at org.igniterealtime.jbosh.StaticBody.fromString(StaticBody.java:114)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.awaitResponse(ApacheHTTPResponse.java:241)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:187)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1114)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:990)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1719)
        at java.lang.Thread.run(Thread.java:818)
     Caused by: java.lang.IllegalStateException: Root element was not 'body' in the 'http://jabber.org/protocol/httpbind' namespace.  (Was 'html' in '')
        at org.igniterealtime.jbosh.BodyParserXmlPull.parse(BodyParserXmlPull.java:98)
        at org.igniterealtime.jbosh.StaticBody.fromString(StaticBody.java:114) 
        at org.igniterealtime.jbosh.ApacheHTTPResponse.awaitResponse(ApacheHTTPResponse.java:241) 
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:187) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1114) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:990) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1719) 
        at java.lang.Thread.run(Thread.java:818) 
10-27 13:10:57.389 6922-7206/io.xxxx.user W/art: No such thread id for suspend: 231
10-27 13:10:57.418 6922-7245/io.xxxx.user W/art: No such thread id for suspend: 264
10-27 13:10:59.225 1259-1326/? D/hwcomposer: hw_composer sent 555 syncs in 60s

Once the error is thrown the connection is automatically established but it causes a delay in app initialization. The code works fine on the very first connection i.e. when the app is launched the very first time or I kill the app using “fore stop” from android system settings. But when I logout and login again, I get the above error.
I have a suspicion that somehow the connection is not being closed cleanly - not sure how to do it properly.

Any helps, tips, pointers will be greatly appreciated.


#2

It appears what you are seeing is Smack being unable to parse a HTTP 404 response by the BOSH endpoint.


#3

What you say does make sense - it seems like I’m getting a HTML formatted page and BoSH client is trying to parse it as HTML.
But why am I getting a 404 in first place? My guess is the SID is not being reset properly when the connection has been closed and the either the server or the client is using the previous SID?
I don’t really know the internals well, but just a guess…Any pointers on troubleshooting this further?


#4

Cross-posted to stackoverflow: https://stackoverflow.com/q/53021137/194894