Smack-bosh 4.4.8 fails reconnect attempt when the network connection changed

aTalk client succesful login with BOSH connection. However when there is a change in the network connection e.g. from wifi to mobile. Bosh client starts the reconnection, but the attempt failed. All subsequent reconnect attempts always failed, until user performs a manual login from the aTalk main menu.

The failure is NoResponseException while waiting for successful SASL authentication; but the problem seems to be that smack does not response to the received ‘challenge’ stanza; until after the NoResponseException event occured.

Following is the logcat captured on aTalk. Any recommendation?

04:55:24.516  V  [1269] 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:1123)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
Caused by: java.net.SocketException: Software caused connection abort
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:119)
	at java.net.SocketInputStream.read(SocketInputStream.java:176)
	at java.net.SocketInputStream.read(SocketInputStream.java:144)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readFromSocket(ConscryptEngineSocket.java:945)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.processDataFromSocket(ConscryptEngineSocket.java:909)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readUntilDataAvailable(ConscryptEngineSocket.java:824)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.read(ConscryptEngineSocket.java:797)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:108)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:196)
	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:88)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:179)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:185)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:240)
	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:264)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:284)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:126)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:442)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:560)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:492)
	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:1123) 
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999) 
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728) 
	at java.lang.Thread.run(Thread.java:920) 
04:55:24.579  V  [1267] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread exiting: 0
04:55:24.612  W  [1291] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0) closed with error
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:1123)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
Caused by: java.net.SocketException: Software caused connection abort
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:119)
	at java.net.SocketInputStream.read(SocketInputStream.java:176)
	at java.net.SocketInputStream.read(SocketInputStream.java:144)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readFromSocket(ConscryptEngineSocket.java:945)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.processDataFromSocket(ConscryptEngineSocket.java:909)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readUntilDataAvailable(ConscryptEngineSocket.java:824)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.read(ConscryptEngineSocket.java:797)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:108)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:196)
	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:88)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:179)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:185)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:240)
	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:264)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:284)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:126)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:442)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:560)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:492)
	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:1123) 
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999) 
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728) 
	at java.lang.Thread.run(Thread.java:920) 
04:55:24.612  V  [1269] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread exiting: 1
04:55:24.615  E  ### Connection closed on error (StreamErrorException: false) during XMPPConnection: Could not obtain response
04:55:24.617  D  The provider state changed: RegistrationState = Unregistered => RegistrationState = Reconnecting. Reason: Could not obtain response
04:55:24.660  D  XMPPConnection closed due to an exception (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0))
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:1123)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
Caused by: java.net.SocketException: Software caused connection abort
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:119)
	at java.net.SocketInputStream.read(SocketInputStream.java:176)
	at java.net.SocketInputStream.read(SocketInputStream.java:144)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readFromSocket(ConscryptEngineSocket.java:945)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.processDataFromSocket(ConscryptEngineSocket.java:909)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.readUntilDataAvailable(ConscryptEngineSocket.java:824)
	at com.android.org.conscrypt.ConscryptEngineSocket$SSLInputStream.read(ConscryptEngineSocket.java:797)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:108)
	at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:196)
	at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:88)
	at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:179)
	at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:185)
	at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:240)
	at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:264)
	at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:284)
	at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:126)
	at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:442)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:560)
	at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:492)
	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:1123) 
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999) 
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728) 
	at java.lang.Thread.run(Thread.java:920) 
04:55:25.665  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 6
04:55:26.669  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 5
04:55:27.674  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 4
04:55:28.678  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 3
04:55:29.682  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 2
04:55:30.686  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 1
04:55:31.691  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 0
04:55:31.692  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 0
04:55:31.714  V  [1292] org.igniterealtime.jbosh.ServiceLib.attemptLoad() Attempting service load: org.igniterealtime.jbosh.ApacheHTTPSender
04:55:31.719  V  [1292] org.igniterealtime.jbosh.ServiceLib.loadService() Selected HTTPSender implementation: org.igniterealtime.jbosh.ApacheHTTPSender
04:55:31.733  I  [1292] org.igniterealtime.jbosh.BOSHClient.init() Starting with 1 request processors
04:55:31.744  V  [1295] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 0 starting...
04:55:31.746  D  SENT (0): 
<body ver='1.8' wait='60' xmpp:version='1.0' rid='166299451011857' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.sytes.net' xmlns='http://jabber.org/protocol/httpbind'>
</body>
04:55:31.749  V  [1295] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 166299451011857
04:55:31.753  V  [1295] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 166299451011857
04:55:32.465  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start tag: body
04:55:32.468  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start element: 
04:55:32.470  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     prefix: 
04:55:32.473  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     URI: http://jabber.org/protocol/httpbind
04:55:32.476  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     local: body
04:55:32.478  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {urn:xmpp:xbosh}version = '1.0'
04:55:32.481  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}authid = '6393374966058231865'
04:55:32.484  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}sid = 'e834902bd095e9f4f1c9d32add9edb7ea7bec62f'
04:55:32.487  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}wait = '60'
04:55:32.489  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}ver = '1.11'
04:55:32.492  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}polling = '2'
04:55:32.495  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}inactivity = '30'
04:55:32.497  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}hold = '1'
04:55:32.500  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {urn:xmpp:xbosh}restartlogic = 'true'
04:55:32.503  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}requests = '2'
04:55:32.505  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}secure = 'true'
04:55:32.508  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}maxpause = '120'
04:55:32.511  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}from = 'atalk.sytes.net'
04:55:32.514  V  [1295] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 received response for RID: 166299451011857 code: 200 ACK: null
04:55:32.515  D  RECV (0): 
<body xmpp:version='1.0' authid='6393374966058231865' xmlns='http://jabber.org/protocol/httpbind' sid='e834902bd095e9f4f1c9d32add9edb7ea7bec62f' 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.sytes.net'>
  <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>
