{"action":"created","issue":{"url":"https://api.github.com/repos/strophe/strophejs/issues/101","labels_url":"https://api.github.com/repos/strophe/strophejs/issues/101/labels{/name}","comments_url":"https://api.github.com/repos/strophe/strophejs/issues/101/comments","events_url":"https://api.github.com/repos/strophe/strophejs/issues/101/events","html_url":"https://github.com/strophe/strophejs/issues/101","id":55392906,"number":101,"title":"Authentication race condition","user":{"login":"jkemp101","id":3944676,"avatar_url":"https://avatars.githubusercontent.com/u/3944676?v=3","gravatar_id":"","url":"https://api.github.com/users/jkemp101","html_url":"https://github.com/jkemp101","followers_url":"https://api.github.com/users/jkemp101/followers","following_url":"https://api.github.com/users/jkemp101/following{/other_user}","gists_url":"https://api.github.com/users/jkemp101/gists{/gist_id}","starred_url":"https://api.github.com/users/jkemp101/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jkemp101/subscriptions","organizations_url":"https://api.github.com/users/jkemp101/orgs","repos_url":"https://api.github.com/users/jkemp101/repos","events_url":"https://api.github.com/users/jkemp101/events{/privacy}","received_events_url":"https://api.github.com/users/jkemp101/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/strophe/strophejs/labels/bug","name":"bug","color":"fc2929"},{"url":"https://api.github.com/repos/strophe/strophejs/labels/question","name":"question","color":"cc317c"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2015-01-25T02:32:24Z","updated_at":"2015-02-04T11:42:01Z","closed_at":null,"body":"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.  \r\n\r\nYou 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.\r\n\r\nGood login:\r\n```\r\nFri 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>\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 2\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 3\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 4\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: removing request\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4 should now be removed\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 got 200\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called\r\nFri 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>\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 posting\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 state changed to 1\r\nFri 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>\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 2\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 3\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 4\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: removing request\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5 should now be removed\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 got 200\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called\r\nFri 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>\r\nFri Jan 23 2015 19:32:36 GMT-0500 (Eastern Standard Time)Strophe is connected.\r\n```\r\n\r\nFailed login:\r\n```\r\nFri 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>\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 2\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 3\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 state changed to 4\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: removing request\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4 should now be removed\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 4.1 got 200\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called\r\nFri 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>\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 posting\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.0 state changed to 1\r\nFri 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>\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 2\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 3\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 state changed to 4\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: removing request\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _throttledRequestHandler called with 0 requests\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5 should now be removed\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: request id 5.1 got 200\r\nFri Jan 23 2015 19:32:06 GMT-0500 (Eastern Standard Time)LOG: _dataRecv called\r\nFri 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>\r\n```\r\n\r\nI 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.\r\n\r\n```\r\n--- strophe.js.org      2014-01-20 16:08:40.000000000 -0500\r\n+++ strophe.js  2015-01-24 21:15:16.641819100 -0500\r\n@@ -3179,6 +3179,7 @@\r\n                     this.send($iq({type: \"set\", id: \"_session_auth_2\"})\r\n                                   .c('session', {xmlns: Strophe.NS.SESSION})\r\n                                   .tree());\r\n+                    this._addSysTimedHandler(2000,this._final_auth_monitor.bin\r\n(this));\r\n                 } else {\r\n                     this.authenticated = true;\r\n                     this._changeConnectStatus(Strophe.Status.CONNECTED, null);\r\n@@ -3190,7 +3191,18 @@\r\n             return false;\r\n         }\r\n     },\r\n-\r\n+    _final_auth_monitor: function ()\r\n+    {\r\n+       if (this.authenticated) {\r\n+               Strophe.debug(\"All is good we authenticated\");\r\n+               return false;\r\n+       } else {\r\n+               Strophe.debug(\"Looks like me need to force a poll\");\r\n+               this._proto._conn._data.push(null);\r\n+               return true;\r\n+       }\r\n+\r\n+    },\r\n     /** PrivateFunction: _sasl_session_cb\r\n      *  _Private_ handler to finish successful SASL connection.\r\n      *\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/strophe/strophejs/issues/comments/72841217","html_url":"https://github.com/strophe/strophejs/issues/101#issuecomment-72841217","issue_url":"https://api.github.com/repos/strophe/strophejs/issues/101","id":72841217,"user":{"login":"jkemp101","id":3944676,"avatar_url":"https://avatars.githubusercontent.com/u/3944676?v=3","gravatar_id":"","url":"https://api.github.com/users/jkemp101","html_url":"https://github.com/jkemp101","followers_url":"https://api.github.com/users/jkemp101/followers","following_url":"https://api.github.com/users/jkemp101/following{/other_user}","gists_url":"https://api.github.com/users/jkemp101/gists{/gist_id}","starred_url":"https://api.github.com/users/jkemp101/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jkemp101/subscriptions","organizations_url":"https://api.github.com/users/jkemp101/orgs","repos_url":"https://api.github.com/users/jkemp101/repos","events_url":"https://api.github.com/users/jkemp101/events{/privacy}","received_events_url":"https://api.github.com/users/jkemp101/received_events","type":"User","site_admin":false},"created_at":"2015-02-04T11:42:01Z","updated_at":"2015-02-04T11:42:01Z","body":"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.\r\n\r\nThe issue is in the _onIdle function.  It begins with the following if statement:\r\n```\r\n        if (this._conn.authenticated && this._requests.length === 0 &&\r\n            data.length === 0 && !this._conn.disconnecting) {\r\n            Strophe.info(\"no requests during idle cycle, sending \" +\r\n                         \"blank request\");\r\n            data.push(null);\r\n        }\r\n```\r\n\r\nIn 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.\r\n\r\nI 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."}}