From 0b86231a36a7965212bcd6828d6324be7c6c0309 Mon Sep 17 00:00:00 2001 From: "Langhammer, Jens" Date: Fri, 4 Oct 2019 10:21:33 +0200 Subject: [PATCH] *(minor): make better use of structured logging --- passbook/core/apps.py | 2 +- passbook/core/auth/factors/password.py | 8 ++++---- passbook/core/auth/view.py | 11 ++++++----- passbook/core/models.py | 9 +++------ passbook/core/signals.py | 2 +- passbook/oauth_client/apps.py | 2 +- passbook/oauth_client/source_types/manager.py | 2 +- passbook/root/urls.py | 2 +- passbook/saml_idp/apps.py | 2 +- passbook/suspicious_policy/signals.py | 4 ++-- 10 files changed, 21 insertions(+), 23 deletions(-) diff --git a/passbook/core/apps.py b/passbook/core/apps.py index 8ea44e28f..cc38e1fb6 100644 --- a/passbook/core/apps.py +++ b/passbook/core/apps.py @@ -22,6 +22,6 @@ class PassbookCoreConfig(AppConfig): for factors_to_load in factors_to_load: try: import_module(factors_to_load) - LOGGER.info("Loaded %s", factors_to_load) + LOGGER.info("Loaded factor", factor_class=factors_to_load) except ImportError as exc: LOGGER.debug(exc) diff --git a/passbook/core/auth/factors/password.py b/passbook/core/auth/factors/password.py index 8aba26e5b..948687c64 100644 --- a/passbook/core/auth/factors/password.py +++ b/passbook/core/auth/factors/password.py @@ -31,14 +31,14 @@ def authenticate(request, backends, **credentials): signature = Signature.from_callable(backend.authenticate) signature.bind(request, **credentials) except TypeError: - LOGGER.debug("Backend %s doesn't accept our arguments", backend) + LOGGER.debug("Backend doesn't accept our arguments", backend=backend) # This backend doesn't accept these credentials as arguments. Try the next one. continue - LOGGER.debug('Attempting authentication with %s...', backend) + LOGGER.debug('Attempting authentication...', backend=backend) try: user = backend.authenticate(request, **credentials) except PermissionDenied: - LOGGER.debug('Backend %r threw PermissionDenied', backend) + LOGGER.debug('Backend threw PermissionDenied', backend=backend) # This backend says to stop in our tracks - this user should not be allowed in at all. break if user is None: @@ -104,5 +104,5 @@ class PasswordFactor(FormView, AuthenticationFactor): return self.form_invalid(form) except PermissionDenied: # User was found, but permission was denied (i.e. user is not active) - LOGGER.debug("Denied access to %s", kwargs) + LOGGER.debug("Denied access", **kwargs) return self.authenticator.user_invalid() diff --git a/passbook/core/auth/view.py b/passbook/core/auth/view.py index 96eaf8736..5446c1c02 100644 --- a/passbook/core/auth/view.py +++ b/passbook/core/auth/view.py @@ -100,17 +100,18 @@ class AuthenticationView(UserPassesTestMixin, View): def get(self, request, *args, **kwargs): """pass get request to current factor""" - LOGGER.debug("Passing GET to %s", class_to_path(self._current_factor_class.__class__)) + LOGGER.debug("Passing GET", view_class=class_to_path(self._current_factor_class.__class__)) return self._current_factor_class.get(request, *args, **kwargs) def post(self, request, *args, **kwargs): """pass post request to current factor""" - LOGGER.debug("Passing POST to %s", class_to_path(self._current_factor_class.__class__)) + LOGGER.debug("Passing POST", view_class=class_to_path(self._current_factor_class.__class__)) return self._current_factor_class.post(request, *args, **kwargs) def user_ok(self): """Redirect to next Factor""" - LOGGER.debug("Factor %s passed", class_to_path(self._current_factor_class.__class__)) + LOGGER.debug("Factor passed", + factor_class=class_to_path(self._current_factor_class.__class__)) # Remove passed factor from pending factors current_factor_tuple = (self.current_factor.uuid.hex, class_to_path(self._current_factor_class.__class__)) @@ -123,7 +124,7 @@ class AuthenticationView(UserPassesTestMixin, View): self.request.session[AuthenticationView.SESSION_PENDING_FACTORS] = \ self.pending_factors self.request.session[AuthenticationView.SESSION_FACTOR] = next_factor - LOGGER.debug("Rendering Factor is %s", next_factor) + LOGGER.debug("Rendering Factor", next_factor=next_factor) return _redirect_with_qs('passbook_core:auth-process', self.request.GET) # User passed all factors LOGGER.debug("User passed all factors, logging in") @@ -140,7 +141,7 @@ class AuthenticationView(UserPassesTestMixin, View): """User Successfully passed all factors""" backend = self.request.session[AuthenticationView.SESSION_USER_BACKEND] login(self.request, self.pending_user, backend=backend) - LOGGER.debug("Logged in user %s", self.pending_user) + LOGGER.debug("Logged in", user=self.pending_user) # Cleanup self.cleanup() next_param = self.request.GET.get('next', None) diff --git a/passbook/core/models.py b/passbook/core/models.py index d240913bf..7b8cbe0f2 100644 --- a/passbook/core/models.py +++ b/passbook/core/models.py @@ -279,8 +279,8 @@ class FieldMatcherPolicy(Policy): if not hasattr(request.user, self.user_field): raise ValueError("Field does not exist") user_field_value = getattr(request.user, self.user_field, None) - LOGGER.debug("Checked '%s' %s with '%s'...", - user_field_value, self.match_action, self.value) + LOGGER.debug("Checking field", value=user_field_value, + action=self.match_action, should_be=self.value) passes = False if self.match_action == FieldMatcherPolicy.MATCH_STARTSWITH: passes = user_field_value.startswith(self.value) @@ -293,8 +293,6 @@ class FieldMatcherPolicy(Policy): passes = bool(pattern.match(user_field_value)) if self.match_action == FieldMatcherPolicy.MATCH_EXACT: passes = user_field_value == self.value - - LOGGER.debug("User got '%r'", passes) return PolicyResult(passes) class Meta: @@ -328,7 +326,6 @@ class PasswordPolicy(Policy): if self.amount_symbols > 0: filter_regex += r'[%s]{%d,}' % (self.symbol_charset, self.amount_symbols) result = bool(re.compile(filter_regex).match(password)) - LOGGER.debug("User got %r", result) if not result: return PolicyResult(result, self.error_message) return PolicyResult(result) @@ -387,7 +384,7 @@ class DebugPolicy(Policy): def passes(self, request: PolicyRequest) -> PolicyResult: """Wait random time then return result""" wait = SystemRandom().randrange(self.wait_min, self.wait_max) - LOGGER.debug("Policy '%s' waiting for %ds", self.name, wait) + LOGGER.debug("Policy waiting", policy=self, delay=wait) sleep(wait) return PolicyResult(self.result, 'Debugging') diff --git a/passbook/core/signals.py b/passbook/core/signals.py index 4e798f1ae..66842f1e8 100644 --- a/passbook/core/signals.py +++ b/passbook/core/signals.py @@ -35,7 +35,7 @@ def invalidate_policy_cache(sender, instance, **kwargs): """Invalidate Policy cache when policy is updated""" from passbook.core.models import Policy if isinstance(instance, Policy): - LOGGER.debug("Invalidating cache for %s", instance.pk) + LOGGER.debug("Invalidating policy cache", policy=instance) keys = cache.keys("%s#*" % instance.pk) cache.delete_many(keys) LOGGER.debug("Deleted %d keys", len(keys)) diff --git a/passbook/oauth_client/apps.py b/passbook/oauth_client/apps.py index da8af24e8..a8e12e668 100644 --- a/passbook/oauth_client/apps.py +++ b/passbook/oauth_client/apps.py @@ -22,6 +22,6 @@ class PassbookOAuthClientConfig(AppConfig): for source_type in source_types_to_load: try: import_module(source_type) - LOGGER.info("Loaded %s", source_type) + LOGGER.info("Loaded source_type", source_class=source_type) except ImportError as exc: LOGGER.debug(exc) diff --git a/passbook/oauth_client/source_types/manager.py b/passbook/oauth_client/source_types/manager.py index d3b1d53c2..389f12c0f 100644 --- a/passbook/oauth_client/source_types/manager.py +++ b/passbook/oauth_client/source_types/manager.py @@ -27,7 +27,7 @@ class SourceTypeManager: self.__source_types[kind] = {} self.__source_types[kind][name.lower()] = cls self.__names.append(name) - LOGGER.debug("Registered source '%s' for '%s'", cls.__name__, kind) + LOGGER.debug("Registered source", source_class=cls.__name__, kind=kind) return cls return inner_wrapper diff --git a/passbook/root/urls.py b/passbook/root/urls.py index 876d2f0b2..6cd579914 100644 --- a/passbook/root/urls.py +++ b/passbook/root/urls.py @@ -26,7 +26,7 @@ for _passbook_app in get_apps(): _passbook_app.label), namespace=_passbook_app.label)) urlpatterns.append(_path) - LOGGER.debug("Loaded %s's URLs", _passbook_app.name) + LOGGER.debug("Mounted URLs", app_name=_passbook_app.name) urlpatterns += [ # Administration diff --git a/passbook/saml_idp/apps.py b/passbook/saml_idp/apps.py index fd080ac32..12b146238 100644 --- a/passbook/saml_idp/apps.py +++ b/passbook/saml_idp/apps.py @@ -22,6 +22,6 @@ class PassbookSAMLIDPConfig(AppConfig): for source_type in source_types_to_load: try: import_module(source_type) - LOGGER.info("Loaded %s", source_type) + LOGGER.info("Loaded SAML Processor", processor_class=source_type) except ImportError as exc: LOGGER.debug(exc) diff --git a/passbook/suspicious_policy/signals.py b/passbook/suspicious_policy/signals.py index 9c7d5db0b..a0ca5058a 100644 --- a/passbook/suspicious_policy/signals.py +++ b/passbook/suspicious_policy/signals.py @@ -28,14 +28,14 @@ def update_score(request, username, amount): ip_score, _ = IPScore.objects.update_or_create(ip=remote_ip) ip_score.score += amount ip_score.save() - LOGGER.debug("Added %s to score of IP %s", amount, remote_ip) + LOGGER.debug("Updated score", amount=amount, for_ip=remote_ip) user = User.objects.filter(username=username) if not user.exists(): return user_score, _ = UserScore.objects.update_or_create(user=user.first()) user_score.score += amount user_score.save() - LOGGER.debug("Added %s to score of User %s", amount, username) + LOGGER.debug("Updated score", amount=amount, for_user=username) @receiver(user_login_failed) def handle_failed_login(sender, request, credentials, **kwargs):