04:55:32.523  V  [1297] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 1 starting...
04:55:32.527  V  [1297] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...
04:55:32.555  D  SENT (0): 
<body rid='166299451011858' sid='e834902bd095e9f4f1c9d32add9edb7ea7bec62f' xmlns='http://jabber.org/protocol/httpbind'>
  <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
    bixhPXN3b3JkZmlzaEBhdGFsay5zeXRlcy5uZXQsbj1zd29yZGZpc2gscj0qRUF4R290SU4qOUBDQTApOkJJJW97ZCk3fk4wbHcoOw==
  </auth>
</body>
04:55:32.556  V  [1297] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 claimed: 166299451011858
04:55:32.559  V  [1297] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 is sending 166299451011858
04:55:32.604  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start tag: body
04:55:32.607  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start element: 
04:55:32.610  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     prefix: 
04:55:32.612  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     URI: http://jabber.org/protocol/httpbind
04:55:32.615  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     local: body
04:55:32.618  V  [1297] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 received response for RID: 166299451011858 code: 200 ACK: null
04:55:32.619  D  RECV (0): 
<body xmlns='http://jabber.org/protocol/httpbind'>
  <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
    cj0qRUF4R290SU4qOUBDQTApOkJJJW97ZCk3fk4wbHcoO1ZWNDlsQnhHS1U1MmppR1lOaFdCeUE9PSxzPTVXVENHSnk1dk1FUWJpNmZWRVJ1S0E9PSxpPTQwOTY=
  </challenge>
</body>
04:55:42.560  W  Long monitor contention with owner RequestProcessor[238432985]: Receive thread 0 (26282) at void org.jivesoftware.smack.AbstractXMPPConnection.login(java.lang.CharSequence, java.lang.String, org.jxmpp.jid.parts.Resourcepart)(AbstractXMPPConnection.java:628) waiters=1 in void java.lang.Object.wait(long, int) for 811ms
04:55:42.564  W  Long monitor contention with owner Smack DefaultReactor Thread #0 (25821) at int sun.nio.ch.SelectorImpl.lockAndDoSelect(long)(SelectorImpl.java:86) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 49.945s
04:55:42.574  W  [1295] 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 [XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)]
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:458)
	at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1634)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1166)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
Caused by: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for successful SASL authentication [XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)]
	at org.jivesoftware.smack.sasl.SASLMechanism.throwExceptionIfRequired(SASLMechanism.java:343)
	at org.jivesoftware.smack.SASLAuthentication.authenticate(SASLAuthentication.java:212)
	at org.jivesoftware.smack.AbstractXMPPConnection.authenticate(AbstractXMPPConnection.java:896)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection.loginInternal(XMPPBOSHConnection.java:231)
	at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:637)
	at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:594)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:455)
	at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1634) 
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1166) 
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999) 
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100) 
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728) 
	at java.lang.Thread.run(Thread.java:920) 
04:55:42.580  V  [1295] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...
04:55:42.587  D  XMPPConnection connected (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0))
04:55:42.591  D  SENT (0): 
<body rid='166299451011859' ack='166299451011857' sid='e834902bd095e9f4f1c9d32add9edb7ea7bec62f' xmlns='http://jabber.org/protocol/httpbind'>
  <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
    Yz1iaXhoUFhOM2IzSmtabWx6YUVCaGRHRnNheTV6ZVhSbGN5NXVaWFFzLHI9KkVBeEdvdElOKjlAQ0EwKTpCSSVve2QpN35OMGx3KDtWVjQ5bEJ4R0tVNTJqaUdZTmhXQnlBPT0scD1zNXhQZTVxTFJaeXF4N3o5aFgrK1N1Z1VyK3M9
  </response>
