Adds Logging For Routeslogging

Adds logging for most routes, to make it easier to debug the routes, and
 keep a better record of major changes. Most operations would not get
 logged, except the beginning of a more sensitive operation, especially
 ones that require admin permissions.

Signed-off-by: Hassan Abouelela <[email protected]>

7 files changed, 66 insertions, 16 deletions

diff --git a/backend/models/form.py b/backend/models/form.py
index eac0b63..cef1977 100644
--- a/backend/models/form.py
+++ b/backend/models/form.py
@@ -1,3 +1,4 @@
+import logging
 import typing as t
 
 import httpx
@@ -9,6 +10,8 @@ from .question import Question
 
 PUBLIC_FIELDS = ["id", "features", "questions", "name", "description", "submitted_text"]
 
+logger = logging.getLogger(__name__)
+
 
 class _WebHook(BaseModel):
     """Schema model of discord webhooks."""
@@ -54,11 +57,14 @@ class Form(BaseModel):
 
     def dict(self, admin: bool = True, **kwargs: t.Any) -> dict[str, t.Any]:
         """Wrapper for original function to exclude private data for public access."""
+        logger.debug("Converting form to dict.")
         data = super().dict(**kwargs)
 
         returned_data = {}
 
         if not admin:
+            logger.debug("Removing non-public fields, as admin was false.")
+
             for field in PUBLIC_FIELDS:
                 if field == "id" and kwargs.get("by_alias"):
                     fetch_field = "_id"
@@ -67,6 +73,7 @@ class Form(BaseModel):
 
                 returned_data[field] = data[fetch_field]
         else:
+            logger.debug("Including all fields.")
             returned_data = data
 
         return returned_data
@@ -86,6 +93,7 @@ async def validate_hook_url(url: str) -> t.Optional[ValidationError]:
             raise ValueError("URL must be a discord webhook.")
 
         try:
+            logger.debug("Pinging discord to verify webhook.")
             async with httpx.AsyncClient() as client:
                 response = await client.get(url)
                 response.raise_for_status()
@@ -117,6 +125,7 @@ async def validate_hook_url(url: str) -> t.Optional[ValidationError]:
 
     # Validate, and return errors, if any
     try:
