Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Authentication race condition #101

Open
jkemp101 opened this issue Jan 25, 2015 · 2 comments
Open

Authentication race condition #101

jkemp101 opened this issue Jan 25, 2015 · 2 comments
Labels
bug

Comments

@jkemp101
Copy link

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>jkemp@tiger.tricomsystems.com/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='jkemp@tiger.tricomsystems.com/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>jkemp@tiger.tricomsystems.com/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='jkemp@tiger.tricomsystems.com/89214e8f' type='chat' from='lprsim@lprsim.tiger.tricomsystems.com'><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.
      *
@jcbrand
Copy link
Contributor

jcbrand commented Feb 4, 2015

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.

@jkemp101
Copy link
Author

jkemp101 commented Feb 4, 2015

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.

@jcbrand jcbrand removed the question label Feb 4, 2015
apparition47 pushed a commit to Switch168/strophejs that referenced this issue Nov 10, 2016
strophe#101 fix authenication race condition
ea6efd0
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jcbrand @jkemp101