From 12706734b65896e23216b6c8e19dd47f0d9f2d1b Mon Sep 17 00:00:00 2001 From: James Robinson Date: Thu, 16 Jan 2025 11:15:09 +0000 Subject: [PATCH 1/6] :recycle: Use Twisted PythonLoggingObserver to pass messages through to standard Python logging. --- apricot/apricot_server.py | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/apricot/apricot_server.py b/apricot/apricot_server.py index 28a2638..04f03ec 100644 --- a/apricot/apricot_server.py +++ b/apricot/apricot_server.py @@ -1,7 +1,7 @@ from __future__ import annotations import inspect -import sys +import logging from typing import TYPE_CHECKING, Any, Self, cast from twisted.internet import reactor, task @@ -61,8 +61,14 @@ def __init__( """ self.debug = debug - # Log to stdout - log.startLogging(sys.stdout) + # Set up Python logging and add this as a Twisted observer + logging.basicConfig( + level=logging.DEBUG if debug else logging.INFO, + datefmt=r"%Y-%m-%d %H:%M:%S", + format=r"%(asctime)s [%(levelname)-8s] %(message)s", + ) + observer = log.PythonLoggingObserver("apricot") + observer.start() # Initialise the UID cache uid_cache: UidCache From 1f45ef37caa01fd0da56f94687c9520dcfad0694 Mon Sep 17 00:00:00 2001 From: James Robinson Date: Thu, 16 Jan 2025 11:53:36 +0000 Subject: [PATCH 2/6] :recycle: Replace twisted.python.log with twisted.logger.Logger --- apricot/apricot_server.py | 44 ++++++----- apricot/ldap/oauth_ldap_entry.py | 9 ++- apricot/ldap/oauth_ldap_tree.py | 42 ++++++----- apricot/ldap/read_only_ldap_server.py | 73 +++++++------------ apricot/oauth/keycloak_client.py | 6 +- apricot/oauth/microsoft_entra_client.py | 16 ++-- apricot/oauth/oauth_client.py | 23 ++++-- apricot/oauth/oauth_data_adaptor.py | 97 ++++++++++++++++--------- pyproject.toml | 1 + 9 files changed, 171 insertions(+), 140 deletions(-) diff --git a/apricot/apricot_server.py b/apricot/apricot_server.py index 04f03ec..89007c0 100644 --- a/apricot/apricot_server.py +++ b/apricot/apricot_server.py @@ -6,6 +6,7 @@ from twisted.internet import reactor, task from twisted.internet.endpoints import quoteStringArgument, serverFromString +from twisted.logger import Logger from twisted.python import log from apricot.cache import LocalCache, RedisCache, UidCache @@ -62,6 +63,7 @@ def __init__( self.debug = debug # Set up Python logging and add this as a Twisted observer + self.logger = Logger() logging.basicConfig( level=logging.DEBUG if debug else logging.INFO, datefmt=r"%Y-%m-%d %H:%M:%S", @@ -73,18 +75,22 @@ def __init__( # Initialise the UID cache uid_cache: UidCache if redis_host and redis_port: - log.msg( - f"Using a Redis user-id cache at host '{redis_host}' on port '{redis_port}'.", + self.logger.info( + "Using a Redis user-id cache at host '{host}' on port '{port}'.", + host=redis_host, + port=redis_port, ) uid_cache = RedisCache(redis_host=redis_host, redis_port=redis_port) else: - log.msg("Using a local user-id cache.") + self.logger.info("Using a local user-id cache.") uid_cache = LocalCache() # Initialise the appropriate OAuth client try: - if self.debug: - log.msg(f"Creating an OAuthClient for {backend}.") + self.logger.info( + "Creating an OAuthClient for the '{backend}' backend.", + backend=backend.value, + ) oauth_backend = OAuthClientMap[backend] oauth_backend_args = inspect.getfullargspec( oauth_backend.__init__, # type: ignore[misc] @@ -97,12 +103,11 @@ def __init__( **{k: v for k, v in kwargs.items() if k in oauth_backend_args}, ) except Exception as exc: - msg = f"Could not construct an OAuth client for the '{backend}' backend.\n{exc!s}" + msg = f"Could not construct an OAuth client for the '{backend.value}' backend.\n{exc!s}" raise ValueError(msg) from exc # Initialise the OAuth data adaptor - if self.debug: - log.msg("Creating an OAuthDataAdaptor.") + self.logger.info("Creating an OAuthDataAdaptor.") oauth_adaptor = OAuthDataAdaptor( domain, oauth_client, @@ -112,8 +117,7 @@ def __init__( ) # Create an LDAPServerFactory - if self.debug: - log.msg("Creating an LDAPServerFactory.") + self.logger.info("Creating an LDAPServerFactory.") factory = OAuthLDAPServerFactory( oauth_adaptor, oauth_client, @@ -122,16 +126,15 @@ def __init__( ) if background_refresh: - if self.debug: - log.msg( - f"Starting background refresh (interval={refresh_interval})", - ) + self.logger.info( + "Starting background refresh (interval={interval})", + interval=refresh_interval, + ) loop = task.LoopingCall(factory.adaptor.refresh) loop.start(refresh_interval) # Attach a listening endpoint - if self.debug: - log.msg("Attaching a listening endpoint (plain).") + self.logger.info("Listening for LDAP requests on port {port}.", port=port) endpoint: IStreamServerEndpoint = serverFromString(reactor, f"tcp:{port}") endpoint.listen(factory) @@ -143,8 +146,10 @@ def __init__( if not tls_private_key: msg = "No TLS private key provided. Please provide one with --tls-private-key or disable TLS." raise ValueError(msg) - if self.debug: - log.msg("Attaching a listening endpoint (TLS).") + self.logger.info( + "Listening for LDAPS requests on port {port}.", + port=tls_port, + ) ssl_endpoint: IStreamServerEndpoint = serverFromString( reactor, f"ssl:{tls_port}:privateKey={quoteStringArgument(tls_private_key)}:certKey={quoteStringArgument(tls_certificate)}", @@ -156,6 +161,5 @@ def __init__( def run(self: Self) -> None: """Start the Twisted reactor.""" - if self.debug: - log.msg("Starting the Twisted reactor.") + self.logger.info("Starting the Twisted reactor.") self.reactor.run() diff --git a/apricot/ldap/oauth_ldap_entry.py b/apricot/ldap/oauth_ldap_entry.py index 7b7fdc7..f10e2e7 100644 --- a/apricot/ldap/oauth_ldap_entry.py +++ b/apricot/ldap/oauth_ldap_entry.py @@ -12,7 +12,7 @@ LDAPInvalidCredentials, ) from twisted.internet import defer -from twisted.python import log +from twisted.logger import Logger from apricot.oauth import LDAPAttributeDict, OAuthClient @@ -35,6 +35,7 @@ def __init__( @param attributes: Attributes of the object. @param oauth_client: An OAuth client used for binding """ + self.logger = Logger() self.oauth_client_ = oauth_client if not isinstance(dn, DistinguishedName): dn = DistinguishedName(stringValue=dn) @@ -73,7 +74,10 @@ def add_child( try: output = self.addChild(rdn, attributes) except LDAPEntryAlreadyExists: - log.msg(f"Refusing to add child '{rdn.getText()}' as it already exists.") + self.logger.warn( + "Refusing to add child '{child}' as it already exists.", + child=rdn.getText(), + ) output = self._children[rdn.getText()] return cast("OAuthLDAPEntry", output) @@ -84,6 +88,7 @@ def _bind(password: bytes) -> OAuthLDAPEntry: if self.oauth_client.verify(username=oauth_username, password=s_password): return self msg = f"Invalid password for user '{oauth_username}'." + self.logger.error(msg) raise LDAPInvalidCredentials(msg) return defer.maybeDeferred(_bind, password) diff --git a/apricot/ldap/oauth_ldap_tree.py b/apricot/ldap/oauth_ldap_tree.py index 2b7f93f..4bb1a7e 100644 --- a/apricot/ldap/oauth_ldap_tree.py +++ b/apricot/ldap/oauth_ldap_tree.py @@ -5,7 +5,7 @@ from ldaptor.interfaces import IConnectedLDAPEntry, ILDAPEntry from ldaptor.protocols.ldap.distinguishedname import DistinguishedName -from twisted.python import log +from twisted.logger import Logger from zope.interface import implementer from apricot.ldap.oauth_ldap_entry import OAuthLDAPEntry @@ -38,6 +38,7 @@ def __init__( self.background_refresh = background_refresh self.debug = oauth_client.debug self.last_update = time.monotonic() + self.logger = Logger() self.oauth_adaptor = oauth_adaptor self.oauth_client = oauth_client self.refresh_interval = refresh_interval @@ -72,8 +73,7 @@ def lookup(self: Self, dn: DistinguishedName | str) -> defer.Deferred[ILDAPEntry """ if not isinstance(dn, DistinguishedName): dn = DistinguishedName(stringValue=dn) - if self.debug: - log.msg(f"Starting an LDAP lookup for '{dn.getText()}'.") + self.logger.debug("Starting an LDAP lookup for '{dn}'.", dn=dn.getText()) return self.root.lookup(dn) def refresh(self: Self) -> None: @@ -83,11 +83,11 @@ def refresh(self: Self) -> None: or (time.monotonic() - self.last_update) > self.refresh_interval ): # Update users and groups from the OAuth server - log.msg("Retrieving OAuth data.") + self.logger.info("Retrieving OAuth data.") oauth_groups, oauth_users = self.oauth_adaptor.retrieve_all() # Create a root node for the tree - log.msg("Rebuilding LDAP tree.") + self.logger.info("Rebuilding LDAP tree.") self.root_ = OAuthLDAPEntry( dn=self.oauth_adaptor.root_dn, attributes={"objectClass": ["dcObject"]}, @@ -105,31 +105,37 @@ def refresh(self: Self) -> None: ) # Add groups to the groups OU - if self.debug: - log.msg( - f"Attempting to add {len(oauth_groups)} groups to the LDAP tree.", - ) + self.logger.debug( + "Attempting to add {n_groups} groups to the LDAP tree.", + n_groups=len(oauth_groups), + ) for group_attrs in oauth_groups: groups_ou.add_child(f"CN={group_attrs.cn}", group_attrs.to_dict()) if self.debug: children = groups_ou.list_children() for child in children: - log.msg(f"... {child.dn.getText()}") - log.msg(f"There are {len(children)} groups in the LDAP tree.") + self.logger.info("... {child}", child=child.dn.getText()) + self.logger.info( + "There are {n_groups} groups in the LDAP tree.", + n_groups=len(children), + ) # Add users to the users OU - if self.debug: - log.msg( - f"Attempting to add {len(oauth_users)} users to the LDAP tree.", - ) + self.logger.debug( + "Attempting to add {n_users} users to the LDAP tree.", + n_users=len(oauth_users), + ) for user_attrs in oauth_users: users_ou.add_child(f"CN={user_attrs.cn}", user_attrs.to_dict()) if self.debug: children = users_ou.list_children() for child in children: - log.msg(f"... {child.dn.getText()}") - log.msg(f"There are {len(children)} users in the LDAP tree.") + self.logger.info("... {child}", child=child.dn.getText()) + self.logger.info( + "There are {n_users} users in the LDAP tree.", + n_users=len(children), + ) # Set last updated time - log.msg("Finished building LDAP tree.") + self.logger.info("Finished building LDAP tree.") self.last_update = time.monotonic() diff --git a/apricot/ldap/read_only_ldap_server.py b/apricot/ldap/read_only_ldap_server.py index c9f08f4..ff87698 100644 --- a/apricot/ldap/read_only_ldap_server.py +++ b/apricot/ldap/read_only_ldap_server.py @@ -4,7 +4,7 @@ from ldaptor.protocols.ldap.ldaperrors import LDAPProtocolError from ldaptor.protocols.ldap.ldapserver import LDAPServer -from twisted.python import log +from twisted.logger import Logger if TYPE_CHECKING: from ldaptor.interfaces import ILDAPEntry @@ -35,6 +35,7 @@ def __init__(self: Self, *, debug: bool = False) -> None: @param debug: Enable debug output """ + self.logger = Logger() super().__init__() self.debug = debug @@ -44,14 +45,12 @@ def getRootDSE( # noqa: N802 reply: Callable[[LDAPSearchResultEntry], None] | None, ) -> LDAPSearchResultDone: """Handle an LDAP Root DSE request.""" - if self.debug: - log.msg("Handling an LDAP Root DSE request.") try: + self.logger.debug("Handling an LDAP Root DSE request.") return super().getRootDSE(request, reply) except Exception as exc: - msg = f"LDAP Root DSE request failed. {exc}" - if self.debug: - log.msg(msg) + msg = f"LDAP Root DSE request failed. {exc!s}" + self.logger.error(msg) # noqa: TRY400 raise LDAPProtocolError(msg) from exc def handle_LDAPAddRequest( # noqa: N802 @@ -62,11 +61,9 @@ def handle_LDAPAddRequest( # noqa: N802 ) -> defer.Deferred[ILDAPEntry]: """Refuse to handle an LDAP add request.""" id((request, controls, reply)) # ignore unused arguments - if self.debug: - log.msg("Handling an LDAP add request.") + self.logger.debug("Handling an LDAP add request.") msg = "ReadOnlyLDAPServer will not handle LDAP add requests" - if self.debug: - log.msg(msg) + self.logger.error(msg) raise LDAPProtocolError(msg) def handle_LDAPBindRequest( # noqa: N802 @@ -76,14 +73,12 @@ def handle_LDAPBindRequest( # noqa: N802 reply: Callable[..., None] | None, ) -> defer.Deferred[ILDAPEntry]: """Handle an LDAP bind request.""" - if self.debug: - log.msg("Handling an LDAP bind request.") try: + self.logger.debug("Handling an LDAP bind request.") return super().handle_LDAPBindRequest(request, controls, reply) except Exception as exc: - msg = f"LDAP bind request failed. {exc}" - if self.debug: - log.msg(msg) + msg = f"LDAP bind request failed. {exc!s}" + self.logger.error(msg) # noqa: TRY400 raise LDAPProtocolError(msg) from exc def handle_LDAPCompareRequest( # noqa: N802 @@ -93,14 +88,12 @@ def handle_LDAPCompareRequest( # noqa: N802 reply: Callable[..., None] | None, ) -> defer.Deferred[ILDAPEntry]: """Handle an LDAP compare request.""" - if self.debug: - log.msg("Handling an LDAP compare request.") try: + self.logger.debug("Handling an LDAP compare request.") return super().handle_LDAPCompareRequest(request, controls, reply) except Exception as exc: - msg = f"LDAP compare request failed. {exc}" - if self.debug: - log.msg(msg) + msg = f"LDAP compare request failed. {exc!s}" + self.logger.error(msg) # noqa: TRY400 raise LDAPProtocolError(msg) from exc def handle_LDAPDelRequest( # noqa: N802 @@ -111,11 +104,9 @@ def handle_LDAPDelRequest( # noqa: N802 ) -> defer.Deferred[ILDAPEntry]: """Refuse to handle an LDAP delete request.""" id((request, controls, reply)) # ignore unused arguments - if self.debug: - log.msg("Handling an LDAP delete request.") + self.logger.debug("Handling an LDAP delete request.") msg = "ReadOnlyLDAPServer will not handle LDAP delete requests" - if self.debug: - log.msg(msg) + self.logger.error(msg) raise LDAPProtocolError(msg) def handle_LDAPExtendedRequest( # noqa: N802 @@ -125,14 +116,12 @@ def handle_LDAPExtendedRequest( # noqa: N802 reply: Callable[..., None] | None, ) -> defer.Deferred[ILDAPEntry]: """Handle an LDAP extended request.""" - if self.debug: - log.msg("Handling an LDAP extended request.") try: + self.logger.debug("Handling an LDAP extended request.") return super().handle_LDAPExtendedRequest(request, controls, reply) except Exception as exc: - msg = f"LDAP extended request failed. {exc}" - if self.debug: - log.msg(msg) + msg = f"LDAP extended request failed. {exc!s}" + self.logger.error(msg) # noqa: TRY400 raise LDAPProtocolError(msg) from exc def handle_LDAPModifyDNRequest( # noqa: N802 @@ -142,12 +131,10 @@ def handle_LDAPModifyDNRequest( # noqa: N802 reply: Callable[..., None] | None, ) -> defer.Deferred[ILDAPEntry]: """Refuse to handle an LDAP modify DN request.""" - if self.debug: - log.msg("Handling an LDAP modify DN request.") + self.logger.debug("Handling an LDAP modify DN request.") id((request, controls, reply)) # ignore unused arguments msg = "ReadOnlyLDAPServer will not handle LDAP modify DN requests" - if self.debug: - log.msg(msg) + self.logger.error(msg) raise LDAPProtocolError(msg) def handle_LDAPModifyRequest( # noqa: N802 @@ -157,10 +144,10 @@ def handle_LDAPModifyRequest( # noqa: N802 reply: Callable[..., None] | None, ) -> defer.Deferred[ILDAPEntry]: """Refuse to handle an LDAP modify request.""" - if self.debug: - log.msg("Handling an LDAP modify request.") + self.logger.debug("Handling an LDAP modify request.") id((request, controls, reply)) # ignore unused arguments msg = "ReadOnlyLDAPServer will not handle LDAP modify requests" + self.logger.error(msg) raise LDAPProtocolError(msg) def handle_LDAPSearchRequest( # noqa: N802 @@ -170,14 +157,12 @@ def handle_LDAPSearchRequest( # noqa: N802 reply: Callable[[LDAPSearchResultEntry], None] | None, ) -> defer.Deferred[ILDAPEntry]: """Handle an LDAP search request.""" - if self.debug: - log.msg("Handling an LDAP search request.") try: + self.logger.debug("Handling an LDAP search request.") return super().handle_LDAPSearchRequest(request, controls, reply) except Exception as exc: - msg = f"LDAP search request failed. {exc}" - if self.debug: - log.msg(msg) + msg = f"LDAP search request failed. {exc!s}" + self.logger.error(msg) # noqa: TRY400 raise LDAPProtocolError(msg) from exc def handle_LDAPUnbindRequest( # noqa: N802 @@ -187,12 +172,10 @@ def handle_LDAPUnbindRequest( # noqa: N802 reply: Callable[..., None] | None, ) -> None: """Handle an LDAP unbind request.""" - if self.debug: - log.msg("Handling an LDAP unbind request.") try: + self.logger.debug("Handling an LDAP unbind request.") super().handle_LDAPUnbindRequest(request, controls, reply) except Exception as exc: - msg = f"LDAP unbind request failed. {exc}" - if self.debug: - log.msg(msg) + msg = f"LDAP unbind request failed. {exc!s}" + self.logger.error(msg) # noqa: TRY400 raise LDAPProtocolError(msg) from exc diff --git a/apricot/oauth/keycloak_client.py b/apricot/oauth/keycloak_client.py index 6b557c7..e01cc60 100644 --- a/apricot/oauth/keycloak_client.py +++ b/apricot/oauth/keycloak_client.py @@ -3,8 +3,6 @@ import operator from typing import TYPE_CHECKING, Any, Self, cast -from twisted.python import log - from .oauth_client import OAuthClient if TYPE_CHECKING: @@ -105,7 +103,7 @@ def groups(self: Self) -> list[JSONDict]: output.append(attributes) except KeyError as exc: msg = f"Failed to process group {group_dict} due to a missing key {exc}." - log.msg(msg) + self.logger.warn(msg) return output def users(self: Self) -> list[JSONDict]: @@ -178,5 +176,5 @@ def users(self: Self) -> list[JSONDict]: output.append(attributes) except KeyError as exc: msg = f"Failed to process user {user_dict} due to a missing key {exc}." - log.msg(msg) + self.logger.warn(msg) return output diff --git a/apricot/oauth/microsoft_entra_client.py b/apricot/oauth/microsoft_entra_client.py index cd67b3b..0b7f7b2 100644 --- a/apricot/oauth/microsoft_entra_client.py +++ b/apricot/oauth/microsoft_entra_client.py @@ -3,8 +3,6 @@ import operator from typing import TYPE_CHECKING, Any, Self, cast -from twisted.python import log - from .oauth_client import OAuthClient if TYPE_CHECKING: @@ -72,10 +70,11 @@ def groups(self: Self) -> list[JSONDict]: ] output.append(attributes) except KeyError as exc: - msg = ( - f"Failed to process group {group_dict} due to a missing key {exc}." + self.logger.warn( + "Failed to process group {group} due to a missing key {key}.", + group=group_dict, + key=str(exc), ) - log.msg(msg) return output def users(self: Self) -> list[JSONDict]: @@ -116,6 +115,9 @@ def users(self: Self) -> list[JSONDict]: attributes["uidNumber"] = user_uid output.append(attributes) except KeyError as exc: - msg = f"Failed to process user {user_dict} due to a missing key {exc}." - log.msg(msg) + self.logger.warn( + "Failed to process user {user} due to a missing key {key}.", + user=user_dict, + key=str(exc), + ) return output diff --git a/apricot/oauth/oauth_client.py b/apricot/oauth/oauth_client.py index 6857626..676e73c 100644 --- a/apricot/oauth/oauth_client.py +++ b/apricot/oauth/oauth_client.py @@ -13,7 +13,7 @@ TokenExpiredError, ) from requests_oauthlib import OAuth2Session -from twisted.python import log +from twisted.logger import Logger if TYPE_CHECKING: from apricot.cache import UidCache @@ -48,6 +48,7 @@ def __init__( self.bearer_token_: str | None = None self.client_secret = client_secret self.debug = debug + self.logger = Logger() self.token_url = token_url self.uid_cache = uid_cache # Allow token scope to not match requested scope. (Other auth libraries allow @@ -57,8 +58,7 @@ def __init__( try: # OAuth client that uses application credentials - if self.debug: - log.msg("Initialising application credential client.") + self.logger.debug("Initialising application credential client.") self.session_application = OAuth2Session( client=BackendApplicationClient( client_id=client_id, @@ -72,8 +72,7 @@ def __init__( try: # OAuth client that uses delegated credentials - if self.debug: - log.msg("Initialising delegated credential client.") + self.logger.debug("Initialising delegated credential client.") self.session_interactive = OAuth2Session( client=LegacyApplicationClient( client_id=client_id, @@ -83,6 +82,7 @@ def __init__( ) except Exception as exc: msg = f"Failed to initialise delegated credential client.\n{exc!s}" + self.logger.error(msg) # noqa: TRY400 raise RuntimeError(msg) from exc @property @@ -90,7 +90,9 @@ def bearer_token(self: Self) -> str: """Return a bearer token, requesting a new one if necessary.""" try: if not self.bearer_token_: - log.msg("Requesting a new authentication token from the OAuth backend.") + self.logger.info( + "Requesting a new authentication token from the OAuth backend.", + ) json_response = self.session_application.fetch_token( token_url=self.token_url, client_id=self.session_application._client.client_id, @@ -99,6 +101,7 @@ def bearer_token(self: Self) -> str: self.bearer_token_ = self.extract_token(json_response) except Exception as exc: msg = f"Failed to fetch bearer token from OAuth endpoint.\n{exc!s}" + self.logger.error(msg) # noqa: TRY400 raise RuntimeError(msg) from exc else: return self.bearer_token_ @@ -163,7 +166,7 @@ def request_(*args: Any, **kwargs: Any) -> requests.Response: result = request_(*args, **kwargs) result.raise_for_status() except (TokenExpiredError, requests.exceptions.HTTPError) as exc: - log.msg(f"Authentication token is invalid.\n{exc!s}") + self.logger.warn("Authentication token is invalid.\n{error}", error=exc) self.bearer_token_ = None result = request_(*args, **kwargs) if result.status_code == HTTPStatus.NO_CONTENT: @@ -181,7 +184,11 @@ def verify(self: Self, username: str, password: str) -> bool: client_secret=self.client_secret, ) except InvalidGrantError as exc: - log.msg(f"Authentication failed for user '{username}'.\n{exc!s}") + self.logger.warn( + "Authentication failed for user '{user}'.\n{error}", + user=username, + error=str(exc), + ) return False else: return True diff --git a/apricot/oauth/oauth_data_adaptor.py b/apricot/oauth/oauth_data_adaptor.py index 81722ea..a378304 100644 --- a/apricot/oauth/oauth_data_adaptor.py +++ b/apricot/oauth/oauth_data_adaptor.py @@ -3,7 +3,7 @@ from typing import TYPE_CHECKING, Self from pydantic import ValidationError -from twisted.python import log +from twisted.logger import Logger from apricot.models import ( LDAPAttributeAdaptor, @@ -45,11 +45,12 @@ def __init__( """ self.debug = oauth_client.debug self.domain = domain - self.oauth_client = oauth_client - self.root_dn = "DC=" + domain.replace(".", ",DC=") self.enable_mirrored_groups = enable_mirrored_groups self.enable_primary_groups = enable_primary_groups self.enable_user_domain_verification = enable_user_domain_verification + self.logger = Logger() + self.oauth_client = oauth_client + self.root_dn = "DC=" + domain.replace(".", ",DC=") def _dn_from_group_cn(self: Self, group_cn: str) -> str: return f"CN={group_cn},OU=groups,{self.root_dn}" @@ -67,10 +68,11 @@ def _retrieve_entries( # Get the initial set of users and groups oauth_groups = self.oauth_client.groups() oauth_users = self.oauth_client.users() - if self.debug: - log.msg( - f"Loaded {len(oauth_groups)} groups and {len(oauth_users)} users from OAuth client.", - ) + self.logger.debug( + "Loaded {n_groups} groups and {n_users} users from OAuth client.", + n_groups=len(oauth_groups), + n_users=len(oauth_users), + ) # Ensure member is set for groups for group_dict in oauth_groups: @@ -117,11 +119,12 @@ def _retrieve_entries( for parent_dict in oauth_groups + user_primary_groups + groups_of_groups if child_dn in parent_dict["member"] ] - if self.debug: - for group_name in child_dict["memberOf"]: - log.msg( - f"... user '{child_dict['cn']}' is a member of '{group_name}'", - ) + for group_name in child_dict["memberOf"]: + self.logger.debug( + "... user '{user}' is a member of '{group_name}'", + user=child_dict["cn"], + group_name=group_name, + ) # Ensure memberOf is set correctly for groups for child_dict in oauth_groups + user_primary_groups + groups_of_groups: @@ -131,11 +134,12 @@ def _retrieve_entries( for parent_dict in oauth_groups + user_primary_groups + groups_of_groups if child_dn in parent_dict["member"] ] - if self.debug: - for group_name in child_dict["memberOf"]: - log.msg( - f"... group '{child_dict['cn']}' is a member of '{group_name}'", - ) + for group_name in child_dict["memberOf"]: + self.logger.debug( + "... group '{group}' is a member of '{group_name}'", + group=child_dict["cn"], + group_name=group_name, + ) # Annotate group and user dicts with the appropriate LDAP classes annotated_groups = [ @@ -171,8 +175,10 @@ def _validate_groups( annotated_groups: list[tuple[JSONDict, list[type[LDAPObjectClass]]]], ) -> list[LDAPAttributeAdaptor]: """Return a list of LDAPAttributeAdaptors representing validated group data.""" - if self.debug: - log.msg(f"Attempting to validate {len(annotated_groups)} groups.") + self.logger.debug( + "Attempting to validate {n_groups} groups.", + n_groups=len(annotated_groups), + ) output = [] for group_dict, required_classes in annotated_groups: try: @@ -183,12 +189,18 @@ def _validate_groups( ), ) except ValidationError as exc: - name = group_dict.get("cn", "unknown") - log.msg(f"... group '{name}' failed validation.") + self.logger.warn( + "... group '{group_name}' failed validation.", + group_name=group_dict.get("cn", "unknown"), + ) for error in exc.errors(): - log.msg( - f" -> '{error['loc'][0]}': {error['msg']} but '{error['input']}' was provided.", + self.logger.warn( + " -> '{attribute}': {expected} but '{actual}' was provided.", + attribute=error["loc"][0], + expected=error["msg"], + actual=error["input"], ) + return output def _validate_users( @@ -196,20 +208,26 @@ def _validate_users( annotated_users: list[tuple[JSONDict, list[type[LDAPObjectClass]]]], ) -> list[LDAPAttributeAdaptor]: """Return a list of LDAPAttributeAdaptors representing validated user data.""" - if self.debug: - log.msg(f"Attempting to validate {len(annotated_users)} users.") + self.logger.debug( + "Attempting to validate {n_users} users.", + n_users=len(annotated_users), + ) output = [] for user_dict, required_classes in annotated_users: - name = user_dict.get("cn", "unknown") try: # Verify user domain if enabled if ( self.enable_user_domain_verification and (user_domain := user_dict.get("domain", None)) != self.domain ): - log.msg(f"... user '{name}' failed validation.") - log.msg( - f" -> 'domain': expected '{self.domain}' but '{user_domain}' was provided.", + self.logger.warn( + "... user '{user_name}' failed validation.", + user_name=user_dict.get("cn", "unknown"), + ) + self.logger.warn( + " -> 'domain': expected '{expected_domain}' but '{actual_domain}' was provided.", + expected_domain=self.domain, + actual_domain=user_domain, ) continue # Construct an LDAPAttributeAdaptor from the user attributes @@ -220,10 +238,16 @@ def _validate_users( ), ) except ValidationError as exc: - log.msg(f"... user '{name}' failed validation.") + self.logger.warn( + "... user '{user_name}' failed validation.", + user_name=user_dict.get("cn", "unknown"), + ) for error in exc.errors(): - log.msg( - f" -> '{error['loc'][0]}': {error['msg']} but '{error['input']}' was provided.", + self.logger.warn( + " -> '{attribute}': {expected} but '{actual}' was provided.", + attribute=error["loc"][0], + expected=error["msg"], + actual=error["input"], ) return output @@ -234,8 +258,9 @@ def retrieve_all( annotated_groups, annotated_users = self._retrieve_entries() validated_groups = self._validate_groups(annotated_groups) validated_users = self._validate_users(annotated_users) - if self.debug: - log.msg( - f"Validated {len(validated_groups)} groups and {len(validated_users)} users.", - ) + self.logger.debug( + "Validated {n_groups} groups and {n_users} users.", + n_groups=len(validated_groups), + n_users=len(validated_users), + ) return (validated_groups, validated_users) diff --git a/pyproject.toml b/pyproject.toml index 93c6324..ecb275c 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -146,6 +146,7 @@ ignore = [ "D213", # multi-line-summary-second-line due to conflict with D212 "E501", # line length "C901", # complex-structure + "G010", # logging-warn due to incorrect heuristic "PLR0912", # too-many-branches "PLR0913", # too-many-arguments "PLR0917", # too-many-positional-arguments From 027dba9420f5e183bea40496ddaededc46fe8aae Mon Sep 17 00:00:00 2001 From: James Robinson Date: Wed, 15 Jan 2025 15:37:16 +0000 Subject: [PATCH 3/6] :sparkles: Add debug callbacks to LDAP lookup --- apricot/ldap/oauth_ldap_tree.py | 30 +++++++++++++++++++++++++++--- 1 file changed, 27 insertions(+), 3 deletions(-) diff --git a/apricot/ldap/oauth_ldap_tree.py b/apricot/ldap/oauth_ldap_tree.py index 4bb1a7e..675247f 100644 --- a/apricot/ldap/oauth_ldap_tree.py +++ b/apricot/ldap/oauth_ldap_tree.py @@ -12,6 +12,7 @@ if TYPE_CHECKING: from twisted.internet import defer + from twisted.python.failure import Failure from apricot.oauth import OAuthClient, OAuthDataAdaptor @@ -67,14 +68,37 @@ def __repr__(self: Self) -> str: return f"{self.__class__.__name__} with backend {self.oauth_client.__class__.__name__}" def lookup(self: Self, dn: DistinguishedName | str) -> defer.Deferred[ILDAPEntry]: - """Lookup the referred to by dn. + """Lookup a DistinguishedName in the LDAP tree. @return: A Deferred returning an ILDAPEntry. """ + + def result_callback(ldap_entry: OAuthLDAPEntry | None) -> OAuthLDAPEntry | None: + if ldap_entry: + self.logger.debug( + "LDAP lookup succeeded: found {dn}", + dn=ldap_entry.dn.getText(), + ) + return ldap_entry + + def failure_callback(failure: Failure) -> Failure: + self.logger.debug( + "LDAP lookup failed: {error}", + error=failure.getErrorMessage(), + ) + return failure + + # Construct a complete DN if not isinstance(dn, DistinguishedName): dn = DistinguishedName(stringValue=dn) - self.logger.debug("Starting an LDAP lookup for '{dn}'.", dn=dn.getText()) - return self.root.lookup(dn) + self.logger.info("Starting an LDAP lookup for '{dn}'.", dn=dn.getText()) + + # Attach debug callbacks to the lookup and return + return ( + self.root.lookup(dn) + .addErrback(failure_callback) + .addCallback(result_callback) + ) def refresh(self: Self) -> None: """Refresh the LDAP tree.""" From 94f452bb9b966ea738a4390044ce59838ff639df Mon Sep 17 00:00:00 2001 From: James Robinson Date: Thu, 16 Jan 2025 16:39:01 +0000 Subject: [PATCH 4/6] :bug: Only set debug log level for Apricot, not at logging root --- apricot/apricot_server.py | 19 +++++++++++-------- apricot/ldap/oauth_ldap_tree.py | 31 ++++++++++++++++--------------- apricot/oauth/oauth_client.py | 4 ++-- 3 files changed, 29 insertions(+), 25 deletions(-) diff --git a/apricot/apricot_server.py b/apricot/apricot_server.py index 89007c0..a7d5e8b 100644 --- a/apricot/apricot_server.py +++ b/apricot/apricot_server.py @@ -62,15 +62,19 @@ def __init__( """ self.debug = debug - # Set up Python logging and add this as a Twisted observer - self.logger = Logger() + # Set up Python root logger logging.basicConfig( - level=logging.DEBUG if debug else logging.INFO, + level=logging.INFO, datefmt=r"%Y-%m-%d %H:%M:%S", format=r"%(asctime)s [%(levelname)-8s] %(message)s", ) + if debug: + logging.getLogger("apricot").setLevel(logging.DEBUG) + + # Configure Twisted loggers to write to Python logging observer = log.PythonLoggingObserver("apricot") observer.start() + self.logger = Logger() # Initialise the UID cache uid_cache: UidCache @@ -87,7 +91,7 @@ def __init__( # Initialise the appropriate OAuth client try: - self.logger.info( + self.logger.debug( "Creating an OAuthClient for the '{backend}' backend.", backend=backend.value, ) @@ -107,7 +111,7 @@ def __init__( raise ValueError(msg) from exc # Initialise the OAuth data adaptor - self.logger.info("Creating an OAuthDataAdaptor.") + self.logger.debug("Creating an OAuthDataAdaptor.") oauth_adaptor = OAuthDataAdaptor( domain, oauth_client, @@ -116,8 +120,8 @@ def __init__( enable_user_domain_verification=enable_user_domain_verification, ) - # Create an LDAPServerFactory - self.logger.info("Creating an LDAPServerFactory.") + # Create an OAuthLDAPServerFactory + self.logger.debug("Creating an OAuthLDAPServerFactory.") factory = OAuthLDAPServerFactory( oauth_adaptor, oauth_client, @@ -161,5 +165,4 @@ def __init__( def run(self: Self) -> None: """Start the Twisted reactor.""" - self.logger.info("Starting the Twisted reactor.") self.reactor.run() diff --git a/apricot/ldap/oauth_ldap_tree.py b/apricot/ldap/oauth_ldap_tree.py index 675247f..fe1b123 100644 --- a/apricot/ldap/oauth_ldap_tree.py +++ b/apricot/ldap/oauth_ldap_tree.py @@ -135,13 +135,15 @@ def refresh(self: Self) -> None: ) for group_attrs in oauth_groups: groups_ou.add_child(f"CN={group_attrs.cn}", group_attrs.to_dict()) - if self.debug: - children = groups_ou.list_children() - for child in children: - self.logger.info("... {child}", child=child.dn.getText()) - self.logger.info( - "There are {n_groups} groups in the LDAP tree.", - n_groups=len(children), + ldap_groups = groups_ou.list_children() + self.logger.info( + "There are {n_groups} groups in the LDAP tree.", + n_groups=len(ldap_groups), + ) + for ldap_group in ldap_groups: + self.logger.debug( + "... {ldap_group}", + ldap_group=ldap_group.dn.getText(), ) # Add users to the users OU @@ -151,14 +153,13 @@ def refresh(self: Self) -> None: ) for user_attrs in oauth_users: users_ou.add_child(f"CN={user_attrs.cn}", user_attrs.to_dict()) - if self.debug: - children = users_ou.list_children() - for child in children: - self.logger.info("... {child}", child=child.dn.getText()) - self.logger.info( - "There are {n_users} users in the LDAP tree.", - n_users=len(children), - ) + ldap_users = users_ou.list_children() + self.logger.info( + "There are {n_users} users in the LDAP tree.", + n_users=len(ldap_users), + ) + for ldap_user in ldap_users: + self.logger.debug("... {ldap_user}", ldap_user=ldap_user.dn.getText()) # Set last updated time self.logger.info("Finished building LDAP tree.") diff --git a/apricot/oauth/oauth_client.py b/apricot/oauth/oauth_client.py index 676e73c..79a00c0 100644 --- a/apricot/oauth/oauth_client.py +++ b/apricot/oauth/oauth_client.py @@ -166,7 +166,7 @@ def request_(*args: Any, **kwargs: Any) -> requests.Response: result = request_(*args, **kwargs) result.raise_for_status() except (TokenExpiredError, requests.exceptions.HTTPError) as exc: - self.logger.warn("Authentication token is invalid.\n{error}", error=exc) + self.logger.warn("Authentication token is invalid. {error}", error=exc) self.bearer_token_ = None result = request_(*args, **kwargs) if result.status_code == HTTPStatus.NO_CONTENT: @@ -185,7 +185,7 @@ def verify(self: Self, username: str, password: str) -> bool: ) except InvalidGrantError as exc: self.logger.warn( - "Authentication failed for user '{user}'.\n{error}", + "Authentication failed for user '{user}'. {error}", user=username, error=str(exc), ) From 00b8dc76be2c79e0db4e3f5c0f57d8e44e5a5083 Mon Sep 17 00:00:00 2001 From: James Robinson Date: Thu, 16 Jan 2025 16:43:36 +0000 Subject: [PATCH 5/6] :art: Do not pass debug flag through class hierarchy --- apricot/apricot_server.py | 3 --- apricot/ldap/oauth_ldap_server_factory.py | 2 +- apricot/ldap/oauth_ldap_tree.py | 1 - apricot/ldap/read_only_ldap_server.py | 10 +++------- apricot/oauth/oauth_client.py | 3 --- apricot/oauth/oauth_data_adaptor.py | 1 - 6 files changed, 4 insertions(+), 16 deletions(-) diff --git a/apricot/apricot_server.py b/apricot/apricot_server.py index a7d5e8b..3612965 100644 --- a/apricot/apricot_server.py +++ b/apricot/apricot_server.py @@ -60,8 +60,6 @@ def __init__( @param tls_certificate: TLS certificate for LDAPS @param tls_private_key: TLS private key for LDAPS """ - self.debug = debug - # Set up Python root logger logging.basicConfig( level=logging.INFO, @@ -102,7 +100,6 @@ def __init__( oauth_client = oauth_backend( client_id=client_id, client_secret=client_secret, - debug=debug, uid_cache=uid_cache, **{k: v for k, v in kwargs.items() if k in oauth_backend_args}, ) diff --git a/apricot/ldap/oauth_ldap_server_factory.py b/apricot/ldap/oauth_ldap_server_factory.py index e7b828a..520d7f3 100644 --- a/apricot/ldap/oauth_ldap_server_factory.py +++ b/apricot/ldap/oauth_ldap_server_factory.py @@ -46,6 +46,6 @@ def buildProtocol(self: Self, addr: IAddress) -> Protocol: # noqa: N802 @param addr: an object implementing L{IAddress} """ id(addr) # ignore unused arguments - proto = ReadOnlyLDAPServer(debug=self.adaptor.debug) + proto = ReadOnlyLDAPServer() proto.factory = self.adaptor return proto diff --git a/apricot/ldap/oauth_ldap_tree.py b/apricot/ldap/oauth_ldap_tree.py index fe1b123..0cfc7d9 100644 --- a/apricot/ldap/oauth_ldap_tree.py +++ b/apricot/ldap/oauth_ldap_tree.py @@ -37,7 +37,6 @@ def __init__( @param refresh_interval: Interval in seconds after which the tree must be refreshed """ self.background_refresh = background_refresh - self.debug = oauth_client.debug self.last_update = time.monotonic() self.logger = Logger() self.oauth_adaptor = oauth_adaptor diff --git a/apricot/ldap/read_only_ldap_server.py b/apricot/ldap/read_only_ldap_server.py index ff87698..285daae 100644 --- a/apricot/ldap/read_only_ldap_server.py +++ b/apricot/ldap/read_only_ldap_server.py @@ -30,14 +30,10 @@ class ReadOnlyLDAPServer(LDAPServer): """A read-only LDAP server.""" - def __init__(self: Self, *, debug: bool = False) -> None: - """Initialise a ReadOnlyLDAPServer. - - @param debug: Enable debug output - """ - self.logger = Logger() + def __init__(self: Self) -> None: + """Initialise a ReadOnlyLDAPServer.""" super().__init__() - self.debug = debug + self.logger = Logger() def getRootDSE( # noqa: N802 self: Self, diff --git a/apricot/oauth/oauth_client.py b/apricot/oauth/oauth_client.py index 79a00c0..77d4c9b 100644 --- a/apricot/oauth/oauth_client.py +++ b/apricot/oauth/oauth_client.py @@ -27,7 +27,6 @@ def __init__( self: Self, client_id: str, client_secret: str, - debug: bool, # noqa: FBT001 redirect_uri: str, scopes_application: list[str], scopes_delegated: list[str], @@ -38,7 +37,6 @@ def __init__( @param client_id: OAuth client ID @param client_secret: OAuth client secret - @param debug: Enable debug output @param redirect_uri: OAuth redirect URI @param scopes: OAuth scopes @param token_url: OAuth token URL @@ -47,7 +45,6 @@ def __init__( # Set attributes self.bearer_token_: str | None = None self.client_secret = client_secret - self.debug = debug self.logger = Logger() self.token_url = token_url self.uid_cache = uid_cache diff --git a/apricot/oauth/oauth_data_adaptor.py b/apricot/oauth/oauth_data_adaptor.py index a378304..97bf043 100644 --- a/apricot/oauth/oauth_data_adaptor.py +++ b/apricot/oauth/oauth_data_adaptor.py @@ -43,7 +43,6 @@ def __init__( @param enable_user_domain_verification: Whether to verify users belong to the correct domain @param oauth_client: An OAuth client used to construct the LDAP tree """ - self.debug = oauth_client.debug self.domain = domain self.enable_mirrored_groups = enable_mirrored_groups self.enable_primary_groups = enable_primary_groups From df32e4b0365d75a4474cd788fd17cdf667eda3bd Mon Sep 17 00:00:00 2001 From: James Robinson Date: Thu, 16 Jan 2025 17:05:25 +0000 Subject: [PATCH 6/6] :truck: Move reactor initialisation --- apricot/apricot_server.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/apricot/apricot_server.py b/apricot/apricot_server.py index 3612965..b62a608 100644 --- a/apricot/apricot_server.py +++ b/apricot/apricot_server.py @@ -74,6 +74,9 @@ def __init__( observer.start() self.logger = Logger() + # Load the Twisted reactor + self.reactor = cast("IReactorCore", reactor) + # Initialise the UID cache uid_cache: UidCache if redis_host and redis_port: @@ -90,7 +93,7 @@ def __init__( # Initialise the appropriate OAuth client try: self.logger.debug( - "Creating an OAuthClient for the '{backend}' backend.", + "Creating an OAuthClient for the {backend} backend.", backend=backend.value, ) oauth_backend = OAuthClientMap[backend] @@ -104,7 +107,7 @@ def __init__( **{k: v for k, v in kwargs.items() if k in oauth_backend_args}, ) except Exception as exc: - msg = f"Could not construct an OAuth client for the '{backend.value}' backend.\n{exc!s}" + msg = f"Could not construct an OAuth client for the {backend.value} backend.\n{exc!s}" raise ValueError(msg) from exc # Initialise the OAuth data adaptor @@ -136,7 +139,7 @@ def __init__( # Attach a listening endpoint self.logger.info("Listening for LDAP requests on port {port}.", port=port) - endpoint: IStreamServerEndpoint = serverFromString(reactor, f"tcp:{port}") + endpoint: IStreamServerEndpoint = serverFromString(self.reactor, f"tcp:{port}") endpoint.listen(factory) # Attach a listening endpoint @@ -152,14 +155,11 @@ def __init__( port=tls_port, ) ssl_endpoint: IStreamServerEndpoint = serverFromString( - reactor, + self.reactor, f"ssl:{tls_port}:privateKey={quoteStringArgument(tls_private_key)}:certKey={quoteStringArgument(tls_certificate)}", ) ssl_endpoint.listen(factory) - # Load the Twisted reactor - self.reactor = cast("IReactorCore", reactor) - def run(self: Self) -> None: """Start the Twisted reactor.""" self.reactor.run()