Smack 4.4.0-master smack connection defaultPacketReplyTimeout is not optimized for login when running on android OS

Smack Smack Dev
1

Current smack Default Packet Reply Timeout of 5s is not optimized during user login process when run under android OS, possibly even on PC when the login server is heavily loaded.

aTalk implementation has changed the global default reply timeout to 10s. During login, aTalk has actually increases the reply timeout to 30s to ensure high degree of a successful login for slow android devices or heavily loaded server.

Currently it seems that there is no control of the reply timeout when the connection is made via the Reconnection Manager i.e. it uses the global default reply timeout.

As shown in the debug log, even aTalk increased default reply timeout of 10s is insufficient. Maybe smack would consider another independent reply timeout timer during login for user to change.

Note: the test is being carried out with Note-10+ and using home test server via WiFi connection.
Strangely it failed 100% for all the subsequent reconnections attempted (>10 times). Not sure if it is due to the disconnection error happen on:
<h1>400 Bad Request</h1>

cmeng: update 20191021 1:30pm
sorry it looks like it is nothing to do with reply timer setting. I seems that the <challenge/> noza just follow whatever time that is being set to. It is something else that is causing the Reconnection to failed 100%.
please refer to

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

======== aTalk BOSH reconnection timeout ==========
2019-10-21 08:23:18.093 6677-7384/org.atalk.android E/(AndroidOmemoService.java:123)#initializationFailed: OmemoManager init failed
    org.jivesoftware.smack.SmackException$NotConnectedException: The connection XMPPBOSHConnection[swordfish@atalk.org/atalk] (0) is no longer connected while waiting for response with IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=KE8NY-85)), : fromFilter (OrFilter: (FromMatchesFilter (full): null, FromMatchesFilter (ignoreResourcepart): swordfish@atalk.org, FromMatchesFilter (full): atalk.org)) because of 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.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:276)
        at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:228)
        at org.jivesoftware.smackx.pubsub.LeafNode.publish(LeafNode.java:330)
        at org.jivesoftware.smackx.pubsub.LeafNode.publish(LeafNode.java:309)
        at org.jivesoftware.smackx.pubsub.PubSubManager.tryToPublishAndPossibleAutoCreate(PubSubManager.java:452)
        at org.jivesoftware.smackx.pep.PepManager.publish(PepManager.java:165)
        at org.jivesoftware.smackx.omemo.OmemoService.publishBundle(OmemoService.java:592)
        at org.jivesoftware.smackx.omemo.OmemoService.init(OmemoService.java:260)
        at org.jivesoftware.smackx.omemo.OmemoManager.initialize(OmemoManager.java:251)
        at org.jivesoftware.smackx.omemo.OmemoManager$2.run(OmemoManager.java:266)
        at java.lang.Thread.run(Thread.java:764)
     Caused by: org.igniterealtime.jbosh.BOSHException: Could not parse body:

2019-10-21 08:23:23.359 6677-7408/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[swordfish@atalk.org/atalk] (0)) will reconnect in 2
2019-10-21 08:23:24.363 6677-7408/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[swordfish@atalk.org/atalk] (0)) will reconnect in 1
2019-10-21 08:23:25.367 6677-7408/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[swordfish@atalk.org/atalk] (0)) will reconnect in 0
2019-10-21 08:23:25.369 6677-7408/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[swordfish@atalk.org/atalk] (0)) will reconnect in 0

2019-10-21 08:23:25.427 6677-7408/org.atalk.android D/SMACK: SENT (0): 
    <body ver='1.8' wait='60' xmpp:version='1.0' rid='5642716902741201' xmlns:xmpp='urn:xmpp:xbosh' hold='1' xml:lang='en' ack='1' to='atalk.org' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
