Merge branch '875-django-setup-very-slow' into 'master'

Improve logging

See merge request !1277

CHANGELOG.rst

@@ -13,6 +13,8 @@ Fixed
 ~~~~~
 
 * Notifications were not properly shown in the frontend.
+* [Dev] Log levels were not correctly propagated to all loggers
+* [Dev] Log format did not contain all essential information
 * When navigating from legacy to legacy page, the latter would reload once for no reason.
 * The oauth authorization page was not accessible when the service worker was active.
 * [Docker] Clear obsolete bundle parts when adding apps using ONBUILD

aleksis/core/settings.py

@@ -935,12 +935,19 @@ LOGGING["root"] = {
     "handlers": ["console"],
     "level": _settings.get("logging.level", "WARNING"),
 }
+# Configure global log Format
+LOGGING["formatters"]["verbose"] = {
+    "format": "{asctime} {levelname} {name}[{process}]: {msg}",
+    "style": "{",
+}
 # Add null handler for selective silencing
 LOGGING["handlers"]["null"] = {"class": "logging.NullHandler"}
 # Make console logging independent of DEBUG
 LOGGING["handlers"]["console"]["filters"].remove("require_debug_true")
 # Use root log level for console
 del LOGGING["handlers"]["console"]["level"]
+# Use verbose log format for console
+LOGGING["handlers"]["console"]["formatter"] = "verbose"
 # Disable exception mails if not desired
 if not _settings.get("logging.mail_admins", True):
     LOGGING["loggers"]["django"]["handlers"].remove("mail_admins")
@@ -956,6 +963,9 @@ LOGGING["loggers"]["celery"] = {
     "level": _settings.get("logging.level", "WARNING"),
     "propagate": False,
 }
+# Set Django log levels
+LOGGING["loggers"]["django"]["level"] = _settings.get("logging.level", "WARNING")
+LOGGING["loggers"]["django.server"]["level"] = _settings.get("logging.level", "WARNING")
 
 # Rules and permissions
 

aleksis/core/util/apps.py

+import logging
 from importlib import metadata
 from typing import TYPE_CHECKING, Any, Optional, Sequence
 
@@ -26,8 +27,11 @@ class AppConfig(django.apps.AppConfig):
     def __init_subclass__(cls):
         super().__init_subclass__()
         cls.default = True
+        cls._logger = logging.getLogger(f"{cls.__module__}.{cls.__name__}")
 
     def ready(self):
+        self._logger.debug("Running app.ready")
+
         super().ready()
 
         # Register default listeners
@@ -36,9 +40,12 @@ class AppConfig(django.apps.AppConfig):
         preference_updated.connect(self.preference_updated)
         user_logged_in.connect(self.user_logged_in)
         user_logged_out.connect(self.user_logged_out)
+        self._logger.debug("Default signal handlers connected")
 
         # Getting an app ready means it should look at its config once
+        self._logger.debug("Force-loading preferences")
         self.preference_updated(self)
+        self._logger.debug("Preferences loaded")
 
     def get_distribution_name(self):
         """Get distribution name of application package."""
@@ -282,6 +289,8 @@ class AppConfig(django.apps.AppConfig):
         return {}
 
     def _maintain_default_data(self):
+        self._logger.debug("Maintaining default data for %s", self.get_name())
+
         from django.contrib.auth.models import Permission
         from django.contrib.contenttypes.models import ContentType
 
@@ -292,10 +301,19 @@ class AppConfig(django.apps.AppConfig):
         for model in self.get_models():
             if hasattr(model, "maintain_default_data"):
                 # Method implemented by each model object; can be left out
+                self._logger.info(
+                    "Maintaining default data of %s in %s", model._meta.model_name, self.get_name()
+                )
                 model.maintain_default_data()
             if hasattr(model, "extra_permissions"):
+                self._logger.info(
+                    "Maintaining extra permissions for %s in %s",
+                    model._meta.model_name,
+                    self.get_name(),
+                )
                 ct = ContentType.objects.get_for_model(model)
                 for perm, verbose_name in model.extra_permissions:
+                    self._logger.debug("Creating %s (%s)", perm, verbose_name)
                     Permission.objects.get_or_create(
                         codename=perm,
                         content_type=ct,