</body>
04:55:42.595  V  [1295] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 166299451011859
04:55:42.607  V  [1295] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 166299451011859
04:55:42.623  V  [1297] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...
04:55:42.666  D  SENT (0): 
<body rid='166299451011860' ack='166299451011858' sid='e834902bd095e9f4f1c9d32add9edb7ea7bec62f' xmlns='http://jabber.org/protocol/httpbind'>
  <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
    bixhPXN3b3JkZmlzaEBhdGFsay5zeXRlcy5uZXQsbj1zd29yZGZpc2gscj1jJig3T3EhUH5qai4rcEk7S2p3fkgjNDJrNnUqZn4pUg==
  </auth>
</body>
04:55:42.672  V  [1297] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 claimed: 166299451011860
04:55:42.682  V  [1297] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 is sending 166299451011860
04:55:42.694  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start tag: body
04:55:42.699  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start element: 
04:55:42.705  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     prefix: 
04:55:42.712  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     URI: http://jabber.org/protocol/httpbind
04:55:42.718  V  [1295] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     local: body
04:55:42.721  V  [1295] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 received response for RID: 166299451011859 code: 200 ACK: null
04:55:42.722  D  RECV (0): 
<body xmlns='http://jabber.org/protocol/httpbind'>
  <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
    dj1nZExYcXV2YmFjdUxUcXhianlXQzd2MlpyejA9
  </success>
</body>
04:55:42.729  D  Reconnection failed due to an exception (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0))
org.jivesoftware.smack.SmackException$SmackSaslException: Server random ASCII is null
	at org.jivesoftware.smack.sasl.core.ScramMechanism.evaluateChallenge(ScramMechanism.java:128)
	at org.jivesoftware.smack.sasl.SASLMechanism.challengeReceived(SASLMechanism.java:241)
	at org.jivesoftware.smack.SASLAuthentication.challengeReceived(SASLAuthentication.java:246)
	at org.jivesoftware.smack.SASLAuthentication.authenticated(SASLAuthentication.java:265)
	at org.jivesoftware.smack.AbstractXMPPConnection.lambda$new$1$org-jivesoftware-smack-AbstractXMPPConnection(AbstractXMPPConnection.java:401)
	at org.jivesoftware.smack.AbstractXMPPConnection$$ExternalSyntheticLambda2.accept(D8$$SyntheticClass:0)
	at org.jivesoftware.smack.NonzaCallback$ClassAndConsumer.accept(NonzaCallback.java:177)
	at org.jivesoftware.smack.NonzaCallback$ClassAndConsumer.access$200(NonzaCallback.java:166)
	at org.jivesoftware.smack.NonzaCallback.onNonzaReceived(NonzaCallback.java:46)
	at org.jivesoftware.smack.AbstractXMPPConnection.parseAndProcessNonza(AbstractXMPPConnection.java:1439)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection.access$1800(XMPPBOSHConnection.java:69)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHPacketReader.responseReceived(XMPPBOSHConnection.java:538)
	at org.igniterealtime.jbosh.BOSHClient.fireResponseReceived(BOSHClient.java:1610)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1145)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
04:55:42.731  V  [1295] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...
04:55:42.740  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start tag: body
04:55:42.743  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start element: 
04:55:42.746  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     prefix: 
04:55:42.748  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     URI: http://jabber.org/protocol/httpbind
04:55:42.750  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     local: body
04:55:42.753  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {urn:xmpp:xbosh}version = '1.0'
04:55:42.755  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}authid = '9899726112254501808'
04:55:42.758  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}type = 'terminate'
04:55:42.761  V  [1297] org.igniterealtime.jbosh.BodyParserXmlPull.parse()         Attribute: {http://jabber.org/protocol/httpbind}condition = 'remote-stream-error'
04:55:42.764  V  [1297] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 received response for RID: 166299451011860 code: 200 ACK: null
04:55:42.765  D  RECV (0): 
<body xmpp:version='1.0' authid='9899726112254501808' type='terminate' condition='remote-stream-error' xmlns:stream='http://etherx.jabber.org/streams' xmlns='http://jabber.org/protocol/httpbind' xmlns:xmpp='urn:xmpp:xbosh'>
  <stream:error>
    <invalid-xml xmlns='urn:ietf:params:xml:ns:xmpp-streams'/>
  </stream:error>
</body>
04:55:42.776  W  [1299] org.jivesoftware.smack.AbstractXMPPConnection.callConnectionClosedOnErrorListener() Connection XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0) closed with error
java.lang.NullPointerException: Attempt to invoke virtual method 'java.lang.String java.lang.String.toUpperCase(java.util.Locale)' on a null object reference
	at org.jivesoftware.smack.packet.StanzaError$Type.fromString(StanzaError.java:334)
	at org.jivesoftware.smack.util.PacketParserUtils.parseError(PacketParserUtils.java:779)
	at org.jivesoftware.smack.util.PacketParserUtils.parseError(PacketParserUtils.java:758)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHPacketReader.responseReceived(XMPPBOSHConnection.java:534)
	at org.igniterealtime.jbosh.BOSHClient.fireResponseReceived(BOSHClient.java:1610)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1145)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
