Feature/extra debug logging (#132)

* add test for utf-16 request body encoding

* handle other charsets for json request body

* add logging test for mimer errors

* log invalid mime translations

* changelog + version bump

* add request body to mimer error logs

* add some extra logging in dda.resources.resource

* flake8

Author: dshafer

.bumpversion.cfg

@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 0.31.0
+current_version = 0.31.1
 
 [bumpversion:file:pyproject.toml]
 

CHANGELOG.md

@@ -4,10 +4,8 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
-# [0.31.0 = 2023-09-11]
+# [0.31.1 = 2023-09-11]
 - [PR 134](https://github.com/salesforce/django-declarative-apis/pull/134) Make filter caching work for all datatypes
-
-# [0.30.0] - 2023-08-23
 - [PR 131](https://github.com/salesforce/django-declarative-apis/pull/131) Support non-utf8 request body
 
 # [0.29.0] - 2023-08-16

django_declarative_apis/resources/resource.py

@@ -148,12 +148,12 @@ def anonymous(self):
 
         return None
 
-    def authenticate(self, request, rm):
+    def authenticate(self, request, rm):  # noqa: C901
         actor, anonymous, error = False, True, ""
         # workaround for django header sillyness
         if "HTTP_AUTHORIZATION" in request.META:
             request.META["AUTHORIZATION"] = request.META["HTTP_AUTHORIZATION"]
-
+        logger.info("ev=dda_resource method=authenticate state=begin")
         # first we're going to try any authenticators that might match header hints. then, we'll try
         # any catch-all registered under None as a hint
         potential_authenticators = []
@@ -167,6 +167,7 @@ def authenticate(self, request, rm):
                     potential_authenticators.extend(authenticators)
                     continue
         except KeyError:
+            logger.exception("ev=dda_resource method=authenticate state=KeyError")
             pass
 
         try:
@@ -175,24 +176,29 @@ def authenticate(self, request, rm):
         except KeyError:
             pass
 
-        if len(potential_authenticators) <= 0:
-            actor, anonymous = _no_authenticators_found, CHALLENGE
-        else:
-            for authenticator in potential_authenticators:
-                authentication_result = authenticator.is_authenticated(request)
+        try:
+            if len(potential_authenticators) <= 0:
+                actor, anonymous = _no_authenticators_found, CHALLENGE
+            else:
+                for authenticator in potential_authenticators:
+                    authentication_result = authenticator.is_authenticated(request)
 
-                if not authentication_result:
-                    error = authentication_result
-                    if self.anonymous and rm in self.anonymous.allowed_methods:
+                    if not authentication_result:
+                        error = authentication_result
+                        if self.anonymous and rm in self.anonymous.allowed_methods:
 
-                        actor, anonymous = self.anonymous(), True
+                            actor, anonymous = self.anonymous(), True
+                        else:
+                            actor, anonymous = authenticator.challenge, CHALLENGE
                     else:
-                        actor, anonymous = authenticator.challenge, CHALLENGE
-                else:
-                    return self.handler, False, error
+                        return self.handler, False, error
 
-        # XXX: this might be a little weird as it'll contain information about the last executed authenticator
-        return actor, anonymous, error
+            # XXX: this might be a little weird as it'll contain information about the last executed authenticator
+            return actor, anonymous, error
+        except Exception:
+            logger.exception(
+                "ev=dda_resource method=authenticate state=authentication_exception"
+            )
 
     # TODO: make this method less complex and remove the `noqa`
     @vary_on_headers("Authorization")  # noqa: C901
@@ -202,6 +208,9 @@ def __call__(self, request, *args, **kwargs):  # noqa: C901
         that are different (OAuth stuff in `Authorization` header.)
         """
         rm = request.method.upper()
+        logger.info(
+            f'ev=dda_resource method=__call__ content_type="{request.headers.get("content-type")}" body="{request.body}"'  # noqa: E501
+        )
 
         # Django's internal mechanism doesn't pick up
         # PUT request, so we trick it a little here.
@@ -258,12 +267,18 @@ def __call__(self, request, *args, **kwargs):  # noqa: C901
             _ = request.POST if request.method == "POST" else request.GET
             status_code, result = meth(request, *args, **kwargs)
         except Exception as e:
+            logger.exception(
+                "ev=dda_resource method=__call__ state=exception_during_endpoint_processing"
+            )
             status_code = http.client.BAD_REQUEST
             result = self.error_handler(e, request, meth, em_format)
 
         try:
             emitter, ct = Emitter.get(em_format)
         except ValueError:  # pragma: nocover
+            logger.error(
+                "ev=dda_resource method=__call__ state=bad_emitter emitter={emitter}"
+            )
             result = rc.BAD_REQUEST
             result.content = "Invalid output format specified '%s'." % em_format
             return result

django_declarative_apis/resources/utils.py

@@ -207,7 +207,7 @@ def translate(self):
                 except (TypeError, ValueError):
                     # This also catches if loadee is None.
                     log_mimer_data_exception = getattr(
-                        settings, "DDA_LOG_MIMER_DATA_EXCEPTION", False
+                        settings, "DDA_LOG_MIMER_DATA_EXCEPTION", True
                     )
                     if log_mimer_data_exception:
                         # using the exception logger should give a better hint of what exactly went wrong

docs/source/conf.py

@@ -74,7 +74,7 @@
 # built documents.
 
 # The full version, including alpha/beta/rc tags.
-release = '0.31.0'  # set by bumpversion
+release = '0.31.1'  # set by bumpversion
 
 # The short X.Y version.
 version = release.rsplit('.', 1)[0]

pyproject.toml

@@ -4,7 +4,7 @@ build-backend = "setuptools.build_meta"
 
 [project]
 name = "django-declarative-apis"
-version = "0.31.0"  # set by bumpversion
+version = "0.31.1"  # set by bumpversion
 description = "Simple, readable, declarative APIs for Django"
 readme = "README.md"
 dependencies = [