Merge pull request #123 from JulianFP/logging

Add proper logging system to backend&frontend, update/fix docs

Author: JulianFP

.github/workflows/ci.yml

@@ -45,9 +45,6 @@ jobs:
         with:
           version: 10
 
-      - name: Run development containers
-        run: docker compose up -d
-
       - name: Install backend
         run: |
           sudo apt-get update && sudo apt-get install -y --no-install-recommends git gcc libldap2-dev libsasl2-dev

backend/project_W/__main__.py

@@ -1,3 +1,4 @@
+import logging
 import platform
 from pathlib import Path
 
@@ -7,9 +8,10 @@
 from granian.server import Server
 from itsdangerous import URLSafeTimedSerializer
 from project_W_lib.config import load_config
-from project_W_lib.logger import get_logger
+from project_W_lib.logger import configure_logging
 
 import project_W.dependencies as dp
+from project_W_lib.models.shared_setting_models import LoggingEnum
 
 from ._version import __commit_id__, __version__
 from .models.setting_models import Settings, SecretKeyValidated
@@ -20,7 +22,6 @@
 )
 
 program_name = "project-W"
-logger = get_logger(program_name)
 
 
 @click.command()
@@ -80,16 +81,6 @@ def main(
     development: bool,
     root_static_files: Path | None,
 ):
-    # post application version for debug purposes and bug reports
-    logger.info(f"Running application version {__version__}")
-    if __commit_id__ is None:
-        raise Exception(
-            "Couldn't read git hash from _version.py file. Make sure to install this package from a working git repository!"
-        )
-    dp.git_hash = __commit_id__.removeprefix("g")
-    logger.info(f"Application was built from git hash {dp.git_hash}")
-    logger.info(f"Python version: {platform.python_version()}")
-
     dp.client_path = root_static_files
 
     # parse config file
@@ -98,10 +89,37 @@ def main(
         if custom_config_path
         else load_config(program_name, Settings)
     )
+
+    # now we can setup the logger and everything else
+    logging_dict = configure_logging(dp.config.logging)
+    dp.logger = logging.getLogger(program_name)
+    debug_enabled_anywhere = False
+    access_log_handlers = []  # for granian
+    if dp.config.logging.console.level == LoggingEnum.DEBUG:
+        debug_enabled_anywhere = True
+        access_log_handlers.append("console")
+    if dp.config.logging.file.level == LoggingEnum.DEBUG:
+        debug_enabled_anywhere = True
+        access_log_handlers.append("file")
+    if debug_enabled_anywhere:
+        dp.logger.warning(
+            "The level of at least one of the loggers has been set to 'DEBUG'. This will produce A LOT of logs which WILL INCLUDE SENSITIVE INFORMATION like tokens or user data, as well as result in slightly lower performance. If this is a production system, then please change the log level as soon as possible after you are done triaging a bug."
+        )
+
     dp.auth_s = URLSafeTimedSerializer(
         dp.config.security.secret_key.root.get_secret_value(), "Project-W"
     )
 
+    # post application version for debug purposes and bug reports
+    dp.logger.info(f"Running application version {__version__}")
+    if __commit_id__ is None:
+        raise Exception(
+            "Couldn't read git hash from _version.py file. Make sure to install this package from a working git repository!"
+        )
+    dp.git_hash = __commit_id__.removeprefix("g")
+    dp.logger.info(f"Application was built from git hash {dp.git_hash}")
+    dp.logger.info(f"Python version: {platform.python_version()}")
+
     if run_periodic_tasks:
         execute_background_tasks()
         return
@@ -130,6 +148,25 @@ def main(
         "address": str(dp.config.web_server.address.ip),
         "port": dp.config.web_server.port,
         "workers": dp.config.web_server.worker_count,
+        "log_enabled": True,
+        "log_level": LogLevels.debug if debug_enabled_anywhere else LogLevels.debug,
+        "log_access_format": '%(addr)s - "%(method)s %(path)s %(protocol)s" %(status)d %(dt_ms).3f',
+        "log_access": debug_enabled_anywhere,
+        "log_dictconfig": {
+            **logging_dict,
+            "loggers": {
+                "_granian": {
+                    "handlers": list(logging_dict["handlers"].keys()),
+                    "level": "DEBUG" if debug_enabled_anywhere else "INFO",
+                    "propagate": False,
+                },
+                "granian.access": {
+                    "handlers": access_log_handlers,
+                    "level": "DEBUG" if debug_enabled_anywhere else "INFO",
+                    "propagate": False,
+                },
+            },
+        },
     }
 
     if dp.config.web_server.ssl:
@@ -145,8 +182,6 @@ def main(
         )
 
     if development:
-        granian_options["log_level"] = LogLevels.debug
-        granian_options["log_access"] = True
         granian_options["reload"] = True
         granian_options["reload_paths"] = [Path(__file__).parent.absolute()]
 

backend/project_W/app.py

@@ -1,14 +1,16 @@
 from contextlib import asynccontextmanager
 
-from fastapi import FastAPI
+from fastapi import FastAPI, Request
 from fastapi.routing import APIRoute
 from fastapi.staticfiles import StaticFiles
 from starlette.middleware.sessions import SessionMiddleware
 from starlette.middleware.trustedhost import TrustedHostMiddleware
 from uvicorn.middleware.proxy_headers import ProxyHeadersMiddleware
+from logging import getLogger
 from project_W_lib.models.response_models import LocalAccountOperationModeEnum
 
 import project_W.dependencies as dp
+from project_W_lib.models.shared_setting_models import LoggingEnum
 
 from ._version import __version__
 from .caching import RedisAdapter
@@ -171,6 +173,40 @@ def custom_generate_unique_id(route: APIRoute):
     terms_of_service=f"{dp.config.client_url}/tos" if dp.config.terms_of_services else None,
     generate_unique_id_function=custom_generate_unique_id,
 )
