Smack 4.4.0: Smack BOSH throws NoResponseException during login process even all nonzas have been send and received properly

The following observation is based on aTalk with smack-4.4.0 and the applied patch below.

XMPPBOSHConnection.patch (4.9 KB)

Below are the aTalk debug log for aTalk initial BOSH connection login and ejabberd server debug log.
From ejabberd server debug log, the BOSH connection time between <auth/> and <challenge/> is immediate. However it seems that smack BoshClient is holding the <challenge/> nonza until it throws NoResponseException. Only then it sends the <response/> nonza. Actually the login is successful as from ejabberd debug log.

i.e. 17:42:19.170 <auth/> => 17:42:19.170 <challenge/>

============== aTalk BOSH connection login debug log =========
2019-10-21 17:42:17.737 1322-1898/org.atalk.android D/SMACK: SENT (1): 
    <body ver='1.8' wait='60' xmpp:version='1.0' rid='5336845303807709' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.org' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
019-10-21 17:42:18.047 1322-2358/org.atalk.android D/SMACK: RECV (1): 
    <body xmpp:version='1.0' authid='8221667300579328793' xmlns='http://jabber.org/protocol/httpbind' sid='b3512ad87ed03dcd93e969619afa52028f0d2943' wait='60' ver='1.11' polling='2' inactivity='30' hold='1' xmpp:restartlogic='true' requests='2' secure='true' maxpause='120' xmlns:xmpp='urn:xmpp:xbosh' xmlns:stream='http://etherx.jabber.org/streams' from='atalk.org'>
      <stream:features>
        <mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
          <mechanism>
            PLAIN
          </mechanism>
          <mechanism>
            SCRAM-SHA-1
          </mechanism>
          <mechanism>
            X-OAUTH2
          </mechanism>
        </mechanisms>
        <register xmlns='http://jabber.org/features/iq-register'/>
      </stream:features>
    </body>
2019-10-21 17:42:18.061 1322-2356/org.atalk.android D/SMACK: SENT (1): 
    <body rid='5336845303807710' sid='b3512ad87ed03dcd93e969619afa52028f0d2943' xmlns='http://jabber.org/protocol/httpbind'>
      <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
        biwsbj1zd29yZGZpc2gscj0mfk9YaFkvXysoejxsZHZxKE4jYihCVnQvX0phMVhvMQ==
      </auth>
    </body>

2019-10-21 17:42:28.065 1322-2356/org.atalk.android W/aTalk: [102552] org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished() Unhandled Exception
    java.lang.RuntimeException: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for successful SASL authentication
        at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:447)
        at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1633)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1165)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:998)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1727)
        at java.lang.Thread.run(Thread.java:764)
     Caused by: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for successful SASL authentication
        at org.jivesoftware.smack.sasl.SASLMechanism.throwExceptionIfRequired(SASLMechanism.java:339)
        at org.jivesoftware.smack.SASLAuthentication.authenticate(SASLAuthentication.java:211)
        at org.jivesoftware.smack.AbstractXMPPConnection.authenticate(AbstractXMPPConnection.java:861)
        at org.jivesoftware.smack.bosh.XMPPBOSHConnection.loginInternal(XMPPBOSHConnection.java:221)
        at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:646)
        at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:603)
        at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:444)
        at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1633) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1165) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:998) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1727) 
        at java.lang.Thread.run(Thread.java:764) 

2019-10-21 17:42:28.067 1322-2360/org.atalk.android D/SMACK: SENT (1): 
    <body rid='5336845303807711' ack='5336845303807709' sid='b3512ad87ed03dcd93e969619afa52028f0d2943' xmlns='http://jabber.org/protocol/httpbind'>
      <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        Yz1iaXdzLHI9Jn5PWGhZL18rKHo8bGR2cShOI2IoQlZ0L19KYTFYbzFNTWFoUnpVcXJHVTlvSjhSZ3hWdEZ3PT0scD1neFhFTEM1Q1Z4aHc2UXQ5ZWlkQVVvR1hPU0U9
      </response>
    </body>