04:55:42.778  E  ### Connection closed on error (StreamErrorException: false) during XMPPConnection: Attempt to invoke virtual method 'java.lang.String java.lang.String.toUpperCase(java.util.Locale)' on a null object reference
04:55:42.779  V  [1297] org.igniterealtime.jbosh.BOSHClient.processExchange() Could not process response
org.igniterealtime.jbosh.BOSHException: Terminal binding condition encountered: remote-stream-error  (Encapsulated transport protocol error.)
	at org.igniterealtime.jbosh.BOSHClient.checkForTerminalBindingConditions(BOSHClient.java:1394)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1170)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
04:55:42.779  D  The provider state changed: RegistrationState = Unregistered => RegistrationState = Reconnecting. Reason: Attempt to invoke virtual method 'java.lang.String java.lang.String.toUpperCase(java.util.Locale)' on a null object reference
04:55:42.786  I  [1297] org.jivesoftware.smack.AbstractXMPPConnection.notifyConnectionError() Connection was already disconnected when attempting to handle org.igniterealtime.jbosh.BOSHException: Terminal binding condition encountered: remote-stream-error  (Encapsulated transport protocol error.)
org.igniterealtime.jbosh.BOSHException: Terminal binding condition encountered: remote-stream-error  (Encapsulated transport protocol error.)
	at org.igniterealtime.jbosh.BOSHClient.checkForTerminalBindingConditions(BOSHClient.java:1394)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1170)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
04:55:42.793  V  [1295] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread exiting: 0
04:55:42.797  V  [1297] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread exiting: 1
04:55:42.800  D  XMPPConnection closed due to an exception (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0))
java.lang.NullPointerException: Attempt to invoke virtual method 'java.lang.String java.lang.String.toUpperCase(java.util.Locale)' on a null object reference
	at org.jivesoftware.smack.packet.StanzaError$Type.fromString(StanzaError.java:334)
	at org.jivesoftware.smack.util.PacketParserUtils.parseError(PacketParserUtils.java:779)
	at org.jivesoftware.smack.util.PacketParserUtils.parseError(PacketParserUtils.java:758)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHPacketReader.responseReceived(XMPPBOSHConnection.java:534)
	at org.igniterealtime.jbosh.BOSHClient.fireResponseReceived(BOSHClient.java:1610)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1145)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:999)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:100)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1728)
	at java.lang.Thread.run(Thread.java:920)
04:55:43.804  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 6
04:55:44.807  D  XMPPConnection (XMPPBOSHConnection[swordfish@atalk.sytes.net/atalk-1kolot5] (0)) will reconnect in 5

New observations:

Under normal login, I see that there are two threads i.e. 0 and 1 running after the connection has started, waiting for new request….

08:34:13.421  D  RECV (2):

<body xmpp:version='1.0' authid='7173515836166334506' xmlns='http://jabber.org/protocol/httpbind' sid='4a319a97e9d1146eb5d7d27ceac79ea24148c8bd' 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.sytes.net'>
  <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>
08:34:13.422  D  [1335] org.igniterealtime.jbosh.BOSHClient.scheduleEmptyRequest() Scheduling empty request in 100ms
08:34:13.423  V  [1338] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 1 starting...
08:34:13.424  V  [1335] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...
08:34:13.424  V  [1338] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...

In reconnection failed case, only thread 1 is running. No sure why thread 0 is being stopped?

<body xmpp:version='1.0' authid='16608370789368696721' xmlns='http://jabber.org/protocol/httpbind' sid='08bd606e4d5c6d62b5705d02e0ebf755cbe2b928' 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.sytes.net'>
  <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>
08:43:05.014  V  [1397] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 1 starting...
08:43:05.015  V  [1397] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...

Further investigation shows that XMPPBOSHConnection did sent out the response immediately on receive the ‘chanllenge’. However the BoshClient did not relay this message; instead thrownNoResponseException after 10s wait.

Any idea who is holding the send message back?

10:01:32.320  D  SENT (0): 
<body rid='2834733052974226' sid='8f0963ddbb9466f5630029d415e791e5c2cf7766' xmlns='http://jabber.org/protocol/httpbind'>
  <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
    bixhPXN3YW5AYXRhbGsuc3l0ZXMubmV0LG49c3dhbixyPU89dlN6Xzx6SHNYcUY0aDxTMk5oQjV3a2w3NVRAfCRK
  </auth>
