diff --git a/.dockerignore b/.dockerignore index b87d345d..6d587e97 100644 --- a/.dockerignore +++ b/.dockerignore @@ -9,3 +9,4 @@ __pycache__ .github .gitlab .gitignore +logs/ diff --git a/.gitignore b/.gitignore index f2bc6c81..4b518e76 100644 --- a/.gitignore +++ b/.gitignore @@ -133,3 +133,6 @@ dmypy.json # VSCode Settings .vscode/settings.json + +# Logs +logs/ diff --git a/backend/__init__.py b/backend/__init__.py index 220b4572..b5360ef6 100644 --- a/backend/__init__.py +++ b/backend/__init__.py @@ -1,3 +1,5 @@ +import logging + import sentry_sdk from sentry_sdk.integrations.asgi import SentryAsgiMiddleware from starlette.applications import Starlette @@ -6,11 +8,15 @@ from starlette.middleware.cors import CORSMiddleware from backend import constants +from backend import logs # This has to be imported before logging statements are used from backend.authentication import JWTAuthenticationBackend from backend.middleware import DatabaseMiddleware, ProtectedDocsMiddleware from backend.route_manager import create_route_map from backend.validation import api +logger = logging.getLogger(__name__) + +# Setup CORS Origins ORIGINS = [ r"(https://[^.?#]*--pydis-forms\.netlify\.app)", # Netlify Previews r"(https?://[^.?#]*.forms-frontend.pages.dev)", # Cloudflare Previews @@ -18,6 +24,7 @@ if not constants.PRODUCTION: # Allow all hosts on non-production deployments + logger.info("Allowing all CORS origins.") ORIGINS.append(r"(.*)") ALLOW_ORIGIN_REGEX = "|".join(ORIGINS) diff --git a/backend/authentication/user.py b/backend/authentication/user.py index 857c2ed2..18fa9350 100644 --- a/backend/authentication/user.py +++ b/backend/authentication/user.py @@ -1,3 +1,4 @@ +import logging import typing as t import jwt @@ -7,6 +8,8 @@ from backend.constants import SECRET_KEY from backend.discord import fetch_user_details +logger = logging.getLogger(__name__) + class User(BaseUser): """Starlette BaseUser implementation for JWT authentication.""" @@ -35,6 +38,7 @@ def decoded_token(self) -> dict[str, any]: return jwt.decode(self.token, SECRET_KEY, algorithms=["HS256"]) async def fetch_admin_status(self, request: Request) -> bool: + logger.debug(f"Checking admin status for user with ID: {self.payload['id']}") self.admin = await request.state.db.admins.find_one( {"_id": self.payload["id"]} ) is not None @@ -43,6 +47,7 @@ async def fetch_admin_status(self, request: Request) -> bool: async def refresh_data(self) -> None: """Fetches user data from discord, and updates the instance.""" + logger.debug(f"Updating user info for user with ID: {self.payload['id']}") self.payload = await fetch_user_details(self.decoded_token.get("token")) updated_info = self.decoded_token diff --git a/backend/constants.py b/backend/constants.py index d90fd9a2..50c09ea6 100644 --- a/backend/constants.py +++ b/backend/constants.py @@ -15,6 +15,8 @@ PRODUCTION = os.getenv("PRODUCTION", "True").lower() != "false" PRODUCTION_URL = "https://forms.pythondiscord.com" +LOG_FILES = os.getenv("LOG_FILES", "False").lower() != "false" + OAUTH2_CLIENT_ID = os.getenv("OAUTH2_CLIENT_ID") OAUTH2_CLIENT_SECRET = os.getenv("OAUTH2_CLIENT_SECRET") OAUTH2_REDIRECT_URI = os.getenv( diff --git a/backend/discord.py b/backend/discord.py index 8cb602c0..5a4e0fbf 100644 --- a/backend/discord.py +++ b/backend/discord.py @@ -1,4 +1,6 @@ """Various utilities for working with the Discord API.""" +import logging + import httpx from backend.constants import ( @@ -7,8 +9,11 @@ API_BASE_URL = "https://discord.com/api/v8" +logger = logging.getLogger(__name__) + async def fetch_bearer_token(code: str, redirect: str, *, refresh: bool) -> dict: + logger.debug(f"Fetching bearer token with code: {code}") async with httpx.AsyncClient() as client: data = { "client_id": OAUTH2_CLIENT_ID, diff --git a/backend/logs.py b/backend/logs.py new file mode 100644 index 00000000..6b4a3001 --- /dev/null +++ b/backend/logs.py @@ -0,0 +1,45 @@ +""" +Patch the uvicorn, watchgod, and global loggers. +""" +import logging +import sys +from logging import handlers +from pathlib import Path + +from backend import constants + +# Setup constants +LOGGING_LEVEL = logging.INFO if constants.PRODUCTION else logging.DEBUG +FORMATTER = logging.Formatter("%(asctime)s | %(name)s | %(levelname)s | %(message)s") + +# Setup the project logger +handler = logging.StreamHandler(sys.stdout) +handler.setFormatter(FORMATTER) + +logger = logging.getLogger("backend") +logger.setLevel(LOGGING_LEVEL) +logger.addHandler(handler) + +# Format uvicorn logging +try: + logging.getLogger("uvicorn").handlers[0].setFormatter(FORMATTER) +except KeyError: + logger.warning("Could not patch uvicorn logger, continuing.") + +# Add file handlers for local development +if constants.LOG_FILES: + # Setup uvicorn handler + uvicorn_log = Path("logs", ".uvicorn.log") + uvicorn_log.parent.mkdir(exist_ok=True) + # Store two copies of 100KB Files + uvicorn_handler = handlers.RotatingFileHandler(uvicorn_log, maxBytes=100000, backupCount=1) + uvicorn_handler.setFormatter(FORMATTER) + + # Setup app handler + backend_log = Path("logs", ".backend.log") + file_handler = logging.FileHandler(backend_log) + file_handler.setFormatter(FORMATTER) + + # Add all handlers + logging.getLogger("uvicorn").addHandler(uvicorn_handler) + logger.addHandler(file_handler) diff --git a/backend/models/form.py b/backend/models/form.py index eac0b63e..cef19774 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 @@ 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 @@ def validate_features(cls, value: list[str]) -> t.Optional[list[str]]: 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 @@ def dict(self, admin: bool = True, **kwargs: t.Any) -> dict[str, t.Any]: 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() -> t.Optional[str]: 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() -> t.Optional[str]: # 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 5254f8b7..c37370e9 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 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 @@ async def post(self, request: Request) -> JSONResponse: 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 1c6e44a8..8ee2aaa3 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.routes.forms.unittesting import filter_unittests from backend.validation import ErrorMessage, OkayResponse, api +logger = logging.getLogger(__name__) class SingleForm(Route): """ @@ -59,6 +62,8 @@ async def patch(self, request: Request) -> JSONResponse: 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 @@ async def patch(self, request: Request) -> JSONResponse: 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 @@ async def patch(self, request: Request) -> JSONResponse: ) 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 5fd90aba..33fe5e7a 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.route import Route from backend.validation import ErrorMessage, OkayResponse, api +logger = logging.getLogger(__name__) + class FormsList(Route): """ @@ -62,11 +66,13 @@ async def post(self, request: Request) -> JSONResponse: 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 d8d8d172..97d74c12 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.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 @@ async def get(self, request: Request) -> JSONResponse: ) 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 f3c4cd75..5bfe8e5d 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 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 @@ async def get(self, request: Request) -> JSONResponse: ) 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 @@ async def delete(self, request: Request) -> JSONResponse: 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 2624c982..8810a41a 100644 --- a/backend/routes/forms/submit.py +++ b/backend/routes/forms/submit.py @@ -5,6 +5,7 @@ import binascii import datetime import hashlib +import logging import uuid from typing import Any, Optional @@ -24,6 +25,8 @@ 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 @@ async def send_submission_webhook( """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 @@ async def send_submission_webhook( 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()