2019-10-21 08:23:26.587 6677-7428/org.atalk.android D/SMACK: RECV (0): 
    <body xmpp:version='1.0' authid='8918239010385705058' xmlns='http://jabber.org/protocol/httpbind' sid='5d90d535ef1a1f860749b9d3ea1ad9579db1946c' 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 08:23:26.666 6677-7427/org.atalk.android D/SMACK: SENT (0): 
    <body rid='5642716902741202' sid='5d90d535ef1a1f860749b9d3ea1ad9579db1946c' xmlns='http://jabber.org/protocol/httpbind'>
      <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
        biwsbj1zd29yZGZpc2gscj1AezBLLkhgIXZTeyZnKjZFc0JHQFwuanxmeFdcKWNTag==
      </auth>
    </body>
2019-10-21 08:23:36.709 6677-7427/org.atalk.android W/aTalk: [100141] 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 08:23:36.713 6677-7329/org.atalk.android W/g.atalk.androi: Long monitor contention with owner Smack DefaultReactor Thread #1 (7330) at void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect()(SmackReactor.java:209) waiters=0 in void org.jivesoftware.smack.SmackReactor$Reactor.handleScheduledActionsOrPerformSelect() for 21.935s
2019-10-21 08:23:36.726 6677-7431/org.atalk.android D/SMACK: SENT (0): 
    <body rid='5642716902741203' ack='5642716902741201' sid='5d90d535ef1a1f860749b9d3ea1ad9579db1946c' xmlns='http://jabber.org/protocol/httpbind'>
      <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        Yz1iaXdzLHI9QHswSy5IYCF2U3smZyo2RXNCR0BcLmp8ZnhXXCljU2oxWU1kTElQMHVraDRqY3F1cU9La1B3PT0scD16WVlmeFFSbEhkMHh3dS9YMnhBTlFQcUZkOFU9
      </response>
    </body>
2019-10-21 08:23:36.728 6677-7428/org.atalk.android D/SMACK: RECV (0): 
    <body xmlns='http://jabber.org/protocol/httpbind'>
      <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        cj1AezBLLkhgIXZTeyZnKjZFc0JHQFwuanxmeFdcKWNTajFZTWRMSVAwdWtoNGpjcXVxT0trUHc9PSxzPTVXVENHSnk1dk1FUWJpNmZWRVJ1S0E9PSxpPTQwOTY=
      </challenge>
    </body>
2

So, is this issue resolved then?

3

The BOSH connection problem is not related to Reply Timeout Timer. However the current default Global timer of 5s is still not optimized during user login process; may be not even optimized for normal operation at least in android and under heavy loaded server.

aTalk has set the Global default to 10s, just to ensure it works under most conditions; however this long 10s may cause ANR when the event failed as a side effect.

During login, aTalk has increased this timer to 30s. During aTalk testing. some login process can take up to 25s to complete. The 30s is also used during service discovery; equally this also takes long time to complete.

I feel that smack may want to consider a separate timer, configurable by user, to be used for user specified processes e.g. login, service discovery etc.

4

Below is a capture of the log when ReconnectionManager failed due to SmackException$NoResponseException on my Note-5 device.
No sure why it takes 61s to <response/> to the received <challenge/>. Usually it takes less than a second to response i.e…

10-28 08:40:41.086 30680-30847/org.atalk.android D/SMACK: RECV (0): 
    <body sid='2f59c588-3fe8-4551-a5fc-3767cf084787' xmlns:stream='http://etherx.jabber.org/streams' xmlns='http://jabber.org/protocol/httpbind'>
      <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        cj1xNF9+cXBbclJTMXh4JUY0cTB2OWs7ZEF9Wkczc0MybDA1YWM4NWQ0LTkzNWEtNGYyNy04MjgwLWU4ODkzMDU5YTY0OSxzPU5tVTNOVFppTXpJdE1HUm1NeTAwWkRBeExXRTNaRFl0TXpRM016STVNelUxT1RjdyxpPTQwOTY=
      </challenge>
    </body>
