Add traceback info to logger messages within exceptions (#394)

* Replace older exception formatting with f-strings

* Add exception info to logging

djangosaml2/backends.py

@@ -283,19 +283,17 @@ def get_or_create_user(
         try:
             user = UserModel.objects.get(**user_query_args)
         except MultipleObjectsReturned:
-            logger.error(
-                "Multiple users match, model: %s, lookup: %s",
-                UserModel._meta,
-                user_query_args,
+            logger.exception(
+                f"Multiple users match, model: {UserModel._meta}, lookup: {user_query_args}",
             )
         except UserModel.DoesNotExist:
             # Create new one if desired by settings
             if create_unknown_user:
                 user = UserModel(**{user_lookup_key: user_lookup_value})
                 created = True
-                logger.debug(f"New user created: {user}")
+                logger.debug(f"New user created: {user}", exc_info=True)
             else:
-                logger.error(
+                logger.exception(
                     f"The user does not exist, model: {UserModel._meta}, lookup: {user_query_args}"
                 )
 

djangosaml2/utils.py

@@ -80,7 +80,7 @@ def get_idp_sso_supported_bindings(
     except UnknownSystemEntity:
         raise UnknownSystemEntity
     except Exception as e:
-        logger.error(f"get_idp_sso_supported_bindings failed with: {e}")
+        logger.exception(f"get_idp_sso_supported_bindings failed with: {e}")
 
 
 def get_location(http_info):
@@ -116,7 +116,9 @@ def validate_referral_url(request, url):
             # This will also resolve Django URL pattern names
             url = resolve_url(url)
     except NoReverseMatch:
-        logger.debug("Could not validate given referral url is a valid URL")
+        logger.debug(
+            "Could not validate given referral url is a valid URL", exc_info=True
+        )
         return None
 
     # Ensure the user-originating redirection url is safe.

djangosaml2/views.py

@@ -175,7 +175,7 @@ class LoginView(SPConfigMixin, View):
 
     def unknown_idp(self, request, idp):
         msg = f"Error: IdP EntityID {escape(idp)} was not found in metadata"
-        logger.error(msg)
+        logger.exception(msg)
         return HttpResponse(msg, status=403)
 
     def load_sso_kwargs_scoping(self, sso_kwargs):
@@ -358,7 +358,7 @@ def get(self, request, *args, **kwargs):
                     **sso_kwargs,
                 )
             except TypeError as e:
-                logger.error(f"{_msg}: {e}")
+                logger.exception(f"{_msg}: {e}")
                 return HttpResponse(_msg)
             else:
                 http_response = HttpResponseRedirect(get_location(result))
@@ -369,7 +369,7 @@ def get(self, request, *args, **kwargs):
                 try:
                     location = client.sso_location(selected_idp, binding)
                 except TypeError as e:
-                    logger.error(f"{_msg}: {e}")
+                    logger.exception(f"{_msg}: {e}")
                     return HttpResponse(_msg)
 
                 session_id, request_xml = client.create_authn_request(
@@ -396,7 +396,8 @@ def get(self, request, *args, **kwargs):
                     )
                 except TemplateDoesNotExist as e:
                     logger.debug(
-                        f"TemplateDoesNotExist: [{self.post_binding_form_template}] - {e}"
+                        f"TemplateDoesNotExist: [{self.post_binding_form_template}] - {e}",
+                        exc_info=True
                     )
 
             if not http_response:
@@ -410,7 +411,7 @@ def get(self, request, *args, **kwargs):
                     )
                 except TypeError as e:
                     _msg = f"Can't prepare the authentication for {selected_idp}"
-                    logger.error(f"{_msg}: {e}")
+                    logger.exception(f"{_msg}: {e}")
                     return HttpResponse(_msg)
                 else:
                     http_response = HttpResponse(result["data"])
@@ -545,7 +546,7 @@ def post(self, request, attribute_mapping=None, create_unknown_user=None):
         try:
             self.custom_validation(response)
         except Exception as e:
-            logger.warning(f"SAML Response validation error: {e}")
+            logger.warning(f"SAML Response validation error: {e}", exc_info=True)
             return self.handle_acs_failure(
                 request,
                 status=400,
@@ -808,7 +809,7 @@ def do_logout_service(self, request, data, binding):
                 )
             except StatusError as e:
                 response = None
-                logger.warning("Error logging out from remote provider: " + str(e))
+                logger.warning(f"Error logging out from remote provider: {e}", exc_info=True)
             state.sync()
             return finish_logout(request, response)
 

setup.py

@@ -27,7 +27,7 @@ def read(*rnames):
 
 setup(
     name="djangosaml2",
-    version="1.9.0",
+    version="1.9.1",
     description="pysaml2 integration for Django",
     long_description=read("README.md"),
     long_description_content_type="text/markdown",

tests/testprofiles/tests.py

@@ -294,7 +294,7 @@ def test_get_or_create_user_duplicates(self):
         self.assertFalse(created)
         self.assertIn(
             "ERROR:djangosaml2:Multiple users match, model: testprofiles.testuser, lookup: {'age': ''}",
-            logs.output,
+            logs.output[0],
         )
 
     def test_get_or_create_user_no_create(self):
@@ -314,7 +314,7 @@ def test_get_or_create_user_no_create(self):
         self.assertFalse(created)
         self.assertIn(
             "ERROR:djangosaml2:The user does not exist, model: testprofiles.testuser, lookup: {'username': 'paul'}",
-            logs.output,
+            logs.output[0],
         )
 
     def test_get_or_create_user_create(self):
@@ -334,7 +334,7 @@ def test_get_or_create_user_create(self):
         self.assertTrue(created)
         self.assertIn(
             f"DEBUG:djangosaml2:New user created: {user}",
-            logs.output,
+            logs.output[0],
         )
 
     def test_deprecations(self):