strophejs icon indicating copy to clipboard operation
strophejs copied to clipboard

Published 20 hours ago • verified publisher icon strophe

Authentication race condition

Open jkemp101 opened this issue 10 years ago • 2 comments

Authentication hangs while attempting to login to openfire 3.9.3 when the client is sent chat messages 3 times per second. Logins would fail about 2 out of 3 attempts. It appears strophe gets confused when the server sends a regular message before strophe receives the final _session_auth_2 iq message. From the server perspective the client is authenticated so it is ok to send the regular message. Strophe does not keep polling for new messages, so it gets the regular message but never polls a second time to get the pending _session_auth_2 iq which is needed to complete the authentication.

You can see in the following failed login example that at line 67 the regular message comes in and strophe stops polling for any new messages.

Good login:

Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)SEND: <body rid='3568300445' xmlns='http://jabber.org/protocol/httpbind' sid='5c2b4a1b'><iq type='set' id='_bind_auth_2' xmlns='jabber:client'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/></iq></body>
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 2
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 3
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 4
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: removing request
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4 should now be removed
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 got 200
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)RECV: <body xmlns='http://jabber.org/protocol/httpbind'><iq xmlns='jabber:client' type='result' id='_bind_auth_2' to='tiger.tricomsystems.com/5c2b4a1b'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>[email protected]/5c2b4a1b</jid></bind></iq></body>
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 posting
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 state changed to 1
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)SEND: <body rid='3568300446' xmlns='http://jabber.org/protocol/httpbind' sid='5c2b4a1b'><iq type='set' id='_session_auth_2' xmlns='jabber:client'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></iq></body>
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 2
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 3
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 4
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: removing request
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5 should now be removed
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 got 200
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)RECV: <body xmlns='http://jabber.org/protocol/httpbind'><iq xmlns='jabber:client' type='result' id='_session_auth_2' to='[email protected]/5c2b4a1b'/></body>
Fri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)Strophe is connected.

Failed login:

Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)SEND: <body rid='4234276768' xmlns='http://jabber.org/protocol/httpbind' sid='89214e8f'><iq type='set' id='_bind_auth_2' xmlns='jabber:client'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/></iq></body>
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 2
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 3
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 4
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: removing request
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4 should now be removed
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 got 200
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)RECV: <body xmlns='http://jabber.org/protocol/httpbind'><iq xmlns='jabber:client' type='result' id='_bind_auth_2' to='tiger.tricomsystems.com/89214e8f'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>[email protected]/89214e8f</jid></bind></iq></body>
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 posting
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 state changed to 1
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)SEND: <body rid='4234276769' xmlns='http://jabber.org/protocol/httpbind' sid='89214e8f'><iq type='set' id='_session_auth_2' xmlns='jabber:client'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></iq></body>
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 2
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 3
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 4
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: removing request
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5 should now be removed
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 got 200
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called
Fri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)RECV: <body xmlns='http://jabber.org/protocol/httpbind'><message xmlns='jabber:client' to='[email protected]/89214e8f' type='chat' from='[email protected]'><body>This is a test:4263</body></message></body>

I added a system timed handler to bump the polling logic when it stops in this state. Probably not the best solution but it works for me right now.

--- strophe.js.org      2014-01-20 16:08:40.000000000 -0500
+++ strophe.js  2015-01-24 21:15:16.641819100 -0500
@@ -3179,6 +3179,7 @@
                     this.send($iq({type: "set", id: "_session_auth_2"})
                                   .c('session', {xmlns: Strophe.NS.SESSION})
                                   .tree());
+                    this._addSysTimedHandler(2000,this._final_auth_monitor.bin
(this));
                 } else {
                     this.authenticated = true;
                     this._changeConnectStatus(Strophe.Status.CONNECTED, null);
@@ -3190,7 +3191,18 @@
             return false;
         }
     },
-
+    _final_auth_monitor: function ()
+    {
+       if (this.authenticated) {
+               Strophe.debug("All is good we authenticated");
+               return false;
+       } else {
+               Strophe.debug("Looks like me need to force a poll");
+               this._proto._conn._data.push(null);
+               return true;
+       }
+
+    },
     /** PrivateFunction: _sasl_session_cb
      *  _Private_ handler to finish successful SASL connection.
      *

jkemp101 avatar Jan 25 '15 02:01 jkemp101