</body>
10:01:32.321  V  [173] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 is sending 2834733052974226
10:01:32.321  D  tagSocket(170) with statsTag=0xffffffff, statsUid=-1
10:01:32.330  I  untagSocket(170)
10:01:32.331  V  [173] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start tag: body
10:01:32.332  V  [173] org.igniterealtime.jbosh.BodyParserXmlPull.parse() Start element: 
10:01:32.332  V  [173] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     prefix: 
10:01:32.333  V  [173] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     URI: http://jabber.org/protocol/httpbind
10:01:32.334  V  [173] org.igniterealtime.jbosh.BodyParserXmlPull.parse()     local: body
10:01:32.334  V  [173] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 1 received response for RID: 2834733052974226 code: 200 ACK: null
10:01:32.336  D  RECV (0): 
<body xmlns='http://jabber.org/protocol/httpbind'>
  <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
    cj1PPXZTel88ekhzWHFGNGg8UzJOaEI1d2tsNzVUQHwkSmYyK3ZMWHd2NkF6alkyTFpFMWhKUXc9PSxzPW9adWZMK2RQWkVjU1p1RkdORGRxR2c9PSxpPTQwOTY=
  </challenge>
</body>
10:01:32.336  E  Send Composed Body: <body sid='8f0963ddbb9466f5630029d415e791e5c2cf7766' xmlns='http://jabber.org/protocol/httpbind'><response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>Yz1iaXhoUFhOM1lXNUFZWFJoYkdzdWMzbDBaWE11Ym1WMExBPT0scj1PPXZTel88ekhzWHFGNGg8UzJOaEI1d2tsNzVUQHwkSmYyK3ZMWHd2NkF6alkyTFpFMWhKUXc9PSxwPXFFa1VCRFFjeGhFZE1xNm5wR00vTFVCTlRkST0=</response></body>
10:01:32.946  D  Received system activity event: net.java.sip.communicator.service.sysactivity.event.SystemActivityEvent[eventID=9]
10:01:32.948  D  Received system activity event: net.java.sip.communicator.service.sysactivity.event.SystemActivityEvent[eventID=9]
10:01:38.287  D  Compat change id reported: 150939131; UID 10190; state: ENABLED
10:01:42.335  D  XMPPConnection connected (XMPPBOSHConnection[swan@atalk.sytes.net/atalk-2gb0ng7] (0))
10:01:42.342  W  [171] 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 [XMPPBOSHConnection[swan@atalk.sytes.net/atalk-2gb0ng7] (0)]
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:461)
	at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1637)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1169)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1001)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:102)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1732)
	at java.lang.Thread.run(Thread.java:1012)
Caused by: org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). While waiting for successful SASL authentication [XMPPBOSHConnection[swan@atalk.sytes.net/atalk-2gb0ng7] (0)]
	at org.jivesoftware.smack.sasl.SASLMechanism.throwExceptionIfRequired(SASLMechanism.java:343)
	at org.jivesoftware.smack.SASLAuthentication.authenticate(SASLAuthentication.java:212)
	at org.jivesoftware.smack.AbstractXMPPConnection.authenticate(AbstractXMPPConnection.java:896)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection.loginInternal(XMPPBOSHConnection.java:233)
	at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:637)
	at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:594)
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:458)
	at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1637) 
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1169) 
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1001) 
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:102) 
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1732) 
	at java.lang.Thread.run(Thread.java:1012) 

Finally the problem was traced to blockUntilSendable() that prevents the sending of the response. The function waited as exchanges.size has reaches maxRequests of 2. Seems like the exchanges list size is not properly being updated. Under normal working condiftion, the exchanges size reaches 1 at this point in time.

aTalk tries to use await with timeout, but not working. The only way that works is forcely break the loop using a software timer count down.

Any idea why exchanges is not being updated.

    private void blockUntilSendable(final AbstractBody msg) {
        assertLocked();

        Timber.d("blockUntilSendable: %s; %s; %s", isWorking(), isImmediatelySendable(msg), exchanges.size());
        while (isWorking() && !isImmediatelySendable(msg)) {
//            for(int i = 100; i > 0; i--) {
//                Timber.w("Count down: %s", i);
//            };
//            break;
            try {
                boolean wait = notFull.await(100, TimeUnit.MILLISECONDS);
            } catch (InterruptedException intx) {
                LOG.log(Level.FINEST, INTERRUPTED, intx);
            }
        }
    }
13:13:51.296  D  XMPPConnection (XMPPBOSHConnection[swan@atalk.sytes.net/atalk-171rf4o] (0)) will reconnect in 1
13:13:52.297  D  XMPPConnection (XMPPBOSHConnection[swan@atalk.sytes.net/atalk-171rf4o] (0)) will reconnect in 0
13:13:52.297  D  XMPPConnection (XMPPBOSHConnection[swan@atalk.sytes.net/atalk-171rf4o] (0)) will reconnect in 0
13:13:52.308  I  [173] org.igniterealtime.jbosh.BOSHClient.init() Starting with 1 request processors
13:13:52.310  D  blockUntilSendable: true; true; 0
13:13:52.312  D  SENT (0): 
<body ver='1.8' wait='60' xmpp:version='1.0' rid='4240682004073777' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.sytes.net' xmlns='http://jabber.org/protocol/httpbind'>
</body>
13:13:52.395  D  RECV (0): 
<body xmpp:version='1.0' authid='16728919139476727748' xmlns='http://jabber.org/protocol/httpbind' sid='56516d37c437c11a68c841b89c7c87312e076f20' 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.sytes.net'>
  <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>