10-28 08:40:41.496 30680-30846/org.atalk.android D/SMACK: SENT (0): 
    <body rid='136062250332261' sid='2f59c588-3fe8-4551-a5fc-3767cf084787' ack='136062250332259' xmlns='http://jabber.org/protocol/httpbind'>
      <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        Yz1iaXdzLHI9cTRffnFwW3JSUzF4eCVGNHEwdjlrO2RBfVpHM3NDMmwwNWFjODVkNC05MzVhLTRmMjctODI4MC1lODg5MzA1OWE2NDkscD1GMGJYZW5ZdlQxbDVvU3NGWXVMK0ZNY3Fmd2M9
      </response>
    </body>

You can just ignore the NoResponseException problem referred here. However there is no further attempt by reconnectionManager to reconnect on NoResponseException in this case.

=========== aTalk BOSHConnection Re-login failure debug log on Note-5 ========
10-28 08:09:25.286 24481-26937/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[cmeng-atalk@dismail.de/atalk] (1)) will reconnect in 1
10-28 08:09:26.286 24481-26937/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[cmeng-atalk@dismail.de/atalk] (1)) will reconnect in 0
10-28 08:09:26.286 24481-26937/org.atalk.android D/SMACK: XMPPConnection (XMPPBOSHConnection[cmeng-atalk@dismail.de/atalk] (1)) will reconnect in 0

10-28 08:09:26.316 24481-26937/org.atalk.android D/SMACK: SENT (1): 
    <body wait='60' xmpp:version='1.0' ack='1' xmlns:xmpp='urn:xmpp:xbosh' ver='1.8' xml:lang='en' rid='8521536482926913' to='dismail.de' hold='1' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
10-28 08:09:41.906 24481-27731/org.atalk.android D/SMACK: RECV (1): 
    <body xmlns:stream='http://etherx.jabber.org/streams' xmpp:version='1.0' xmlns:xmpp='urn:xmpp:xbosh' ver='1.6' inactivity='60' requests='2' polling='5' secure='true' hold='1' from='dismail.de' authid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' wait='60' sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns='http://jabber.org/protocol/httpbind'>
      <stream:features xmlns='jabber:client'>
        <register xmlns='http://jabber.org/features/iq-register'/>
        <mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
          <mechanism>
            SCRAM-SHA-1
          </mechanism>
          <mechanism>
            PLAIN
          </mechanism>
        </mechanisms>
        <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
          <required/>
        </starttls>
      </stream:features>
    </body>
10-28 08:09:42.026 24481-27745/org.atalk.android D/SMACK: SENT (1): 
    <body rid='560461436107503' sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
10-28 08:09:42.036 24481-26937/org.atalk.android D/SMACK: SENT (1): 
    <body rid='560461436107504' sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' ack='560461436107502' xmlns='http://jabber.org/protocol/httpbind'>
      <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='SCRAM-SHA-1'>
        biwsbj1jbWVuZy1hdGFsayxyPUNsPVl4QENASFxeXUU0RzQreTE5Z3J6dlwmKSYpblRh
      </auth>
    </body>
10-28 08:09:43.546 24481-27731/org.atalk.android D/SMACK: RECV (1): 
    <body sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns:stream='http://etherx.jabber.org/streams' xmlns='http://jabber.org/protocol/httpbind'>
      <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        cj1DbD1ZeEBDQEhcXl1FNEc0K3kxOWdyenZcJikmKW5UYWE3Mjg5YjZhLTQzNWMtNGM0YS1iZmM4LTJiZmU0ZGI3ZWNkZCxzPU5tVTNOVFppTXpJdE1HUm1NeTAwWkRBeExXRTNaRFl0TXpRM016STVNelUxT1RjdyxpPTQwOTY=
      </challenge>
    </body>
10-28 08:09:52.036 24481-26937/org.atalk.android D/SMACK: Reconnection failed due to an exception (XMPPBOSHConnection[cmeng-atalk@dismail.de/atalk] (1))
    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:201)
        at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:646)
        at org.jivesoftware.smack.AbstractXMPPConnection.login(AbstractXMPPConnection.java:603)
        at org.jivesoftware.smack.ReconnectionManager$2.run(ReconnectionManager.java:287)
        at java.lang.Thread.run(Thread.java:818)