+        logger.info("Validating a webhook url.")
         await validate()
     except Exception as e:
         loc = (
diff --git a/backend/routes/admin.py b/backend/routes/admin.py
index 5254f8b..c37370e 100644
--- a/backend/routes/admin.py
+++ b/backend/routes/admin.py
@@ -1,6 +1,8 @@
 """
 Adds new admin user.
 """
+import logging
+
 from pydantic import BaseModel, Field
 from spectree import Response
 from starlette.authentication import requires
@@ -10,6 +12,8 @@ from starlette.responses import JSONResponse
 from backend.route import Route
 from backend.validation import ErrorMessage, OkayResponse, api
 
+logger = logging.getLogger(__name__)
+
 
 class AdminModel(BaseModel):
     id: str = Field(alias="_id")
@@ -32,6 +36,8 @@ class AdminRoute(Route):
         data = await request.json()
         admin = AdminModel(**data)
 
+        logger.info(f"Trying to add a new admin with ID: {admin.id}")
+
         if await request.state.db.admins.find_one(
             {"_id": admin.id}
         ):
diff --git a/backend/routes/forms/form.py b/backend/routes/forms/form.py
index 1c6e44a..8ee2aaa 100644
--- a/backend/routes/forms/form.py
+++ b/backend/routes/forms/form.py
@@ -1,6 +1,8 @@
 """
 Returns, updates or deletes a single form given an ID.
 """
+import logging
+
 import deepmerge
 from pydantic import ValidationError
 from spectree.response import Response
@@ -13,6 +15,7 @@ from backend.route import Route
 from backend.routes.forms.unittesting import filter_unittests
 from backend.validation import ErrorMessage, OkayResponse, api
 
+logger = logging.getLogger(__name__)
 
 class SingleForm(Route):
     """
@@ -59,6 +62,8 @@ class SingleForm(Route):
         data = await request.json()
 
         form_id = {"_id": request.path_params["form_id"]}
+        logger.info(f"Attempting to patch a form with ID: {form_id.get('_id')}")
+
         if raw_form := await request.state.db.forms.find_one(form_id):
             if "_id" in data or "id" in data:
                 return JSONResponse({"error": "locked_field"}, status_code=400)
@@ -77,6 +82,7 @@ class SingleForm(Route):
             except ValidationError as e:
                 return JSONResponse(e.errors(), status_code=422)
 
+            logger.debug("Inserting updated form into DB.")
             await request.state.db.forms.replace_one(
                 {"_id": request.path_params["form_id"]},
                 form.dict()
@@ -93,14 +99,14 @@ class SingleForm(Route):
     )
     async def delete(self, request: Request) -> JSONResponse:
         """Deletes form by ID."""
-        if not await request.state.db.forms.find_one(
-            {"_id": request.path_params["form_id"]}
-        ):
+        form_id = {"_id": request.path_params["form_id"]}
+        logger.info(f"Attempting to delete a form with ID: {form_id.get('_id')}")
+
+        if not await request.state.db.forms.find_one(form_id):
             return JSONResponse({"error": "not_found"}, status_code=404)
 
-        await request.state.db.forms.delete_one(
-            {"_id": request.path_params["form_id"]}
-        )
+        logger.debug("Executing deletion.")
+        await request.state.db.forms.delete_one(form_id)
         await request.state.db.responses.delete_many(
             {"form_id": request.path_params["form_id"]}
         )
diff --git a/backend/routes/forms/index.py b/backend/routes/forms/index.py
index 5fd90ab..33fe5e7 100644
--- a/backend/routes/forms/index.py
+++ b/backend/routes/forms/index.py
@@ -1,6 +1,8 @@
 """
 Return a list of all forms to authenticated users.
 """
+import logging
+
 from spectree.response import Response
 from starlette.authentication import requires
 from starlette.requests import Request
@@ -12,6 +14,8 @@ from backend.models.form import validate_hook_url
 from backend.route import Route
 from backend.validation import ErrorMessage, OkayResponse, api
 
+logger = logging.getLogger(__name__)
+
 
 class FormsList(Route):
     """
@@ -62,11 +66,13 @@ class FormsList(Route):
             pass
 
         form = Form(**form_data)
+        logging.info(f"Attempting to add a form with ID: {form.id}")
 
         if await request.state.db.forms.find_one({"_id": form.id}):
             return JSONResponse({
                 "error": "id_taken"
             }, status_code=400)
 
+        logging.debug("Inserting new form.")
         await request.state.db.forms.insert_one(form.dict(by_alias=True))
         return JSONResponse(form.dict())
diff --git a/backend/routes/forms/response.py b/backend/routes/forms/response.py
index d8d8d17..97d74c1 100644
--- a/backend/routes/forms/response.py
+++ b/backend/routes/forms/response.py
@@ -1,6 +1,8 @@
 """
 Returns or deletes form response by ID.
 """
+import logging
+
 from spectree import Response as RouteResponse
 from starlette.authentication import requires
 from starlette.requests import Request
@@ -10,6 +12,8 @@ from backend.models import FormResponse
 from backend.route import Route
 from backend.validation import ErrorMessage, OkayResponse, api
 
+logger = logging.getLogger(__name__)
+
 
 class Response(Route):
     """Get or delete single form response by ID."""
@@ -42,14 +46,19 @@ class Response(Route):
     )
     async def delete(self, request: Request) -> JSONResponse:
         """Delete a form response by ID."""