+# logging middleware for debug mode
+if (
+    dp.config.logging.console.level == LoggingEnum.DEBUG
+    or dp.config.logging.file.level == LoggingEnum.DEBUG
+):
+    middleware_logger = getLogger("project-W.middleware")
+
+    @app.middleware("http")
+    async def logging_middleware(request: Request, call_next):
+        middleware_logger.debug(
+            "Incoming request",
+            extra={
+                "url_path": request.url.path,
+                "url_host": request.url.hostname,
+                "scheme": request.url.scheme,
+                "method": request.method,
+                "headers": dict(request.headers),
+                "query_params": request.query_params,
+                "path_params": request.path_params,
+                "cookies": request.cookies,
+                "client": request.client,
+            },
+        )
+        response = await call_next(request)
+        middleware_logger.debug(
+            "Outgoing response",
+            extra={
+                "status": response.status_code,
+                "headers": dict(response.headers),
+            },
+        )
+        return response
+
+
 # middleware required by authlib for oidc
 app.add_middleware(
     SessionMiddleware,

backend/project_W/caching.py

@@ -7,7 +7,6 @@
 from redis.asyncio.client import Pipeline
 from redis.asyncio.retry import Retry
 from redis.backoff import ExponentialBackoff
-from project_W_lib.logger import get_logger
 from project_W_lib.models.request_models import RunnerRegisterRequest
 
 import project_W.dependencies as dp
@@ -18,8 +17,6 @@
 
 
 class CachingAdapter(ABC):
-    logger = get_logger("project-W")
-
     @abstractmethod
     async def open(self, connection_obj):
         """
@@ -211,7 +208,7 @@ async def open(self, connection_obj: RedisConnection):
 
         await self.__check_server_version()
 
-        self.logger.info("Successfully connected to Redis")
+        dp.logger.info("Successfully connected to Redis")
 
     async def __check_server_version(self):
         query_result = await self.client.info("server")
@@ -227,10 +224,10 @@ async def __check_server_version(self):
             elif redis_version_split[i] > self.minimal_required_redis_version[i]:
                 break
 
-        self.logger.info(f"Redis server is on version {redis_version}")
+        dp.logger.info(f"Redis server is on version {redis_version}")
 
     async def close(self):
-        self.logger.info("Closing Redis connections...")
+        dp.logger.info("Closing Redis connections...")
         await self.client.close()
 
     async def register_new_online_runner(
@@ -279,7 +276,7 @@ async def get_online_runner_by_id(self, runner_id: int) -> OnlineRunner | None:
             try:
                 return OnlineRunner.model_validate(runner_dict)
             except ValidationError:
-                self.logger.error(
+                dp.logger.error(
                     f"Validation error occurred while reading from redis! The following data was read instead of an OnlineRunner object: {runner_dict}. Continuing..."
                 )
                 return None
@@ -465,7 +462,7 @@ async def get_in_process_job(self, job_id: int) -> InProcessJob | None:
             try:
                 return InProcessJob.model_validate(job_dict)
             except ValidationError:
-                self.logger.error(
+                dp.logger.error(
                     f"Validation error occurred while reading from redis! The following data was read instead of an InProcessJob object: {job_dict}. Continuing..."
                 )
                 return None

backend/project_W/cli_tasks.py

@@ -1,16 +1,12 @@
 import asyncio
 
-from project_W_lib.logger import get_logger
-
 import project_W.dependencies as dp
 
 from .models.setting_models import SecretKeyValidated
 from .database import PostgresAdapter
 from .security import ldap_deps, oidc_deps
 from .smtp import SmtpClient
 
-logger = get_logger("project-W")
-
 
 async def db_init():
     dp.db = PostgresAdapter(str(dp.config.postgres_connection_string))
@@ -40,35 +36,35 @@ async def finish():
 
 
 async def database_cleanup():
-    logger.info("Starting database cleanup task...")
+    dp.logger.info("Starting database cleanup task...")
     if dp.config.cleanup.user_retention_in_days is not None:
         await dp.db.user_cleanup(dp.config.cleanup.user_retention_in_days)
     if dp.config.cleanup.finished_job_retention_in_days is not None:
         await dp.db.job_cleanup(dp.config.cleanup.finished_job_retention_in_days)
     await dp.db.general_cleanup()
-    logger.info("Finished database cleanup task")
+    dp.logger.info("Finished database cleanup task")
 
 
 async def oidc_token_invalidation():
-    logger.info(
+    dp.logger.info(
         "Starting cleanup of tokens associated with non-existing OIDC users or users with insufficient permissions..."
     )
     tokens_of_oidc_users = await dp.db.get_oidc_tokens()
     for token in tokens_of_oidc_users:
         await oidc_deps.invalidate_token_if_oidc_user_lost_privileges(token)
-    logger.info(
+    dp.logger.info(
         f"Finished cleanup of OIDC tokens, successfully checked {len(tokens_of_oidc_users)}"
     )
 
 
 async def ldap_token_invalidation():
-    logger.info(
+    dp.logger.info(
         "Starting cleanup of tokens associated with non-existing LDAP users or users with insufficient permissions..."
     )
     tokens_of_ldap_users = await dp.db.get_ldap_tokens()
     for token in tokens_of_ldap_users:
         await ldap_deps.invalidate_token_if_ldap_user_lost_privileges(ldap_deps.ldap_adapter, token)
-    logger.info(
+    dp.logger.info(
         f"Finished cleanup of LDAP tokens, successfully checked {len(tokens_of_ldap_users)}"
     )
 
@@ -94,20 +90,20 @@ async def database_delete_encryption_loop():
 
 
 def execute_background_tasks():
-    logger.info("Starting background tasks...")
+    dp.logger.info("Starting background tasks...")
     asyncio.run(background_tasks_loop())
-    logger.info("Finished all background tasks")
+    dp.logger.info("Finished all background tasks")
 
 
 def perform_secret_key_rotation(secret_key: SecretKeyValidated):
-    logger.info("Starting database re-encryption...")
+    dp.logger.info("Starting database re-encryption...")
     asyncio.run(database_secret_rotation_loop(secret_key))
-    logger.info("Finished database re-encryption")
+    dp.logger.info("Finished database re-encryption")
 
 
 def perform_database_encrypted_content_deletion():
-    logger.info("Starting deletion of encrypted contents in database...")
+    dp.logger.info("Starting deletion of encrypted contents in database...")
     asyncio.run(database_delete_encryption_loop())
-    logger.info(
+    dp.logger.info(
         "Finished deletion of encrypted contents in database. Don't forget to also flush redis"
     )