10-28 08:10:44.266 24481-27731/org.atalk.android D/SMACK: RECV (1): 
    <body sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns:stream='http://etherx.jabber.org/streams' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
10-28 08:10:44.276 24481-27730/org.atalk.android D/SMACK: SENT (1): 
    <body rid='560461436107505' sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' ack='560461436107502' xmlns='http://jabber.org/protocol/httpbind'>
      <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        Yz1iaXdzLHI9Q2w9WXhAQ0BIXF5dRTRHNCt5MTlncnp2XCYpJiluVGFhNzI4OWI2YS00MzVjLTRjNGEtYmZjOC0yYmZlNGRiN2VjZGQscD1HR25QMDQrbzc0b29Hak5TOTlaaFNQWU9TclE9
      </response>
    </body>
10-28 08:10:44.566 24481-27731/org.atalk.android D/SMACK: RECV (1): 
    <body sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns:stream='http://etherx.jabber.org/streams' xmlns='http://jabber.org/protocol/httpbind'>
      <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        dj0xZGtsdDlUQnhHYnpFenQrZnRiRDRWY0dvbjg9
      </success>
    </body>
    <body rid='560461436107506' sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns='http://jabber.org/protocol/httpbind'>
    </body>
10-28 08:10:45.086 24481-27731/org.atalk.android D/SMACK: RECV (1): 
    <body sid='01c1b4ce-4c3d-40c8-8e20-edce57492f46' xmlns:stream='http://etherx.jabber.org/streams' xmlns='http://jabber.org/protocol/httpbind'>
      <stream:features xmlns='jabber:client'>
        <ver xmlns='urn:xmpp:features:rosterver'/>
        <bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'>
          <required/>
        </bind>
        <session xmlns='urn:ietf:params:xml:ns:xmpp-session'>
          <optional/>
        </session>
        <csi xmlns='urn:xmpp:csi:0'/>
        <sm xmlns='urn:xmpp:sm:2'>
          <optional/>
        </sm>
        <sm xmlns='urn:xmpp:sm:3'>
          <optional/>
        </sm>
        <c ver='deZ5rC/kTkiw4o7g4kLfFOlrrXE=' hash='sha-1' node='http://prosody.im' xmlns='http://jabber.org/protocol/caps'/>
        <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>
          <required/>
        </starttls>
      </stream:features>
    </body>
5

This

sounds like you are having trouble once again with a sync stanza listener that is blocking the receiver thread.

6

Thanks for information.

aTalk implementation uses the following defined reply packet timer under various conditions.
No idea which sync stanza listener is actually holding back. aTalk uses the 60s only during IBR captcha reply from user.

Currently what I see is that smack reply timer implementation are fixed; it is very difficult to find an optimized value to use: too long causes ANR on app UI, too short causes reliability problem.

Just wonder whether there is a perfect way how smackReactor handles reply timeout e.g.
make it interruptable at 3s interval from app level with a single maximum setting of say 60s. So smack takes care of worst case condition, at the same time allow app/user to cancel the wait if found to long.
Has not have the in-depth though about this approach to ascertain it works in all condition.

    /**
     * Smack packet maximum reply timeout - Smack will immediately return on reply or until timeout
     * before issues exception. Need this to take care for some servers response on some packages
     * e.g. disco#info (30 seconds). Also on some slow client e.g. Samsung SII takes up to 30
     * Sec to response to sasl authentication challenge on first login
     */
    public static final int SMACK_PACKET_REPLY_EXTENDED_TIMEOUT_30 = 30000;  // 30 seconds

    // vCard save takes about 29 seconds on Note 8
    public static final int SMACK_PACKET_REPLY_EXTENDED_TIMEOUT_40 = 40000;  // 40 seconds

    // Captcha entry timeout is control by server - so set to long smack timeout (60S)
    public static final int SMACK_PACKET_CAPTCHA_TIMEOUT = 60000;

    /**
     * aTalk Smack packet reply default timeout.
     */
    public static final int SMACK_PACKET_REPLY_TIMEOUT_10 = 10000;
7

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