Revision: 15784 http://trac.calendarserver.org//changeset/15784 Author: sagen@apple.com Date: 2016-08-03 16:20:52 -0700 (Wed, 03 Aug 2016) Log Message: ----------- LDAP connection pool sizes now indepently configurable; pool name is included in log messages and stats keys; an anonymous bind is performed after the credentials-verification bind in case servers limit the number of times a given user can be "logged in" at the same time. Modified Paths: -------------- twext/trunk/twext/who/ldap/_service.py twext/trunk/twext/who/ldap/test/test_service.py Modified: twext/trunk/twext/who/ldap/_service.py =================================================================== --- twext/trunk/twext/who/ldap/_service.py 2016-08-03 18:01:01 UTC (rev 15783) +++ twext/trunk/twext/who/ldap/_service.py 2016-08-03 23:20:52 UTC (rev 15784) @@ -217,6 +217,10 @@ self.activeCount = 0 self.connectionsCreated = 0 self.connectionMax = connectionMax + self.log.debug( + "Created {pool} LDAP connection pool with connectionMax={max}", + pool=self.poolName, max=self.connectionMax + ) def getConnection(self): """ @@ -243,25 +247,25 @@ self.connectionCreateLock.release() else: self.connectionCreateLock.release() - self.ds.poolStats["connection-blocked"] += 1 + self.ds.poolStats["connection-{}-blocked".format(self.poolName)] += 1 connection = self.connectionQueue.get() - connectionID = "connection-{}".format( - self.connections.index(connection) + connectionID = "connection-{}-{}".format( + self.poolName, self.connections.index(connection) ) self.ds.poolStats[connectionID] += 1 self.activeCount = len(self.connections) - self.connectionQueue.qsize() - self.ds.poolStats["connection-active"] = self.activeCount - self.ds.poolStats["connection-max"] = max( - self.ds.poolStats["connection-max"], self.activeCount + self.ds.poolStats["connection-{}-active".format(self.poolName)] = self.activeCount + self.ds.poolStats["connection-{}-max".format(self.poolName)] = max( + self.ds.poolStats["connection-{}-max".format(self.poolName)], self.activeCount ) if self.activeCount > self.connectionMax: self.log.error( - "Active LDAP connections ({active}) exceeds maximum ({max})", - active=self.activeCount, max=self.connectionMax + "[Pool: {pool}] Active LDAP connections ({active}) exceeds maximum ({max})", + pool=self.poolName, active=self.activeCount, max=self.connectionMax ) return connection @@ -272,6 +276,7 @@ """ self.connectionQueue.put(connection) self.activeCount = len(self.connections) - self.connectionQueue.qsize() + self.ds.poolStats["connection-{}-active".format(self.poolName)] = self.activeCount def failedConnection(self, connection): @@ -279,9 +284,10 @@ A connection has failed; remove it from the list of active connections. A new one will be created if needed. """ - self.ds.poolStats["connection-errors"] += 1 + self.ds.poolStats["connection-{}-errors".format(self.poolName)] += 1 self.connections.remove(connection) self.activeCount = len(self.connections) - self.connectionQueue.qsize() + self.ds.poolStats["connection-{}-active".format(self.poolName)] = self.activeCount def _connect(self): @@ -295,7 +301,10 @@ @raises: L{LDAPConnectionError} if unable to connect. """ - self.log.debug("Connecting to LDAP at {log_source.url}") + self.log.debug( + "[Pool: {pool}] Connecting to LDAP at {url}", + pool=self.poolName, url=self.ds.url + ) connection = self._newConnection() if self.credentials is not None: @@ -306,15 +315,15 @@ self.credentials.password, ) self.log.debug( - "Bound to LDAP as {credentials.username}", - credentials=self.credentials + "[Pool: {pool}] Bound to LDAP as {credentials.username}", + pool=self.poolName, credentials=self.credentials ) except ( ldap.INVALID_CREDENTIALS, ldap.INVALID_DN_SYNTAX ) as e: self.log.error( - "Unable to bind to LDAP as {credentials.username}", - credentials=self.credentials + "[Pool: {pool}] Unable to bind to LDAP as {credentials.username}", + pool=self.poolName, credentials=self.credentials ) raise LDAPBindAuthError( self.credentials.username, e @@ -354,7 +363,10 @@ connection.set_option(option, value) if self.ds._useTLS: - self.log.debug("Starting TLS for {log_source.url}") + self.log.debug( + "[Pool: {pool}] Starting TLS for {url}", + pool=self.poolName, url=self.ds.url + ) connection.start_tls_s() self.connectionsCreated += 1 @@ -394,7 +406,8 @@ extraFilters=None, ownThreadpool=True, threadPoolMax=10, - connectionMax=10, + authConnectionMax=5, + queryConnectionMax=5, tries=3, warningThresholdSeconds=5, _debug=False, @@ -509,11 +522,10 @@ max(threadPoolMax, self.threadpool.max) ) - # Separate pools for LDAP queries and LDAP binds. Note, they each get - # half of connectionMax. + # Separate pools for LDAP queries and LDAP binds. self.connectionPools = { - "query": ConnectionPool("query", self, credentials, connectionMax / 2), - "auth": ConnectionPool("auth", self, None, connectionMax / 2), + "query": ConnectionPool("query", self, credentials, queryConnectionMax), + "auth": ConnectionPool("auth", self, None, authConnectionMax), } self.poolStats = collections.defaultdict(int) @@ -625,6 +637,10 @@ except Exception as e: self.log.error("Unexpected error {error} trying to authenticate {dn}", error=str(e), dn=dn) return False + finally: + # Do an unauthenticated bind on this connection at the end in + # case the server limits the number of concurrent auths by a given user. + connection.simple_bind_s("", "") def _recordsFromQueryString( Modified: twext/trunk/twext/who/ldap/test/test_service.py =================================================================== --- twext/trunk/twext/who/ldap/test/test_service.py 2016-08-03 18:01:01 UTC (rev 15783) +++ twext/trunk/twext/who/ldap/test/test_service.py 2016-08-03 23:20:52 UTC (rev 15784) @@ -499,7 +499,7 @@ actually created is what we expect. """ - service = self.service(connectionMax=4) + service = self.service(authConnectionMax=2) pool = service.connectionPools["auth"] self.assertEquals(0, len(pool.connections)) @@ -508,7 +508,11 @@ # Ask for a connection and check the counts with TestService.Connection(service, "auth"): self.assertEquals(1, len(pool.connections)) + self.assertEquals(1, service.poolStats["connection-auth-active"]) + # When the above context exits, the connection is returned + self.assertEquals(0, service.poolStats["connection-auth-active"]) + self.assertEquals(1, len(pool.connections)) self.assertEquals(1, pool.connectionsCreated) @@ -519,33 +523,40 @@ with TestService.Connection(service, "auth"): self.assertEquals(2, len(pool.connections)) self.assertEquals(2, pool.connectionsCreated) + self.assertEquals(2, service.poolStats["connection-auth-active"]) + self.assertEquals(1, service.poolStats["connection-auth-active"]) + self.assertEquals(0, service.poolStats["connection-auth-active"]) - # Ask for three connections (one more than connectionMax/2) and + # Ask for three connections (one more than connectionMax) and # the third will actually block until the returnConnection( ) call with TestService.Connection(service, "auth"): self.assertEquals(2, len(pool.connections)) self.assertEquals(2, pool.connectionsCreated) - with TestService.Connection(service, "auth") as connection: - self.assertEquals(2, len(pool.connections)) - self.assertEquals(2, pool.connectionsCreated) - # schedule a connection to be returned in 1 second - from twisted.internet import reactor - reactor.callLater(1, pool.returnConnection, connection) + # For the 2nd connection, don't use the context manager so we can + # control when returnConnection happens + connection = pool.getConnection() + self.assertEquals(2, len(pool.connections)) + self.assertEquals(2, pool.connectionsCreated) - # For the third connection, I'm using this method so it gets - # requested in a thread, otherwise we'd hang. - yield service._authenticateUsernamePassword( - u"uid=wsanchez,cn=user,{0}".format(self.baseDN), - u"zehcnasw" - ) + # schedule connection 2 to be returned in 1 second + from twisted.internet import reactor + reactor.callLater(1, pool.returnConnection, connection) - # Proof we bumped up against connection-max: - self.assertEquals(1, service.poolStats["connection-blocked"]) + # For the third connection, I'm using this method so it gets + # requested in a thread, otherwise we'd hang. + yield service._authenticateUsernamePassword( + u"uid=wsanchez,cn=user,{0}".format(self.baseDN), + u"zehcnasw" + ) + # Proof we bumped up against connectionMax: + self.assertEquals(1, service.poolStats["connection-auth-blocked"]) + self.assertEquals(2, len(pool.connections)) self.assertEquals(2, pool.connectionsCreated) - self.assertEquals(2, service.poolStats["connection-max"]) + self.assertEquals(2, service.poolStats["connection-auth-max"]) + self.assertEquals(0, service.poolStats["connection-auth-active"])