-        if not await request.state.db.responses.find_one(
-            {
-                "_id": request.path_params["response_id"],
-                "form_id": request.path_params["form_id"]
-            }
-        ):
+        ids = {
+            "_id": request.path_params["response_id"],
+            "form_id": request.path_params["form_id"]
+        }
+
+        logger.info(
+            f"Attempting to delete a response from {ids.get('form_id')} with ID: {ids.get('_id')}"
+        )
+
+        if not await request.state.db.responses.find_one(ids):
             return JSONResponse({"error": "not_found"}, status_code=404)
 
+        logger.debug("Executing deletion.")
         await request.state.db.responses.delete_one(
             {"_id": request.path_params["response_id"]}
         )
diff --git a/backend/routes/forms/responses.py b/backend/routes/forms/responses.py
index f3c4cd7..5bfe8e5 100644
--- a/backend/routes/forms/responses.py
+++ b/backend/routes/forms/responses.py
@@ -1,6 +1,8 @@
 """
 Returns all form responses by form ID.
 """
+import logging
+
 from pydantic import BaseModel
 from spectree import Response
 from starlette.authentication import requires
@@ -9,7 +11,9 @@ from starlette.responses import JSONResponse
 
 from backend.models import FormResponse, ResponseList
 from backend.route import Route
-from backend.validation import api, ErrorMessage, OkayResponse
+from backend.validation import ErrorMessage, OkayResponse, api
+
+logger = logging.getLogger(__name__)
 
 
 class ResponseIdList(BaseModel):
@@ -56,9 +60,10 @@ class Responses(Route):
     )
     async def delete(self, request: Request) -> JSONResponse:
         """Bulk deletes form responses by IDs."""
-        if not await request.state.db.forms.find_one(
-            {"_id": request.path_params["form_id"]}
-        ):
+        form_id = {"_id": request.path_params["form_id"]}
+        logger.info(f"Bulk deleting responses for form with ID: {form_id.get('_id')}")
+
+        if not await request.state.db.forms.find_one(form_id):
             return JSONResponse({"error": "not_found"}, status_code=404)
 
         data = await request.json()
@@ -96,6 +101,7 @@ class Responses(Route):
                 status_code=400
             )
 
+        logger.debug(f"Executing deletion for the following responses: {','.join(actual_ids)}")
         await request.state.db.responses.delete_many(
             {
                 "_id": {"$in": list(actual_ids)}
diff --git a/backend/routes/forms/submit.py b/backend/routes/forms/submit.py
index 2624c98..8810a41 100644
--- a/backend/routes/forms/submit.py
+++ b/backend/routes/forms/submit.py
@@ -5,6 +5,7 @@ Submit a form.
 import binascii
 import datetime
 import hashlib
+import logging
 import uuid
 from typing import Any, Optional
 
@@ -24,6 +25,8 @@ from backend.routes.auth.authorize import set_response_token
 from backend.routes.forms.unittesting import execute_unittest
 from backend.validation import ErrorMessage, api
 
+logger = logging.getLogger(__name__)
+
 HCAPTCHA_VERIFY_URL = "https://hcaptcha.com/siteverify"
 HCAPTCHA_HEADERS = {
     "Content-Type": "application/x-www-form-urlencoded"
@@ -208,6 +211,10 @@ class SubmitForm(Route):
         """Helper to send a submission message to a discord webhook."""
         # Stop if webhook is not available
         if form.webhook is None:
+            logger.warning(
+                f"Attempted to submit a form that has "
+                f"webhooks enabled with no webhook url. ID: {form.id}"
+            )
             raise ValueError("Got empty webhook.")
 
         try:
@@ -259,6 +266,7 @@ class SubmitForm(Route):
             hook["content"] = message.replace("_USER_MENTION_", mention)
 
         # Post hook
+        logger.debug("Attempting to send an embed to the webhook.")
         async with httpx.AsyncClient() as client:
             r = await client.post(form.webhook.url, json=hook)
             r.raise_for_status()