*(minor): make better use of structured logging

This commit is contained in:
Langhammer, Jens 2019-10-04 10:21:33 +02:00
parent c0df1f38b8
commit 0b86231a36
10 changed files with 21 additions and 23 deletions

View File

@ -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)

View File

@ -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()

View File

@ -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)

View File

@ -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')

View File

@ -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))

View File

@ -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)

View File

@ -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

View File

@ -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

View File

@ -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)

View File

@ -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):