13:13:52.408  D  blockUntilSendable: true; true; 1
13:13:52.410  D  SENT (0): 
<body rid='4240682004073778' sid='56516d37c437c11a68c841b89c7c87312e076f20' xmlns='http://jabber.org/protocol/httpbind'>
  <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
    bixhPXN3YW5AYXRhbGsuc3l0ZXMubmV0LG49c3dhbixyPWBoYHombjx+cjVBLTA/Iml2flkta1Y3JU5vZ2xQdmRz
  </auth>
</body>
13:13:52.422  D  RECV (0): 
<body xmlns='http://jabber.org/protocol/httpbind'>
  <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
    cj1gaGB6Jm48fnI1QS0wPyJpdn5ZLWtWNyVOb2dsUHZkc1cycW50NXdmdzhyK2RYSFFDWTlzVmc9PSxzPW9adWZMK2RQWkVjU1p1RkdORGRxR2c9PSxpPTQwOTY=
  </challenge>
</body>
13:13:52.423  D  blockUntilSendable: true; false; 2
13:14:02.415  W  [176] 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 [XMPPBOSHConnection[swan@atalk.sytes.net/atalk-171rf4o] (0)]
	at org.jivesoftware.smack.bosh.XMPPBOSHConnection$BOSHConnectionListener.connectionEvent(XMPPBOSHConnection.java:460)
	at org.igniterealtime.jbosh.BOSHClient.fireConnectionEstablished(BOSHClient.java:1646)
	at org.igniterealtime.jbosh.BOSHClient.processExchange(BOSHClient.java:1176)
	at org.igniterealtime.jbosh.BOSHClient.processMessages(BOSHClient.java:1008)
	at org.igniterealtime.jbosh.BOSHClient.access$300(BOSHClient.java:104)
	at org.igniterealtime.jbosh.BOSHClient$RequestProcessor.run(BOSHClient.java:1740)
	at java.lang.Thread.run(Thread.java:1012)

Found the root cause of the problem. Following shows the modified BoshClient#processExchange() that created logcat for both normal (OK) and reconnection (Failed) cases.

From the logcat, observation on the failed case:
a. On received the ‘mechanisms’ stanza, it does not proceed to perform finally() block.
b. The problem was traced to fireConnectionEstablished()
c. The XMPPBOSHConnection#connectionEvent() was trying to login() as isFirstInitialization is false.
d. The whole thread was pause until NoResponseException

    private void processExchange(final int idx, final HTTPExchange exch) {
        assertUnlocked();

        HTTPResponse resp;
        AbstractBody body;
        int respCode;
        try {
            if (LOG.isLoggable(Level.FINEST))
                LOG.finest(
                    "Thread " + idx + " is sending "
                        + exch.getRequest().getAttribute(Attributes.RID));

            resp = exch.getHTTPResponse();
            body = resp.getBody();
            respCode = resp.getHTTPStatus();

            if (LOG.isLoggable(Level.FINEST)) {
                String respRid = body.getAttribute(Attributes.RID);
                if (respRid == null)
                    respRid = exch.getRequest().getAttribute(Attributes.RID);
                LOG.finest(
                    "Thread " + idx + " received response"
                        + " for RID: " + respRid
                        + " code: " + respCode
                        + " ACK: " + body.getAttribute(Attributes.ACK));
            }
        } catch (BOSHException boshx) {
            LOG.log(Level.FINEST, "Could not obtain response", boshx);
            dispose(boshx);
            return;
        } catch (InterruptedException intx) {
            LOG.log(Level.FINEST, INTERRUPTED, intx);
            dispose(intx);
            return;
        }
        fireResponseReceived(body);
        Timber.w("Http response received");

        // Process the message with the current session state
        AbstractBody req = exch.getRequest();
        CMSessionParams params;
        List<HTTPExchange> toResend = null;
        lock.lock();
        try {
            Timber.w("Thread is working: %s; cmParams: %s", isWorking(), cmParams);
            if (!isWorking()) {
                lock.unlock();
                return;
            }
            // exchanges.remove(exch);

            // Check for session creation response info, if needed
            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();
            }
            params = cmParams;

            checkForTerminalBindingConditions(body, respCode);
            if (isTermination(body)) {
                // Explicit termination
                lock.unlock();
                dispose(null);
                return;
            }

            // FIXME this may not work with more than 1 RequestProcessor
            if (isRecoverableBindingCondition(body)) {
                // Retransmit outstanding requests
                if (toResend == null) {
                    toResend = new ArrayList<HTTPExchange>(exchanges.size());
                }
                for (HTTPExchange exchange : exchanges) {
                    HTTPExchange resendExch =
                            new HTTPExchange(exchange.getRequest());
                    toResend.add(resendExch);
                }
                for (HTTPExchange exchange : toResend) {
                    exchanges.add(exchange);
                }
            } else {
                // Process message as normal
                processRequestAcknowledgements(req, body);
                processResponseAcknowledgementData(req);
                HTTPExchange resendExch =
                        processResponseAcknowledgementReport(body);
                if (resendExch != null && toResend == null) {
                    toResend = new ArrayList<HTTPExchange>(1);
                    toResend.add(resendExch);
                    exchanges.add(resendExch);
                }
            }
        } catch (BOSHException boshx) {
            LOG.log(Level.FINEST, "Could not process response", boshx);
            lock.unlock();
            dispose(boshx);
            return;
        } finally {
            Timber.d("blockUntilSendable thread: %s; exchanges size: %s; lock: %s", idx, exchanges.size(), lock.isHeldByCurrentThread());
            if (lock.isHeldByCurrentThread()) {
                try {
                    exchanges.remove(exch);
                    if (exchanges.isEmpty()) {
                        scheduleEmptyRequest(processPauseRequest(req));
                    }
                    Timber.d("blockUntilSendable thread: %s; signalAll @ processExchange", idx);
                    notFull.signalAll();
                } finally {
                    lock.unlock();
                }
            }
        }

        if (toResend != null) {
            for (HTTPExchange resend : toResend) {
                HTTPResponse response =
                        httpSender.send(params, resend.getRequest());
                resend.setHTTPResponse(response);
                fireRequestSent(resend.getRequest());
            }
        }
    }