2019-10-21 17:42:28.068 1322-2358/org.atalk.android D/SMACK: RECV (1): 
    <body xmlns='http://jabber.org/protocol/httpbind'>
      <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
       cj0mfk9YaFkvXysoejxsZHZxKE4jYihCVnQvX0phMVhvMU1NYWhSelVxckdVOW9KOFJneFZ0Rnc9PSxzPTVXVENHSnk1dk1FUWJpNmZWRVJ1S0E9PSxpPTQwOTY=
      </challenge>
    </body>
========== ejabberd debug log ============
2019-10-21 17:42:19.110 [debug] <0.749.0>@ejabberd_bosh:wait_for_session:317 got request:
** RequestID: 5336845303807709
** Request: {body,<<>>,[{to,<<"atalk.org">>},{ack,1},{<<"xml:lang">>,<<"en">>},{hold,1},{rid,5336845303807709},{'xmpp:version',<<"1.0">>},{wait,60},{ver,<<"1.8">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>}],[],193}
2019-10-21 17:42:19.111 [debug] <0.749.0>@ejabberd_bosh:do_reply:679 send reply:
** RequestID: 5336845303807709
** Reply: {body,<<>>,[{sid,<<"b3512ad87ed03dcd93e969619afa52028f0d2943">>},{wait,60},{ver,<<"1.11">>},{polling,2},{inactivity,30},{hold,1},{'xmpp:restartlogic',true},{requests,2},{secure,true},{maxpause,120},{'xmlns:xmpp',<<"urn:xmpp:xbosh">>},{'xmlns:stream',<<"http://etherx.jabber.org/streams">>},{from,<<"atalk.org">>}],[{xmlstreamstart,<<"stream:stream">>,[{<<"id">>,<<"8221667300579328793">>},{<<"version">>,<<"1.0">>},{<<"xml:lang">>,<<"en">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"from">>,<<"atalk.org">>},{<<"xmlns">>,<<"jabber:client">>}]},{xmlstreamelement,{xmlel,<<"stream:features">>,[],[{xmlel,<<"mechanisms">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>}],[{xmlel,<<"mechanism">>,[],[{xmlcdata,<<"PLAIN">>}]},{xmlel,<<"mechanism">>,[],[{xmlcdata,<<"SCRAM-SHA-1">>}]},{xmlel,<<"mechanism">>,[],[{xmlcdata,<<"X-OAUTH2">>}]}]},{xmlel,<<"register">>,[{<<"xmlns">>,<<"http://jabber.org/features/iq-register">>}],[]}]}}],0}
** To: {<0.748.0>,#Ref<0.1092676128.2977169409.258753>}
2019-10-21 17:42:19.169 [debug] <0.748.0>@mod_bosh:process:69 Incoming data: <<"<body rid='5336845303807710' sid='b3512ad87ed03dcd93e969619afa52028f0d2943' xmlns='http://jabber.org/protocol/httpbind'><auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>biwsbj1zd29yZGZpc2gscj0mfk9YaFkvXysoejxsZHZxKE4jYihCVnQvX0phMVhvMQ==</auth></body>">>
2019-10-21 17:42:19.170 [debug] <0.749.0>@ejabberd_bosh:active:384 got request:
** Request: {body,<<>>,[{sid,<<"b3512ad87ed03dcd93e969619afa52028f0d2943">>},{rid,5336845303807710}],[{xmlstreamelement,{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"SCRAM-SHA-1">>}],[{xmlcdata,<<"biwsbj1zd29yZGZpc2gscj0mfk9YaFkvXysoejxsZHZxKE4jYihCVnQvX0phMVhvMQ==">>}]}}],273}
2019-10-21 17:42:19.170 [debug] <0.749.0>@ejabberd_bosh:do_reply:679 send reply:
** RequestID: 5336845303807710
** Reply: {body,<<>>,[],[{xmlstreamelement,{xmlel,<<"challenge">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>}],[{xmlcdata,<<"cj0mfk9YaFkvXysoejxsZHZxKE4jYihCVnQvX0phMVhvMU1NYWhSelVxckdVOW9KOFJneFZ0Rnc9PSxzPTVXVENHSnk1dk1FUWJpNmZWRVJ1S0E9PSxpPTQwOTY=">>}]}}],0}
2019-10-21 17:42:29.291 [debug] <0.748.0>@mod_bosh:process:69 Incoming data: <<"<body rid='5336845303807711' ack='5336845303807709' sid='b3512ad87ed03dcd93e969619afa52028f0d2943' xmlns='http://jabber.org/protocol/httpbind'><response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>Yz1iaXdzLHI9Jn5PWGhZL18rKHo8bGR2cShOI2IoQlZ0L19KYTFYbzFNTWFoUnpVcXJHVTlvSjhSZ3hWdEZ3PT0scD1neFhFTEM1Q1Z4aHc2UXQ5ZWlkQVVvR1hPU0U9</response></body>">>
2019-10-21 17:42:29.293 [debug] <0.749.0>@ejabberd_bosh:do_reply:679 send reply:
** RequestID: 5336845303807711
** Reply: {body,<<>>,[],[{xmlstreamelement,{xmlel,<<"success">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>}],[{xmlcdata,
<<"dj1HMzViZ1J0SUZCY2dxNkYzeUxZWmpEWnYxakU9">>}]}}],0}```

Below is a finest capture of the BoshClient states during the ReconnectionManager re-connection process.

The detailed tracings reveal the following observations:

  1. In response to <stream:feature/>, BoshCleint sends the <auth/> nonza as required
  2. Server replies with <challenge/> nonza
  3. BoshClient actually responds with <response/> nonza
  4. However the <response/> nonza is being blocked at BOSHClient.send() when calling blockUntilSendable() method.
  5. It is found that isImmediatelySendable(msg) returns false; because both the RequestProcessor threads are still awaiting their responses. i.e. exchanges.size() == maxRequests
  6. It is found the two earlier exchanges although have been fulfilled, but the processExchange() does not execute the finally{} block as the whole process is being blocked at fireConnectionEstablished()
  7. i.e. @ XMPPBOSHConnection.connectionEvent(BOSHClientConnEvent connEvent) is being locked in synchronized (XMPPBOSHConnection.this).

Apparently the synchronized() is not being properly released in the last connection failure (see below)

======== XMPPBOSHConnection  =========
 public void connectionEvent(BOSHClientConnEvent connEvent) {
...
            finally {
                notified = true;
                synchronized (XMPPBOSHConnection.this) {
                    XMPPBOSHConnection.this.notifyAll();
                }
            }
...
}
======== BOSHClinet =========
private void processExchange(final int idx, final HTTPExchange exch) {
...
            if (cmParams == null) {
                cmParams = CMSessionParams.fromSessionInit(req, body);

                // Adjust number of request processors based on REQ value
                adjustRequestProcessorsPool();

                // The following call handles the lock. It's not an escape.
                fireConnectionEstablished();
            }
..
        finally {
            if (lock.isHeldByCurrentThread()) {
                try {
                    exchanges.remove(exch);
                    if (exchanges.isEmpty()) {
                        scheduleEmptyRequest(processPauseRequest(req));
                    }
                    notFull.signalAll();
                } finally {
                    lock.unlock();
                }
            }
        }
...
}
========= aTalk BOSH connection Failure ========
2019-10-23 12:20:05.731 2110-3554/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[swordfish@atalk.org/atalk] (1)) will reconnect in 0
2019-10-23 12:20:05.764 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 0 starting...
2019-10-23 12:20:05.767 2110-3554/org.atalk.android D/SMACK: SENT (1): 
    <body ver='1.8' wait='60' xmpp:version='1.0' rid='1626131178961980' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.org' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
2019-10-23 12:20:05.767 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 1626131178961980
2019-10-23 12:20:05.768 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 1626131178961980
2019-10-23 12:20:06.201 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 received response for RID: 1626131178961980 code: 200 ACK: null
2019-10-23 12:20:06.206 2110-3729/org.atalk.android D/SMACK: RECV (1): 
    <body xmpp:version='1.0' authid='15537854872994943732' xmlns='http://jabber.org/protocol/httpbind' sid='b43c757a74940fe10e67dbe32f9d950b01473f82' wait='60' ver='1.11' polling='2' inactivity='30' hold='1' xmpp:restartlogic='true' requests='2' secure='true' maxpause='120' xmlns:xmpp='urn:xmpp:xbosh' xmlns:stream='http://etherx.jabber.org/streams' from='atalk.org'>
      <stream:features>
        <mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
          <mechanism>
            PLAIN
          </mechanism>
          <mechanism>
            SCRAM-SHA-1
          </mechanism>
          <mechanism>
            X-OAUTH2
          </mechanism>
        </mechanisms>
        <register xmlns='http://jabber.org/features/iq-register'/>
      </stream:features>
    </body>
2019-10-23 12:20:06.210 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 1 starting...
2019-10-23 12:20:06.212 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...
2019-10-23 12:20:06.229 2110-3728/org.atalk.android D/SMACK: SENT (1): 
    <body rid='1626131178961981' sid='b43c757a74940fe10e67dbe32f9d950b01473f82' xmlns='http://jabber.org/protocol/httpbind'>
      <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
        biwsbj1zd29yZGZpc2gscj1tfUZ3UlcmNHdqfll3UUo3dHJ2aS4jP3NVTjlnKGlgRQ==
      </auth>
    </body>
2019-10-23 12:20:06.230 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 claimed: 1626131178961981
2019-10-23 12:20:06.231 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 is sending 1626131178961981
2019-10-23 12:20:06.283 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 received response for RID: 1626131178961981 code: 200 ACK: null
2019-10-23 12:20:16.238 2110-3728/org.atalk.android W/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished() Unhandled Exception
    java.lang.RuntimeException: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for successful SASL authentication
        at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:447)
        at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1638)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1170)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1733)
        at java.lang.Thread.run(Thread.java:764)
     Caused by: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for successful SASL authentication
        at org.jivesoftware.smack.sasl.SASLMechanism.throwExceptionIfRequired(SASLMechanism.java:339)
        at org.jivesoftware.smack.SASLAuthentication.authenticate(SASLAuthentication.java:211)
        at org.jivesoftware.smack.AbstractXMPPConnection.authenticate(AbstractXMPPConnection.java:861)
        at org.jivesoftware.smack.bosh.XMPPBOSHConnection.loginInternal(XMPPBOSHConnection.java:221)
        at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:646)
        at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:603)
        at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:444)
        at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1638) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1170) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1733) 
        at java.lang.Thread.run(Thread.java:764) 
2019-10-23 12:20:16.240 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...
2019-10-23 12:20:16.247 2110-3731/org.atalk.android D/SMACK: SENT (1): 
    <body rid='1626131178961982' ack='1626131178961980' sid='b43c757a74940fe10e67dbe32f9d950b01473f82' xmlns='http://jabber.org/protocol/httpbind'>
      <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        Yz1iaXdzLHI9bX1Gd1JXJjR3an5Zd1FKN3RydmkuIz9zVU45ZyhpYEVqek9sWlViRFh3TEt1bHloTlJFajBRPT0scD1Gb1JUeTYyRVV2QThoeXBkeDNMYjBLY2draDg9
      </response>
    </body>
2019-10-23 12:20:16.250 2110-3729/org.atalk.android D/SMACK: RECV (1): 
    <body xmlns='http://jabber.org/protocol/httpbind'>
      <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        cj1tfUZ3UlcmNHdqfll3UUo3dHJ2aS4jP3NVTjlnKGlgRWp6T2xaVWJEWHdMS3VseWhOUkVqMFE9PSxzPTVXVENHSnk1dk1FUWJpNmZWRVJ1S0E9PSxpPTQwOTY=
      </challenge>
    </body>
2019-10-23 12:20:16.250 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 1626131178961982
2019-10-23 12:20:16.252 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 1626131178961982
2019-10-23 12:20:16.257 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...
2019-10-23 12:20:16.306 2110-3554/org.atalk.android D/SMACK: SENT (1): 
    <body rid='1626131178961983' ack='1626131178961981' sid='b43c757a74940fe10e67dbe32f9d950b01473f82' xmlns='http://jabber.org/protocol/httpbind'>
      <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
        biwsbj1zd29yZGZpc2gscj0tUzUqezA5NlF6UHBjPlA8ezB2LzJCXlZXL2ErU258Xg==
      </auth>
    </body>
2019-10-23 12:20:16.309 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 claimed: 1626131178961983
2019-10-23 12:20:16.314 2110-3731/org.atalk.android V/aTalk: [110792] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 is sending 1626131178961983
2019-10-23 12:20:16.317 2110-3731/org.atalk.android I/System.out: Thread-110792(ApacheHTTPLog):isSBSettingEnabled false
2019-10-23 12:20:16.369 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 received response for RID: 1626131178961982 code: 200 ACK: null
2019-10-23 12:20:16.372 2110-3729/org.atalk.android D/SMACK: RECV (1): 
    <body xmlns='http://jabber.org/protocol/httpbind'>
      <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        dj1kUVJpZGFPelVXRCtFR05Td1ptWE1HN2d3L3M9
      </success>
    </body>
2019-10-23 12:20:16.374 2110-3728/org.atalk.android V/aTalk: [110790] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...

==========================================================================
====================== Initial XMPPBOSHConnection Login Failure ==================
The ReconnectionManager get triggered by the initial BOSHConnection failure; in all cases at a very specific code exec location. i.e. OMEMO published of prekeys.
It appears that the XMPPBOSHConnection get abruptly disconnected half way through sending of prekeys stanza. So far it is observed that the failure is 100% when the connection is made via Mobile network. And in almost all cases, it is OK when connection is made via WiFi.
I am still not sure what is causing this.

I am suspecting the problem is due to andorid-OS i.e. strictmode-java-lang-throwable-untagged-socket-detected, but yet to prove the case. As I am still unable to find the location to insert
TrafficStats.setThreadStatsTag(THREAD_ID); to make thing works.

Appreciate if anyone can offer some help on this.

2019-10-23 14:30:31.107 25961-26290/org.atalk.android V/aTalk: [111482] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 3268214467642508
2019-10-23 14:30:31.113 25961-26310/org.atalk.android D/SMACK: SENT (0): 
    <body rid='3268214467642508' ack='3268214467642506' sid='b8fc641bfa2989a6d25ed0fac0fb8a03aa1a5f41' xmlns='http://jabber.org/protocol/httpbind'>
      <iq xmlns='jabber:client' id='1DPNK-83' type='set'>
        <pubsub xmlns='http://jabber.org/protocol/pubsub'>
          <publish node='eu.siacs.conversations.axolotl.bundles:1175061843'>
            <item xmlns='http://jabber.org/protocol/pubsub'>
              <bundle xmlns='eu.siacs.conversations.axolotl'>
                <signedPreKeyPublic signedPreKeyId='7'>
                  BYO0TfZBS5Y309M6oYcWqc6mtukZoD8Vou0qRg4WzdRT
                </signedPreKeyPublic>
...
        <preKeyPublic preKeyId='24'>
                    BRS1eE/9pfADbcjzdpYC7

2019-10-23 14:30:31.113 25961-26310/org.atalk.android D/SMACK: SENT (0): 
2019-10-23 14:30:31.114 25961-26290/org.atalk.android V/aTalk: [111482] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 3268214467642508
2019-10-23 14:30:31.147 25961-26300/org.atalk.android V/aTalk: [111487] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 received response for RID: 3268214467642507 code: 200 ACK: null
2019-10-23 14:30:31.218 25961-26290/org.atalk.android V/aTalk: [111482] org.igniterealtime.jbosh.BOSHClient.processExchange() Could not obtain response
    org.igniterealtime.jbosh.BOSHException: Could not parse body:
    <?xml version='1.0'?>
    <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
    <h1>400 Bad Request</h1>
        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:246)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:192)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1127)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1744)
        at java.lang.Thread.run(Thread.java:764)
     Caused by: java.lang.IllegalStateException: Root element was not 'body' in the 'http://jabber.org/protocol/httpbind' namespace.  (Was 'h1' 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:246) 
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:192) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1127) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1744) 
        at java.lang.Thread.run(Thread.java:764) 
     Caused by: org.igniterealtime.jbosh.BOSHException: Could not parse body:
    <?xml version='1.0'?>
    <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
    <h1>400 Bad Request</h1>
        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:246)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:192)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1127)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1744)
        	... 1 more
     Caused by: java.lang.IllegalStateException: Root element was not 'body' in the 'http://jabber.org/protocol/httpbind' namespace.  (Was 'h1' in '')
        at org.igniterealtime.jbosh.BodyParserXmlPull.parse(BodyParserXmlPull.java:98)
        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:246) 
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:192) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1127) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1744) 
2019-10-23 14:30:31.248 25961-26290/org.atalk.android V/aTalk: [111482] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread exiting: 0

The attached patch fixes two more problems:

  1. The BOSH request and response nonza are displayed in proper time sequence
  2. The ReconnectionManager re-connection process is now working

XMPPBOSHConnection.patch (7.3 KB)

Now need to investigate why the connection gets disconnected abruptly with mobile network;
Also there is new problem that XMPPBOSHConnection is not working at all in Note-5 (API-21)

========== aTalk BOSHConnection failure log on android 5.0 (API-21) ===========

10-24 13:27:58.396 31990-32635/org.atalk.android V/aTalk: [2] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 0 starting...
10-24 13:27:58.396 31990-32635/org.atalk.android V/aTalk: [2] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...
10-24 13:27:58.416 31990-32635/org.atalk.android V/aTalk: [2] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 7222157928960409
10-24 13:27:58.416 31990-32635/org.atalk.android V/aTalk: [2] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 7222157928960409
10-24 13:27:58.416 31990-32618/org.atalk.android D/SMACK: SENT (0): 
    <body wait='60' xmpp:version='1.0' ack='1' xmlns:xmpp='urn:xmpp:xbosh' ver='1.8' xml:lang='en' rid='7222157928960409' to='atalk.org' hold='1' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
10-24 13:27:58.506 31990-32635/org.atalk.android V/aTalk: [2] org.igniterealtime.jbosh.BOSHClient.processExchange() Could not obtain response
    org.igniterealtime.jbosh.BOSHException: Could not obtain response
        at org.igniterealtime.jbosh.ApacheHTTPResponse.awaitResponse(ApacheHTTPResponse.java:251)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:192)
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1127)
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003)
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105)
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1742)
        at java.lang.Thread.run(Thread.java:818)
     Caused by: javax.net.ssl.SSLPeerUnverifiedException: No peer certificate
        at com.android.org.conscrypt.SSLNullSession.getPeerCertificates(SSLNullSession.java:104)
        at org.apache.http.conn.ssl.AbstractVerifier.verify(AbstractVerifier.java:93)
        at org.apache.http.conn.ssl.SSLSocketFactory.createSocket(SSLSocketFactory.java:388)
        at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:214)
        at org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:167)
        at org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:125)
        at org.apache.http.impl.client.DefaultRequestDirector.executeOriginal(DefaultRequestDirector.java:1287)
        at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:699)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:575)
        at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:491)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.awaitResponse(ApacheHTTPResponse.java:235)
        at org.igniterealtime.jbosh.ApacheHTTPResponse.getBody(ApacheHTTPResponse.java:192) 
        at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1127) 
        at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1003) 
        at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:105) 
        at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1742) 
        at java.lang.Thread.run(Thread.java:818)

Please close this discussion thread as the mentioned issue in the subject is closed. Refer to the following links for further discussion on XMPPBOSHConnection.

Smack 4.4.0: Smack BOSH receives “400 Bad Request’ from server when sending large amount of data via mobile network

Smack 4.4.0: Smack BOSH Connection host TLS certification verification process

This topic was automatically closed 100 days after the last reply. New replies are no longer allowed.