strophejs icon indicating copy to clipboard operation
strophejs copied to clipboard
verified publisher icon strophe

Authentication race condition

Open jkemp101 opened this issue 11 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

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.

Do you know why Strophe doesn't continue to poll when receiving message before the _session_auth_2 iq? That might be where the real problem lies.

Your fix looks a bit like a band-aid and not as if it addresses the root problem.

jcbrand avatar Feb 04 '15 09:02 jcbrand

Unfortunately it looks like all of the sasl authentication phases assume only the correct message will come down the stream. That's probably ok except for the last phase where the server believes the client is authenticated but the client doesn't know that yet. My patch was a quick fix so I could move forward, I think the correct fix will take a little more work.

The issue is in the _onIdle function. It begins with the following if statement:

        if (this._conn.authenticated && this._requests.length === 0 &&
            data.length === 0 && !this._conn.disconnecting) {
            Strophe.info("no requests during idle cycle, sending " +
                         "blank request");
            data.push(null);
        }

In this particular case this._conn.authenticated == false so it doesn't push a null request. The rest of that function only polls the server if this._requests.length > 0. So at this point the client will never make another request to the server and never see the final authentication message.

I think the other issue is that the authentication code will never see the regular message so it doesn't even know a message came in that should be ignored and the server be polled again for more messages.

jkemp101 avatar Feb 04 '15 11:02 jkemp101