To resolve the problem. aTalk add the following code into the XMPPBOSHConnection#connectInternal() i.e.

            addConnectionListener(new ConnectionListener() {
                @Override
                public void connectionClosed() {
                    ConnectionListener.super.connectionClosed();
                    isFirstInitialization = true;
                }

                @Override
                public void connectionClosedOnError(Exception e) {
                    ConnectionListener.super.connectionClosedOnError(e);
                    isFirstInitialization = true;
                }
            });
====== Normal network login (Working) =======
09:12:29.179  V  [147] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 5615382955758882
09:12:29.187  D  SENT (0): 
<body ver='1.8' wait='60' xmpp:version='1.0' rid='5615382955758882' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.sytes.net' xmlns='http://jabber.org/protocol/httpbind'>
</body>
09:12:29.361  V  [147] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 received response for RID: 5615382955758882 code: 200 ACK: null
09:12:29.369  D  RECV (0): 
<body xmpp:version='1.0' authid='1134915779452251666' xmlns='http://jabber.org/protocol/httpbind' sid='c57ec4f1d4a4deaaff17926df10bd84fcbd45f20' 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.sytes.net'>
  <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>
09:12:29.369  W  Http response received
09:12:29.369  W  Thread is working: true
09:12:29.372  D  blockUntilSendable thread: 0; exchanges size: 1; lock: true
09:12:29.374  D  [147] org.igniterealtime.jbosh.BOSHClient.scheduleEmptyRequest() Scheduling empty request in 100ms
09:12:29.376  D  blockUntilSendable thread: 0; signalAll @ processExchange
09:12:29.378  V  [149] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 1 starting...
09:12:29.378  V  [147] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 will wait for new request...
09:12:29.380  V  [149] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...
09:12:29.390  D  The provider state changed: RegistrationState = Unregistered => RegistrationState = Registering. Reason: null
09:12:29.442  D  blockUntilSendable: true; true; 0
09:12:29.443  V  [147] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 0 claimed: 5615382955758883
09:12:29.445  V  [147] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 is sending 5615382955758883
09:12:29.445  D  SENT (0): 
<body rid='5615382955758883' sid='c57ec4f1d4a4deaaff17926df10bd84fcbd45f20' xmlns='http://jabber.org/protocol/httpbind'>
  <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
    bixhPXN3YW5AYXRhbGsuc3l0ZXMubmV0LG49c3dhbixyPUhceTdmQy1eMlZfOE9fMVFmfU9Nd3pmcyRJSF1OKFZY
  </auth>
</body>


