{"action":"created","issue":{"url":"https://api.github.com/repos/go-mgo/mgo/issues/254","repository_url":"https://api.github.com/repos/go-mgo/mgo","labels_url":"https://api.github.com/repos/go-mgo/mgo/issues/254/labels{/name}","comments_url":"https://api.github.com/repos/go-mgo/mgo/issues/254/comments","events_url":"https://api.github.com/repos/go-mgo/mgo/issues/254/events","html_url":"https://github.com/go-mgo/mgo/issues/254","id":148695735,"number":254,"title":"client continually calling isMaster","user":{"login":"wgallagher","id":1172860,"avatar_url":"https://avatars.githubusercontent.com/u/1172860?v=3","gravatar_id":"","url":"https://api.github.com/users/wgallagher","html_url":"https://github.com/wgallagher","followers_url":"https://api.github.com/users/wgallagher/followers","following_url":"https://api.github.com/users/wgallagher/following{/other_user}","gists_url":"https://api.github.com/users/wgallagher/gists{/gist_id}","starred_url":"https://api.github.com/users/wgallagher/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wgallagher/subscriptions","organizations_url":"https://api.github.com/users/wgallagher/orgs","repos_url":"https://api.github.com/users/wgallagher/repos","events_url":"https://api.github.com/users/wgallagher/events{/privacy}","received_events_url":"https://api.github.com/users/wgallagher/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":5,"created_at":"2016-04-15T15:44:58Z","updated_at":"2016-10-14T20:29:10Z","closed_at":"2016-05-19T15:31:40Z","body":"I'm seeing an issue where, after running for some time in production, the mgo client begins calling authenticate for every query.  This happens after ~ 2 hours at ~ 700RPS.  Once the client enters this state, it never recovers.\r\n\r\nWhen the process first starts, each query is sent using the credentials that were previously authenticated on the socket.  The sequence looks like this:  authenticate, query, logout, authenticate, query, ...  The authentication optimization in auth.go causes the (logout, authenticates) to cancel out producing a sequence of queries:  authenticate, query, query, query, ...\r\n\r\nAt some point, the client begins to send 'ismaster' before every request.  This breaks that above sequence which now looks like:  authenticate, query, logout, ismaster, authenticate, query, logout.\r\n\r\nI believe the cause for the additional 'ismaster' queries is a socket that has been abended due to a recoverable error (timeout?).  The socket abend causes the server to become abended.  This results in the following code from cluster.go to perform a 'ismaster':\r\n\r\n\t\tif abended && !slaveOk {\r\n\t\t\tvar result isMasterResult\r\n\t\t\terr := cluster.isMaster(s, &result)\r\n\t\t\tif err != nil || !result.IsMaster {\r\n\t\t\t\tlogf(\"Cannot confirm server %s as master (%v)\", server.Addr, err)\r\n\t\t\t\ts.Release()\r\n\t\t\t\tcluster.syncServers()\r\n\t\t\t\ttime.Sleep(100 * time.Millisecond)\r\n\t\t\t\tcontinue\r\n\r\nThe server.abended state is never reset to 'false' in this case causing each request to be preceeded by an 'ismaster' query and the associated authenticate / logout described above.  The end result is 5 operations being performed for each query.\r\n"},"comment":{"url":"https://api.github.com/repos/go-mgo/mgo/issues/comments/253911259","html_url":"https://github.com/go-mgo/mgo/issues/254#issuecomment-253911259","issue_url":"https://api.github.com/repos/go-mgo/mgo/issues/254","id":253911259,"user":{"login":"nikhilm","id":78682,"avatar_url":"https://avatars.githubusercontent.com/u/78682?v=3","gravatar_id":"","url":"https://api.github.com/users/nikhilm","html_url":"https://github.com/nikhilm","followers_url":"https://api.github.com/users/nikhilm/followers","following_url":"https://api.github.com/users/nikhilm/following{/other_user}","gists_url":"https://api.github.com/users/nikhilm/gists{/gist_id}","starred_url":"https://api.github.com/users/nikhilm/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nikhilm/subscriptions","organizations_url":"https://api.github.com/users/nikhilm/orgs","repos_url":"https://api.github.com/users/nikhilm/repos","events_url":"https://api.github.com/users/nikhilm/events{/privacy}","received_events_url":"https://api.github.com/users/nikhilm/received_events","type":"User","site_admin":false},"created_at":"2016-10-14T20:29:10Z","updated_at":"2016-10-14T20:29:10Z","body":"@niemeyer  This is a reproducible test case - https://gist.github.com/nikhilm/ce59ad89bbf4f2dde53db6c90cc9c447\r\n\r\nWe are hitting this case consistently in our prod database, where after one socket failure, all sockets in the pool will keep performing extra ismaster checks until we restart our service.\r\n\r\n#255 does fix it, but I don't understand enough about mgo internals to know if that is the right fix (especially the locking).\r\n\r\nI hope the test case works, I only have about a 80% success rate with it running against a local mongo.\r\n\r\ncc @vlopatkin"}}
{"actor":{"display_login":"nikhilm"}}