====== Change of network (Not working) =======
09:16:14.638  D  SENT (0): 
<body ver='1.8' wait='60' xmpp:version='1.0' rid='2420838118717613' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.sytes.net' xmlns='http://jabber.org/protocol/httpbind'>
</body>
09:16:14.777  V  [172] org.igniterealtime.jbosh.BOSHClient.processExchange() Thread 0 received response for RID: 2420838118717613 code: 200 ACK: null
09:16:14.779  W  Http response received
09:16:14.779  W  Thread is working: true
09:16:14.781  V  [174] org.igniterealtime.jbosh.BOSHClient.processMessages() Processing thread 1 starting...
09:16:14.781  D  RECV (0): 
<body xmpp:version='1.0' authid='1454585575450901146' xmlns='http://jabber.org/protocol/httpbind' sid='ba11abc19ee5fd31074ad1b49b9d12ff715be008' 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.sytes.net'>
  <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>
09:16:14.782  V  [174] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 will wait for new request...
09:16:14.797  D  blockUntilSendable: true; true; 1
09:16:14.798  V  [174] org.igniterealtime.jbosh.BOSHClient.claimExchange() Thread 1 claimed: 2420838118717614
09:16:14.799  D  SENT (0): 
<body rid='2420838118717614' sid='ba11abc19ee5fd31074ad1b49b9d12ff715be008' xmlns='http://jabber.org/protocol/httpbind'>
  <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
    bixhPXN3YW5AYXRhbGsuc3l0ZXMubmV0LG49c3dhbixyPSo+U0BhWX10NUVIXktyZVQ9Q1hASnl8O04wJUI+Ii9Q
  </auth>
</body>
1 Like

Thanks for the analysis and the proposed fix. Could you create a PR with it?

I wonder if the actual fix would be changing

isFirstInitialization = false

to

isFirstInitialization = true

in XMPPBOSHConnection.instantShutdown().

Yes, you are correct. It works equally well with your proposal i.e..

isFirstInitialization = true
in XMPPBOSHConnection.instantShutdown().

Will change to this implement this for aTalk.

As for the PR, I may have problem doing this. Due to my ignorance, I accidently messed up the forked master branch source in my smack repository. Whenver I rased a new PR, it also contains all these carbage. I am not sure how to revert the branch to its original state.

I am thinking to just purge and recreate a new fork smack reposity. But worry it will destroy all the previous PR;s that I had raised. Do you think it is OK to recreate a new forked smack? Any recommendation.

Hi @cmeng ! Thanks for all of your hard work on Smack over the years!

I am not a Git expert, but from what I can tell, I believe that you do not need to create a new fork of Smack.

Do make sure that you have a backup of things, before you continue. Like I said, I’m not an expert.

As far as I can tell, you have three open PRs:

All of these PRs are created from specific branches of your fork of Smack. That means that if you ‘reset’ the ‘master’ branch of your own repository, those PRs should be unaffected.

The ‘master’ branch of your fork is currently ‘ahead’ of the ‘master’ branch of IgniteRealtime’s Smack repository. Your repository’s ‘master’ branch has 4 more commits.

There are a couple of ways that you can resolve this, without starting a completely new fork. The description below will execute a one-time forced change, that makes your fork’s ‘master’ branch be equal to ignite’s ‘master’ branch.

First, determine if the 4 commits that are ‘different’ in your repository are important to you. If they are, create a new branch that contains those commits, to keep them safe.

Then, make sure that you have Ignite’s repository set up as a ‘remote’ for your repository. On my computer, it looks like this:

$ git remote -v
origin	git@github.com:guusdk/Smack.git (fetch)
origin	git@github.com:guusdk/Smack.git (push)
upstream	git@github.com:igniterealtime/Smack.git (fetch)
upstream	git@github.com:igniterealtime/Smack.git (push)

Here, origin is my fork and upstream is IgniteRealtime’s. This can look different for you. Notably, you won’t see guusdk but cmeng-git. The identifiers (the first word on each line) may be different for you.

You can do the following to make sure that your local computer has the latest information for all remotes:

git fetch --all

Next, checkout the master branch of your fork:

$ git checkout master 
Switched to branch 'master'
Your branch is up to date with 'origin/master'.

You can then make your fork’s master branch be similar to IgniteRealtime’s master branch, by resetting it. Note that this will remove any changes that are on your branch (but it will not affect any other branches).

Note that in the example below, I reset to the master branch of what is named upstream in my environment. You may need to use a different word than upstream in your environment. The command that I used earlier (git remove -v) will tell you what identifier to use.

$ git reset --hard upstream/master
HEAD is now at 70e0d6f69 [sinttest] Move exit status logic into TestRunResult

Now, the master branch of fork of the repository that is on your computer is the same as the master branch of IgniteRealtime’s fork.

You can now push this change to your fork in the GitHub repository. In the example below, I’m using the origin identifier. Again, make sure to use the identifier that is correct for your environment.

$ git push --force --set-upstream origin
branch 'master' set up to track 'origin/master'.
...

That should do it!

Thanks for the clear instruction on how to clean up my forked smack repo.

I have raise the PR for the changes.

1 Like

I’ve created an issue for this

Please mention “Fixes SMACK-956” in the commit message.

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